Introducing enhanced logging mechanism

docme · 2015-06-15 15:32:32

I'm enjoying the logging simplicity:

var ILog: ISynLog;
begin
  ILog := TSynLog.Enter;

But I have a rather messy user defined hierarchy of classes and cross-unit-inherited methods and when it is used for class methods, I'm wanting to also store the self value (and perhaps class type) also.
I've tried using:

  ILog := TSynLog.Enter(self,'something');

and

  ILog := TSynLog.Enter(self);

However these remove the unit name (and the .mab method name) from the log file line, which I want to keep there.
Any pointers as to how I can do this?
TIA

docme · 2015-06-19 13:56:24

I've looked at the data available for logging and come up with my own enter line format, which I think is reasonably parseable:

code address, ['-', instance address,] {' ', [ounitname, '.',] [instance class name, '@',] osymname, ' (', oline, ')',} [' ', extra text]

Where:
[] and {} delimit sections which will hide/show depending on data availability or WithUnitName setting.
Instance is always assumed to be self and the methodname parameter I'd regard as extra text.
Not sure if I've made a mess of the MethodNameLocal item in my code though.
Two spaces before extra text to indicate free form text follows.
There are two sources for unit, which if produce different text would show both separated with '/'.
Instance class name is only shown if different from osymname class.

I don't know how involved it is changing the logviewer, but from what I've seen there aren't any changes necessary there.
Added in TSynMapFile = class:

  private
    class procedure GetLog(aAddressAbsolute: PtrUInt; out ounitname,
      osymname: rawutf8; out oline: integer); static;

Added before implementation - this allows lazy programmer to use self parameter in non-class procedure/function to no ill effect:

const self = nil;

This is a fix of class procedure TSynMapFile.Log to return data instead of logging it:

class procedure TSynMapFile.GetLog(aAddressAbsolute: PtrUInt; out ounitname, osymname : rawutf8;out oline : integer);
var u, s, Line, offset: integer;
begin
  ounitname := '';
  osymname := '';
  oline := -1;
  if (aAddressAbsolute=0) or (InstanceMapFile=nil) then
    exit;
  with InstanceMapFile do
    begin
      if not HasDebugInfo then exit;
      offset := AbsoluteToOffset(aAddressAbsolute);
      s := FindSymbol(offset);
      u := FindUnit(offset,Line);
      if s<0 then begin
        if u<0 then begin
          exit;
        end;
      end else
        if (u>=0) and (s>=0) then
          if u=fUnitSynLogIndex  then
            exit else // don't log stack trace internal to SynLog.pas :)
          if (u=fUnitSystemIndex) and (PosEx('Except',Symbols[s].Name)>0) then
            exit; // do not log stack trace of System.SysRaiseException
      if u>=0 then begin
        ounitname := Units[u].Symbol.Name;
        if s>=0 then
          if Symbols[s].Name=Units[u].Symbol.Name then
            s := -1;
      end;
      if s>=0 then
        osymname := Symbols[s].Name;
      if Line>0 then
        oline := Line;
    end;
end;

And changed procedure TSynLog.AddRecursion:

procedure TSynLog.AddRecursion(aIndex: integer; aLevel: TSynLogInfo);
type
  {$ifdef FPC}{$PACKRECORDS 1}{$endif}
  TTypeInfo = {$ifndef FPC}packed{$endif} record
    Kind: byte;
    Name: ShortString;
  end;
  {$ifdef FPC}{$PACKRECORDS C}{$endif}
  TClassType =
    {$ifndef FPC_REQUIRES_PROPER_ALIGNMENT}
    packed
    {$endif FPC_REQUIRES_PROPER_ALIGNMENT}
    record
     ClassType: TClass;
     ParentInfo: pointer;
     PropCount: SmallInt;
     UnitName: ShortString;
  end;
  PTypeInfo = ^TTypeInfo;
  PClassType = ^TClassType;
var Info: PTypeInfo;
    MS: cardinal;
    cunitname,csymname:string;
    ounitname,osymname:rawutf8;
    dotpos,oline : integer;
label DoEnt;
// normal procedure or function:
// Details: code address,                          {' ', [ounitname, '.',]                             osymname, ' (', oline, ')',} ['  ', extra text].
// method:
// Details: code address, ['-', instance address,] {' ', [ounitname, '.',] [instance class name, '@',] osymname, ' (', oline, ')',} ['  ', extra text].
begin
  with fThreadContext^ do
  if cardinal(aIndex)<cardinal(RecursionCount) then
  with Recursion[aIndex] do begin
    if aLevel<>sllLeave then begin
      TSynMapFile.GetLog(Caller,ounitname,osymname,oline);
      fWriter.AddPointer(Caller);
      if Instance<>nil then begin
        fWriter.Add('-');
        fWriter.AddPointer(PtrUInt(Instance));
      end;
      if ClassType<>nil then begin
        if fFamily.WithUnitName then begin
          Info := PPointer(PtrInt(ClassType)+vmtTypeInfo)^;
          if Info<>nil then begin
            {$ifdef FPC}
            cunitname := PClassType(GetFPCTypeData(pointer(Info)))^.UnitName;
            {$else}
            cunitname := PClassType(@Info^.Name[ord(Info^.Name[0])+1])^.UnitName;
            {$endif}
            if cunitname = '' then
            else
              if (ounitname <> cunitname) and (ounitname <> '') then
                ounitname := cunitname + '/' + ounitname;
          end;
        end;
        // classname:
        csymname := PShortString(PPointer(PtrInt(ClassType)+vmtClassName)^)^;
        if (osymname = '') then begin
          if (csymname <> '') then
            osymname := csymname + '@';
        end else begin
          if (csymname <> '') then
            if (csymname <> osymname) then begin
              dotpos := pos('.',osymname);
              if dotpos <> 0 then
                if csymname <> copy(osymname,1,dotpos-1) then
                  osymname := csymname + '@' + osymname
            end;
        end;
      end;
      if (fFamily.WithUnitName and (ounitname <> ''))
      or (osymname <> '') then begin
        fWriter.Add(' ');
        if (fFamily.WithUnitName and (ounitname <> '')) then begin
          fWriter.AddShort(ounitname);
          fWriter.Add('.');
        end;
        if (osymname <> '') then
          fWriter.AddShort(osymname);
        if (oline <> -1) then begin
          fWriter.Add(' ');
          fWriter.Add('(');
          fWriter.Add(oline);
          fWriter.Add(')');
        end;
      end;
      if MethodName<>nil then begin // extra text!
        fWriter.Add(' ');
        fWriter.Add(' ');
//        if MethodNameLocal<>mnLeave then begin
          fWriter.AddNoJSONEscape(MethodName);
//          if MethodNameLocal=mnEnter then
//            MethodNameLocal := mnLeave;
//        end;
      end;
    end;
    // Timestamp - start and stop.
    if fFamily.HighResolutionTimeStamp and (fFrequencyTimeStamp<>0) then
DoEnt:case aLevel of
        sllEnter: EnterTimeStamp := fCurrentTimeStamp;
        sllLeave: begin
                    if fFrequencyTimeStamp=0 then
                      MS := 0 else // avoid div per 0 exception
                      MS := ((fCurrentTimeStamp-EnterTimeStamp)*(1000*1000))div fFrequencyTimeStamp;
                    fWriter.AddMicroSec(MS);
                  end;
      end
    else
      if aLevel in [sllEnter,sllLeave] then
        begin
          QueryPerformanceCounter(fCurrentTimeStamp);
          dec(fCurrentTimeStamp,fStartTimeStamp);
          goto DoEnt;
        end;
  end;
  fWriter.AddEndOfLine(aLevel);
end;

Hope it is helpful to someone.

ab · 2015-06-19 17:00:42

Thanks for sharing.

docme · 2015-06-20 10:44:36

AB: Pleasure. Feel free to include the code into synlog and advise if you think I've missed anything in my formatting.
I'm also looking to improve the logview program based on this change for myself, perhaps with a diagram interface and/or automated log checking.
Any ideas where to start looking for existing code that does this?

docme · 2015-08-28 09:46:03

I'm wanting to put in code like the following:

ILog := TSynLog.Enter(self,'param1'+param1+'param2'+param2);

However it won't compile in D2007.
Any ideas what I can do to make something like it work?

ab · 2015-08-28 11:50:49

Just write

ILog := TSynLog.Enter(self,pointer(RawUTF8('param1'+param1+'param2'+param2)));

mpv · 2015-11-23 11:05:25

I discover some problems with viewing log files using LogView.dpr in case log is in ptIdentifiedInOnFile format.
The first one: Double click on enter/leave do not check the current log line thread and move me to incorrect corresponding log record. This one I fix in LogViewMain.pas - see [55335f5bc6]

The second is wrong method execution time profiling. I write a ticket with small sample log to reproduce: [a1174de4f5]

Sometimes customers do not give me access to production servers and the only thing I can detect problems is a log files they send to me, so profiling is very important

mpv · 2016-02-26 13:04:27

@AB
I need a small enhancement for logging sllLeave type of event.
In the corporate environment we usual use Zabbix or MSSCOM (depending on customer) for monitoring different aspects of out application servers (memory, CPU dick space, windows performance counters etc.)
Also we need to analyse a application businesses logic specific features, such as "average response time for different methods" , "number of request to specified app server method" etc.
Almost all we need we can easy calculate by parsing a app log files using unix bash commands (and got a very easy Zabbix integration). The one we miss is "response time for different methods". Currently "method time" calculation logic is complex and are inside of LogViewer app. I can't reproduce it inside bash easy even with perl. So idea is to add a method name (if any) to the sllLeave event type, so instead of

20160219 11302152  #  +    getAppInfo
......
20160219 11302152  #  -    00.000.182

I will got

20160219 11302152  #  +    getAppInfo
......
20160219 11302152  #  -    getAppInfo 00.000.182

In this case I can very easy calculate a response time statistics for `getAppInfo` method.

We need only a small modification to TSynLog.AddRecursion function and may be add an option to TSynLogFamily.

What do you think? Can we add this modification and commit to trunk?

P.S.
I saw mORMot monitor, but can't use it in enterprise solution - enterprise admin usually want to see all statistics of all (not only mORMot based) services in the single tool like MSSCOM/Zabbix, etc, so I need to integrate there.

ab · 2016-02-26 19:24:23

We also use Zabbix here, but for IT/infrastructure level.
The new Monitoring classes of mORMot (still not finished) are to be used at ORM/SOA Level.

The format you are proposing for the logs was the initial layout.
Then we deleted the redundant information, which polluted the logs.
Honnestly, we would not go back...

I guess it would be MUCH faster and safer to use the TSynLogFile class to read the log, and compute the time.
OR
Just define your own log entry in the corresponding methods, including the time via a TPrecisionTimer.Start/Stop.

mpv · 2016-10-15 13:53:59

I discover a AV in case of

TSynLogClass.Family.EchoRemoteStart

is called before any

TSynLogClass.Add

I propose to add a SynLog() call in the first line of

procedure TSynLogFamily.EchoRemoteStart(..)
begin
  SynLog(); // <-- will create a SynLogFileList to prevent AV 
  EchoRemoteStop;
  fEchoRemoteEvent := aClientEvent;
  fEchoRemoteClientOwned := aClientOwnedByFamily;
  SynLogFileList.Safe.Lock; // <- in other case AV is here
end;

Bo · 2018-07-25 06:05:03

Hi AB,

How do I not to log the exception I explicitly want them to be silent somewhere but do not want this type of exception globally silent:

try
  TryLoadAsFormat1(data);
  // no exception, is format 1
  // do some thing here
except
// do nothing,  silent the exception, but the ISynLog will log this exception which I don't need
end;

Thanks,

mpv · 2018-07-25 12:52:22

You can add some exceptions to be ignored to LogFamily.ExceptionIgnore list

Bo · 2018-07-25 23:16:18

mpv wrote:

You can add some exceptions to be ignored to LogFamily.ExceptionIgnore list

Isn't that globally ignore that type of exception? But I just want to ignore in that function.

ab · 2018-07-26 06:53:59

It is not possible.

And remember that exceptions should be exceptional!
http://mattwarren.org/2016/12/20/Why-Ex … ceptional/
http://blog.synopse.info/post/2015/04/1 … -good-idea
https://synopse.info/files/html/Synopse … l#TITL_165

franfj · 2018-09-04 08:24:02

Hi ab,

Is there any way to create a SynLog for each instance of a class. I've one class that is used on several parts of the application, and I want to be able to log each one on a different file.

One way of doing it will be creating a TSynLog descendant for each instance.

unit MyServer;
  
  TMyAsynchServer = class (TAsyncServer)
  ...
  constructor Create(..., aLog: TSynLogClass);

And on the application that uses the unit:

unit MyMain;
  TMyLog1 = class (TSynLog)
  end;
  TMyLog2 = class (TSynLog)
  end;
 ...
  TMyLogN = class (TSynLog)
  end;

...

  with TMyLog1.Family do
  begin
    // I want to log on my custom function
     EchoCustom := MySynLogTrace1; 
     NoFile := True; 
  end;
  FMyServer1 := TMyAsyncServer.Create(.... , TMyLog1);

  with TMyLog2.Family do
  begin
    // I want to log on my custom function
     EchoCustom := MySynLogTrace2; 
     NoFile := True; 
  end;
  FMyServer2 := TMyAsyncServer.Create(.... , TMyLog2);
  ...

But I'm looking for a way to do it within the unit that defines the component (TMyAsynchServer), to be able to define the "EchoCustom" functions in the same class/unit, as it will echo to a custom logger that is already created by the application.

unit MyServer;
  TMyAsynchServer = class (TAsyncServer)
  ...
  constructor Create(...); // no need to define a TSynLogClass since is managed inside
  function MySynLogEcho(Sender: TTextWriter; Level: TSynLogInfo;
  const Text: RawUTF8): boolean;
  ...

constructor TMyAsynchServer.Create(....)
begin
  // I need a way to create here a TSynLogClass per instance, not shared between other instances of TMyAsychServer 
  with XXXX.Family do  // ! If I use one TSynLog class, all the instances point to the latest instance MySynLogEcho fucntion
  begin 
    // I want to log on my custom function
     EchoCustom := MySynLogEcho; 
     NoFile := True; 
  end;
  inherited Create(..., MySynLogClassWithEcho, ...)
end;

I'm not sure if I've explained it well... it's a bit complex, maybe is not designed to work this way and is not possible, hope that could be understood

Thanks!

Last edited by franfj (2018-09-04 08:25:05)

edwinsn · 2018-09-05 02:53:17

@franfj,
There is a simpler way, check my TSynLog child class below:

  (*
    A TSynLog child class that adds only one single feature:
     - You can specify the target log file name.

    Example:
      var
        logger: TEyLogger;
      begin
        logger := TEyLogger.Create('C:\logfile001.log');
        logger.Log('testing...');
        ...
        logger.Free;
      end;

    Note:
     - Do not call TSynLog.Add class method, but instead always create a new TEyLogger object and call its Log()
       method.
     - See: http://synopse.info/forum/viewtopic.php?pid=10765

    By design you make a child class of TSynLog and all instances of that class will share the same logging target,
    this makes it very hard to control the target output file, so in order to allow each object of TEyLogger
    has its own target file, we override the ComputeFileName method.
  *)
  TEyLogger = class(TSynLog)
  private
    FSpecifiedBufferSize: Integer;
  protected
    FSpecifiedLogFile: string;
    procedure ComputeFileName; override;
  public
    constructor Create(const aLogFilePath: string; const aBufSize: Integer = 4096);
  end;

implementation

uses
  EyFileUtils;

constructor TEyLogger.Create(const aLogFilePath: string; const aBufSize:
  Integer = 4096);
begin
  FSpecifiedLogFile := aLogFilePath;
  FSpecifiedBufferSize := aBufSize;
  inherited Create(nil);

  //by default accept all levels of logging
  Self.Family.Level := LOG_VERBOSE;
  Self.GenericFamily.Level := LOG_VERBOSE;

  // by default don't add the system's environment variables at the beginning of the target log file.
  self.fFamily.NoEnvironmentVariable := True;
  self.fFamily.IncludeComputerNameInFileName := False;

  self.GenericFamily.NoEnvironmentVariable := True;
  self.GenericFamily.IncludeComputerNameInFileName := False;
end;

procedure TEyLogger.ComputeFileName;
begin
  fFileName := FSpecifiedLogFile;
  if fFileName = '' then
    inherited;
end;

franfj · 2018-09-05 06:27:16

Thanks @edwinsn but I think that does not match what I'm looking for, because I wanted to use my own logging to log the output of some Synopse mORMot classes (at the moment TAsynchServer from SynBidirSock, but could be anything in the future), so I can't change the way that current implementation works (they expect a TSynLogClass and use the .Add method).

Anyway thanks for the code, the linked https://synopse.info/fossil/info/d3f5197f3c shows that it's a "limitation" of the design pattern as I supposed.

mORMot Open Source

#51 2015-06-15 15:32:32

Re: Introducing enhanced logging mechanism

#52 2015-06-19 13:56:24

Re: Introducing enhanced logging mechanism

#53 2015-06-19 17:00:42

Re: Introducing enhanced logging mechanism

#54 2015-06-20 10:44:36

Re: Introducing enhanced logging mechanism

#55 2015-08-28 09:46:03

Re: Introducing enhanced logging mechanism

#56 2015-08-28 11:50:49

Re: Introducing enhanced logging mechanism

#57 2015-11-23 11:05:25

Re: Introducing enhanced logging mechanism

#58 2016-02-26 13:04:27

Re: Introducing enhanced logging mechanism

#59 2016-02-26 19:24:23

Re: Introducing enhanced logging mechanism

#60 2016-10-15 13:53:59

Re: Introducing enhanced logging mechanism

#61 2018-07-25 06:05:03

Re: Introducing enhanced logging mechanism

#62 2018-07-25 12:52:22

Re: Introducing enhanced logging mechanism

#63 2018-07-25 23:16:18

Re: Introducing enhanced logging mechanism

#64 2018-07-26 06:53:59

Re: Introducing enhanced logging mechanism

#65 2018-09-04 08:24:02

Re: Introducing enhanced logging mechanism

#66 2018-09-05 02:53:17

Re: Introducing enhanced logging mechanism

#67 2018-09-05 06:27:16

Re: Introducing enhanced logging mechanism

Board footer