AutoFlushTimeOut has no effect when compiled app runs in non-C drive

ComingNine · 2014-09-06 23:15:07

When AutoFlushTimeOut is set, the compiled program is supposed to flush log at the specified interval. However, it does not work if the compiled app is run in non-C drive (D:\ drive, for example). Could you help to comment whether this is a bug ?

project14.dpr

program Project14;

uses
  Forms,
  SysUtils,
  Unit1 in 'Unit1.pas' {Form1};

{$R *.res}

begin

  Forms.Application.Initialize;
  Forms.Application.MainFormOnTaskbar := True;
  Forms.Application.CreateForm(TForm1, Form1);
  Forms.Application.Run;

end.

unit1.pas

unit Unit1;

interface

uses
  SynCommons, SyncObjs,
  Windows, Messages, SysUtils, Variants, Classes, Graphics, Controls, Forms,
  Dialogs;

type
  TEchoThread = class(TThread)
  private
    FTerminateEvent: TSimpleEvent;
  protected
    procedure Execute; override;
  public
    constructor Create(ACreateSuspended: Boolean);
    destructor Destroy; override;
    procedure StopNow;
  end;

type
  TForm1 = class(TForm)
    procedure FormCreate(Sender: TObject);
    procedure FormDestroy(Sender: TObject);
  private
    FEchoThread: TEchoThread;
    procedure OnThreadTerminated(Sender: TObject);
  public
  end;

var
  Form1: TForm1;

implementation

{$R *.dfm}

{ TEchoThread }

constructor TEchoThread.Create(ACreateSuspended: Boolean);
begin
  inherited Create(ACreateSuspended);
  FTerminateEvent := TSimpleEvent.Create;
end;

destructor TEchoThread.Destroy;
begin
  FTerminateEvent.Free;
  inherited Destroy;
end;

procedure TEchoThread.StopNow;
begin
  Terminate;
  FTerminateEvent.SetEvent;
end;

procedure TEchoThread.Execute;
var
  ILog: ISynLog;
begin
  ILog := TSynLog.Enter;
  while not Terminated do
  begin
    try
      try
        ILog.Log(sllInfo, ' hello world ');
      finally
      end;
    except on E: Exception do
      begin
        ILog.Log(sllException, E);
      end;
    end;
    FTerminateEvent.WaitFor(5 * 1000);
  end;
end;

{ TForm1 }

procedure TForm1.FormCreate(Sender: TObject);
var
  ILog: ISynLog;
begin
  ILog := TSynLog.Enter;
  FEchoThread := TEchoThread.Create(True);
  FEchoThread.FreeOnTerminate := False;
  FEchoThread.OnTerminate := OnThreadTerminated;
  FEchoThread.Start;
end;

procedure TForm1.FormDestroy(Sender: TObject);
var
  ILog: ISynLog;
begin
  ILog := TSynLog.Enter;
  // FEchoThread.Terminate;
  FEchoThread.StopNow;
  FEchoThread.WaitFor;
  FEchoThread.Free;
end;

procedure TForm1.OnThreadTerminated(Sender: TObject);
var
  ILog: ISynLog;
  ex: TObject;
begin
  ILog := TSynLog.Enter;
  Assert(Sender is TThread);
  ex := TThread(Sender).FatalException;
  if Assigned(ex) then begin
    // Thread terminated due to an exception
    if ex is Exception then begin
      ILog.Log(sllException, Exception(ex));
      Application.ShowException(Exception(ex));
    end else
      ShowMessage(ex.ClassName);
  end else begin
    // Thread terminated cleanly
  end;
end;

initialization

  with TSynLog.Family do
  begin
    AutoFlushTimeOut := 1;
    Level := LOG_VERBOSE;
    PerThreadLog := ptIdentifiedInOnFile;
    RotateFileCount := 50;
    RotateFileSizeKB := 20 * 1024; // rotate by 20 MB logs
  end;

end.

unit1.dfm

object Form1: TForm1
  Left = 0
  Top = 0
  Caption = 'Form1'
  ClientHeight = 202
  ClientWidth = 447
  Color = clBtnFace
  Font.Charset = DEFAULT_CHARSET
  Font.Color = clWindowText
  Font.Height = -11
  Font.Name = 'Tahoma'
  Font.Style = []
  OldCreateOrder = False
  OnCreate = FormCreate
  OnDestroy = FormDestroy
  PixelsPerInch = 96
  TextHeight = 13
end

ComingNine · 2014-09-06 23:22:08

O_O

I did not describe correctly.

It seems that when run in D:\ drive:
(1) The log is indeed flushed, because the log displays the updated content when opened with LogView.exe
(2) However, if I only press F5 to refresh (in Explorer), the file size of the log does not change ! <--- The file size of the log shown in Explorer changes when run in C:\ drive. Could you help to comment ?

ab · 2014-09-07 06:17:17

But what about the content?
(open the log in our LogViewer tool)

What does a good old "dir" at the command line prompt show?
I would not take much care about explorer behavior, which is quite strange with its refresh and so on...
(I am a Total Commanderfan) ;-)

ComingNine · 2014-09-07 08:30:39

The log content is indeed flushed, because the log displays the updated content when opened with LogView.exe.
"Dir" under "Cmd" behaves the same as the explorer. However, "ls" under "Cygwin Bash" will shows the increased file size ( after this, the Dir and the explorer will also show what ls shows).
Thank you for your comments !

Last edited by ComingNine (2014-09-07 08:31:06)

ComingNine · 2014-09-07 08:32:52

I wonder if there is a "IPC" or "TCP/IP" version of LogView, so that it will constantly accept incoming messages and display them ?

cheemeng · 2014-09-07 16:34:15

I guess you could make use of the FindFirstChangeNotification API call to notify you of changes to the file.

I reckon you would most likely need to create a new descendant of TSynLogFile that
1. has an additional parameter to LoadFromMap to allow you to specify an Offset to P instead of always pointing to fMap.Buffer (chances are you would need to duplicate most of the code from TMemoryMapText.LoadFromMap as well as TSynLogFile.LoadFromMap, and strip out the parts that perform initialization and parts that always read from fLines[0], replacing it with fLines[fCount])
2. upon notification of file change, calculate the size difference and pass that in to a call to the new LoadFromMap

Or you could open a request ticket and request for Arnaud to add the Offset into TMemoryMapText.LoadFromMap and its descendants as well, and modify the code to support subsequent calls to LoadFromMap

ab · 2014-09-07 17:50:03

It was not possible.

Now it is possible, since I've just added a new "Server Launch" button to the LogView tool.
It allows to run the tool as a HTTP server, ready to display remote logs, echoed from mORMot HTTP clients.

See also the newly added RemoteLoggingTest client sample project in "11 - Exception logging", able to connect and echo its log content to the LogView tool running as server.

Next steps are:
1. Optionally run all echoing into a background thread, to avoid blocking the main process due to failure (e.g. network slowness);
2. In this background thread, gather all pending messages into one single message to server;
3. Enable remote logging from our SynCrossPlatformREST client - i.e. allow remote logging directly from a mobile application;
4. Update documentation to reflect those new possibilities.

See today's events in the http://synopse.info/fossil/timeline for the corresponding commits.

cheemeng · 2014-09-07 18:08:14

That was fast!

*Now waiting (im)patiently for Daily Rotation*

ComingNine · 2014-09-07 20:17:36

ab wrote:

Now it is possible, since I've just added a new "Server Launch" button to the LogView tool.
It allows to run the tool as a HTTP server, ready to display remote logs, echoed from mORMot HTTP clients.

Fantastic work !

When LogView.exe starts to listen, everything works perfect after replacing

 "var ILog: ISynLog" and "ILog := TSynLog.Enter" and "ILog.Log(sllInfo"

with

 "" and "SQLite3Log.Add.Enter" and "SQLite3Log.Add.Log(sllInfo"

!

However, as shown from the right panel of the picture, it seems that SQLite3Log has put quite a few extra log messages into the log file. Could you help to comment how to disable the log messages related to "TSQLHttpClientWinHttp" ? This will help me to double-click and view the log content some other time.

ab · 2014-09-08 06:33:58

Note that SQLite3Log=TSQLLog and not TSynLog.
So it does make sense if TSynLog does not send any remote notification, since only SQLite3Log=TSQLLog has been defined for remote logging.

But, by design, the internal remote logging events (i.e. when the logger calls the RemoteLog method-based services - the "PUT root/RemoteLog" entries) are NOT transmitted to the server.
Otherwise, it triggers an infinite loop!

I'll continue the implementation today, and do more testing.

Thanks for the feedback.

ComingNine · 2014-09-08 07:17:42

Many thanks for your efforts !

ab · 2014-09-08 17:04:04

I've committed the remaining work.
See the latest commits of http://synopse.info/fossil/timeline

Introducing TSQLRest.Log() support for our cross-platform client units
* either logging to a file, in the same format than TSynLog / LogView
* or logging to a remote log server, e.g. our LogView tool running in server mode
* all ORM and SOA client methods will now use this logging abilities to trace the process
* tested with Delphi, FPC or SmartMobileStudio clients (only remote logs are allowed for SMS, since there is no file access from an HTML5 app)

Performance is very good, since several rows of logging can be gathered in one REST call.
This makes it pretty fast, especially with remote AJAX clients...
And under Win32/Win64, all sending is handled in a background thread.

ComingNine · 2014-09-08 20:26:52

ab wrote:

I've committed the remaining work.
See the latest commits of http://synopse.info/fossil/timeline
Introducing TSQLRest.Log() support for our cross-platform client units
* either logging to a file, in the same format than TSynLog / LogView
* or logging to a remote log server, e.g. our LogView tool running in server mode
* all ORM and SOA client methods will now use this logging abilities to trace the process
* tested with Delphi, FPC or SmartMobileStudio clients (only remote logs are allowed for SMS, since there is no file access from an HTML5 app)
Performance is very good, since several rows of logging can be gathered in one REST call.
This makes it pretty fast, especially with remote AJAX clients...
And under Win32/Win64, all sending is handled in a background thread.

Really amazing work !!

The "11 - Exception logging" sample compiles and runs smoothly. And a live show from a listening LogView.exe looks almost the same as what is shown when the log file is opened by LogView.exe.

ComingNine · 2014-09-08 20:52:00

Could you help to comment the following two questions ?

(1) In a non-mORMot-based application, I would like to first test if there is a listening LogView (log server). If there is, in all places of all units of the application, mORMot will be in the uses list, and "SQLite3Log.Add.Enter" and "SQLite3Log.Add.Log(sllInfo" will be used. If there is not, in all places of all units of the application, only SynCommons will be in the uses list, and "var ILog: ISynLog" and "ILog := TSynLog.Enter" and "ILog.Log(sllInfo" will be used. Could you help to comment how to achieve this ?

(2) Could you help to modify (improve) the scroll-bar appearance and the scrolling behavior of LogView.exe ?
Regarding the scroll-bar appearance, from the pictures below, when UltraEdit or Notepad2 loads the same log file, the scroll bar is much larger than the one of LogView.exe.
Regarding the scrolling behavior, when the middle mouse button is scrolled, UltraEdit or Notepad2 will move the scroll-bar and not move the cursor. However, LogView.exe will move the cursor (and moves the scroll-bar based on the position of the cursor). This can be less comfortable, for example, when a large log file is loaded by LogView.exe, when I use the left mouse button to drag the scroll-bar down hundreds of lines, and then scroll the middle mouse button, the scroll-bar suddenly jumps to the very beginning. For another example, if one wants to scroll down the view by scrolling the middle mouse button, one has to scroll multiple times because the cursor has to move from the beginning to the end of the view.
Could you help to comment how to make the LogView.exe's scroll-bar similar to Notepad2's, and to make the LogView.exe's scrolling behavior similar to Notepad2's ?

Last edited by ComingNine (2014-09-08 21:02:28)

ab · 2014-09-09 06:17:51

(1) I can't follow you: you can not, at run-time, delete units from source code which is already compiled...

(2) We use a standard TListBox in virtual mode.
You may help us by proposing some code.

BTW I do not have any middle button in my microsoft mouse.
I you meant the "middle wheel", it will scroll from the current selected item. So just click in the list to select one row, then you could use the mouse wheel to scroll.

It was on purpose that we did not change the current selected item when some events come in, but just roll the top item of the list.
In fact, the current selected row is displayed as detail in the memo at the bottom of the form.
If you change the selected row when a new event comes in, you change the memo at the bottom - so you are not able to read it in peace.
We may add a "tracking" checkbox to disable the auto-scroll feature.
Still missing a "Save List" button to save a .log from the incoming events.

If you want to smile, enable the logs in TestSQL3.dpr - you will get a 550 MB of log.
Then try to open it with NotePad2 or UltraEdit, and compare the speed and memory used.

ComingNine · 2014-09-09 07:16:09

ab wrote:

(1) I can't follow you: you can not, at run-time, delete units from source code which is already compiled...
(2) We use a standard TListBox in virtual mode.
You may help us by proposing some code.
BTW I do not have any middle button in my microsoft mouse.
I you meant the "middle wheel", it will scroll from the current selected item. So just click in the list to select one row, then you could use the mouse wheel to scroll.
It was on purpose that we did not change the current selected item when some events come in, but just roll the top item of the list.
In fact, the current selected row is displayed as detail in the memo at the bottom of the form.
If you change the selected row when a new event comes in, you change the memo at the bottom - so you are not able to read it in peace.
We may add a "tracking" checkbox to disable the auto-scroll feature.
Still missing a "Save List" button to save a .log from the incoming events.
If you want to smile, enable the logs in TestSQL3.dpr - you will get a 550 MB of log.
Then try to open it with NotePad2 or UltraEdit, and compare the speed and memory used.

> (1) I can't follow you: you can not, at run-time, delete units from source code which is already compiled...

Sorry for the confusion ! The intent is to be able to log whether there is a LogView (log server) or not. It seems that commenting out the "exit;" in "FormCreate" of "RemoteLogMain.pas" will be enough :

  try
    Screen.Cursor := crHourGlass;
    try
      fClient := TSQLHttpClient.CreateForRemoteLogging(
        AnsiString(edtServer.Text),AnsiString(edtPort.Text),SQLite3Log);
    finally
      Screen.Cursor := crDefault;
    end;
  except
    on E: Exception do begin
      FreeAndNil(fClient);
      MessageDlg(E.Message,mtError,[mbOk],0);
      // exit;
    end;
  end;

Thank you very much for your efforts !

> It was on purpose that we did not change the current selected item when some events come in, but just roll the top item of the list.
> In fact, the current selected row is displayed as detail in the memo at the bottom of the form.
> If you change the selected row when a new event comes in, you change the memo at the bottom - so you are not able to read it in peace.
> We may add a "tracking" checkbox to disable the auto-scroll feature.
> Still missing a "Save List" button to save a .log from the incoming events.

Sorry for the confusion ! I agree with your decision that "auto-scroll" should be disabled so that the log view will not be disturbed by incoming messages. I also agree with you that a choice to enable "auto-scroll" for incoming messages is nice.

Please bear with me and see the following pictures:
The first picture is after I use LogView to open a log file:
sVBRLhP.png?1

An example of my comments of LogView's scrolling behavior: After I use LogView to open a log file, if I scroll the mouse wheel downwards, the listbox selection is being scrolled down instead of the scroll bar. The scroll bar will not move until the listbox selection is moved to the bottom. This is different from UltraEdit or Notepad or Microsoft Word, and thus counter-intuitive.
S7iNmWG.png?1

Another example of my comments of LogView's scrolling behavior: After I use LogView to open a log file, if I use the left mouse button to drag the scroll bar downwards, the picture is shown below.
VKiK216.png?1
Now if I scroll the mouse wheel upwards or downwards, the display will jump to the very beginning because LogView will move the selection. The picture is shown below. However, at this point I normally want to move the display. Again, this is is different from UltraEdit or Notepad or Microsoft Word.
OBOb4vG.png?1

> If you want to smile, enable the logs in TestSQL3.dpr - you will get a 550 MB of log.
> Then try to open it with NotePad2 or UltraEdit, and compare the speed and memory used.

LogView is indeed lightning fast ! Kudos for your work ! ( But It should be noted that UltraEdit is also lightning fast. )
As mentioned above, the scrolling behavior when one scroll the mouse wheel in UltraEdit might be better.
As mentioned in the previous post, making the size of the scroll bar proportional to the log file length (i.e., big scroll bar when small log file is opened) might also be better.

Last edited by ComingNine (2014-09-09 07:23:39)

ab · 2014-09-09 07:50:50

In fact, the scroll wheel is used to scroll from one row to another, since it allows to quickly read the full log content of each row in the bottom memo.
When debugging, it is much more convenient than scrolling per page.
This is a log viewer, for debugging, not a text viewer, for reading some text or code.
Purpose of this tool is to debug, not work like editors.

To scroll, you point, click, move and release the scrollbar.
Or you click on the event on the left side, to reach the left event.
Or you enter some text in the search box.

ComingNine · 2014-09-09 08:01:19

ab wrote:

In fact, the scroll wheel is used to scroll from one row to another, since it allows to quickly read the full log content of each row in the bottom memo.
When debugging, it is much more convenient than scrolling per page.
This is a log viewer, for debugging, not a text viewer, for reading some text or code.
Purpose of this tool is to debug, not work like editors.
To scroll, you point, click, move and release the scrollbar.
Or you click on the event on the left side, to reach the left event.
Or you enter some text in the search box.

Thank you very much for your comments ! I can see your point !

About the scroll bar appearance (i.e., proportional to the log file length), the code of Chris Luck in http://www.delphigroups.info/2/0e/291440.html seems to work in a simple VCL project. Could you help to comment whether it is possible for LogView to have a proportional scroll bar ?

var 
  ScrollInfo: TScrollInfo; 
  I, J, K: Integer; 
  N1, N2: Double; 
begin 
//  Conditions for proportional thumb :- 
//  1) Take 127 as the *Minimum* value for nMax. 
//  2) nPage = nMax - 126. (for correct thumb positioning) 
//  3) nMax = (127 / (( RowCount / VisibleRowCount ) -1) ) + 127 
  // prevent drawing (WM_SETREDRAW in 'Messages' unit) 
  // or try DoubleBuffering to reduce flicker. 
  SG.Perform(WM_SETREDRAW, 0, 0); 
  try 
    // take a note of TopRow so we can reset it later 
    I := SG.TopRow; 
    // then set TopRow to 0 (no change if already there) 
    SG.TopRow := 0; 
    J := SG.RowCount-SG.FixedRows; 
    K := SG.VisibleRowCount-SG.FixedRows; 
    N1 := (J / K) -1; 
    FillChar(ScrollInfo,SizeOf(ScrollInfo),0); 
    ScrollInfo.cbSize := SizeOf(ScrollInfo); 
    ScrollInfo.fMask := SIF_PAGE; 
    // reset nPage to allow scrollbar to show 
    ScrollInfo.nPage := 0; 
    SetScrollInfo(SG.Handle, SB_VERT, ScrollInfo, false); 
    if N1 > 0.00001 then  // prevent div by 0 
    begin 
      N2 := (127 / N1)+127; 
      ScrollInfo.nMax := Round(N2); 
      ScrollInfo.nMin := 0; 
      ScrollInfo.nPage := ScrollInfo.nMax - 126; 
    end 
    else 
    begin 
      ScrollInfo.nMin := 0; 
      ScrollInfo.nMax := 127; 
      ScrollInfo.nPage := 0; 
    end; 
    ScrollInfo.fMask := SIF_RANGE or SIF_PAGE or SIF_POS; 
    SetScrollInfo(SG.Handle, SB_VERT, ScrollInfo, true); 
    // reset TopRow 
    SG.TopRow := I; 
  finally 
    SG.Perform(WM_SETREDRAW, 1, 0);  // enable drawing 
    SG.Refresh; 
  end; 
end;

ab · 2014-09-09 11:07:44

We have added a new TSynLogFamily.RotateFileDailyAtHour property to enable log file rotation or SynLZ compression, at a given hour.

Also introducing TSynLogFamily.OnRotate property to enable customize log file rotation.

See http://synopse.info/fossil/info/9c76171d3 and http://synopse.info/fossil/info/a4306758f

ComingNine · 2014-09-09 11:51:33

Brilliant work !

mORMot Open Source

#1 2014-09-06 23:15:07

AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#2 2014-09-06 23:22:08

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#3 2014-09-07 06:17:17

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#4 2014-09-07 08:30:39

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#5 2014-09-07 08:32:52

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#6 2014-09-07 16:34:15

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#7 2014-09-07 17:50:03

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#8 2014-09-07 18:08:14

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#9 2014-09-07 20:17:36

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#10 2014-09-08 06:33:58

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#11 2014-09-08 07:17:42

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#12 2014-09-08 17:04:04

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#13 2014-09-08 20:26:52

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#14 2014-09-08 20:52:00

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#15 2014-09-09 06:17:51

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#16 2014-09-09 07:16:09

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#17 2014-09-09 07:50:50

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#18 2014-09-09 08:01:19

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#19 2014-09-09 11:07:44

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

#20 2014-09-09 11:51:33

Re: AutoFlushTimeOut has no effect when compiled app runs in non-C drive

Board footer