Real-time logging of a service application

Question

I have a service application which I will be soon implementing a log file. Before I start writing how it saves the log file, I have another requirement that a small simple form application should be available to view the log in real-time. In other words, if the service writes something to the log, not only should it save it to the file, but the other application should immediately know and display what was logged.

A dirty solution would be for this app to constantly open this file and check for recent changes, and load anything new. But this is very sloppy and heavy. On the other hand, I could write a server/client socket pair and monitor it through there, but it's a bit of an overload I think to use TCP/IP for sending one string. I'm thinking of using the file method, but how would I make this in a way that wouldn't be so heavy? In other words, suppose the log file grows to 1 million lines. I don't want to load the entire file, I just need to check the end of the file for new data. I'm also OK with a delay of up to 5 seconds, but that would contradict the "Real-time".

The only methods of reading/writing a file which I am familiar with consist of keeping file open/locked and reading all contents of the file, and I have no clue how to only read portions from the end of a file, and to protect it from both applications attempting to access it.

Answer 1

Our Open Source TSynLog class matches most of your needs - it's already stable and proven (used in real world applications, including services).

It features mainly fast logging (with a set of levels, not a hierarchy of level), exception interception with stack trace, and custom logging (including serialization of objects as JSON within the log).

You have even some additional features, like customer-side method profiler, and a log viewer.

Log files are locked during generation: you can read them, not modify them.

Works from Delphi 5 up to XE2, fully Open Source and with daily updates.

Answer 2

Years ago I wrote a circular buffer binary-file trace logging system, that avoided the problem of an endlessly growing file, while giving me the capabilities that I wanted, such as being able to see a problem if I wanted to, but otherwise, being able to just ignore the trace buffer.

However, if you want a continuous online system, then I would not use files at all.

I used files because I really did want file-like persistence and no listener app to have to be running. I simply wanted the file solution because I wanted the logging to happen whether anybody was around to "listen" right now, or not, but didn't use an endlessly growing text log because I was worried about using up hundreds of megs on log files, and filling up my 250 megabyte hard drive. One hardly has concerns like that in the era of 1 tb hard disks.

As David says, the client server solution is best, and is not complex really.

But you might prefer files, as I did, in my case way back. I only launched my viewer app as a post-mortem tool that I ran AFTER a crash. This was before there was MadExcept or anything like it, so I had some apps that just died, and I wanted to know what had happened.

Before my circular buffer, I would use a debug view tool like sys-internals DebugView and OutputDebugString, but that didn't help me when the crash happened before I launched DebugView.

File-based logging (binary) is one of the few times I allowed myself to create binary files. I normally hate hate hate binary files. But you just try to make a circular buffer without using a fixed length binary record.

Here's a sample unit. If I was writing this now instead of in 1997, I would have not used a "File of record", but hey, there it is.

To extend this unit so it could be used to be the realtime viewer, I would suggest that you simply check the datetime stamp on the binary file and refresh every 1-5 seconds (your choice) but only when the datetime stamp on the binary trace file has changed. Not hard, and not exactly a heavy load on the system.

This unit is used for the logger and for the viewer, it is a class that can read from, and write to, a circular buffer binary file on disk.

unit trace;

{$Q-}
{$I-}

interface

uses Classes;

const
  traceBinMsgLength = 255; // binary record message length
  traceEOFMARKER = $FFFFFFFF;

type
  TTraceRec = record
    index: Cardinal;
    tickcount: Cardinal;
    msg: array[0..traceBinMsgLength] of AnsiChar;
  end;
  PTraceBinRecord = ^TTraceRec;
  TTraceFileOfRecord = file of TTraceRec;

  TTraceBinFile = class
    FFilename: string;
    FFileMode: Integer;
    FTraceFileInfo: string;
    FStorageSize: Integer;
    FLastIndex: Integer;
    FHeaderRec: TTraceRec;
    FFileRec: TTraceRec;
    FAutoIncrementValue: Cardinal;
    FBinaryFileOpen: Boolean;
    FBinaryFile: TTraceFileOfRecord;
    FAddTraceMessageWhenClosing: Boolean;
  public
    procedure InitializeFile;
    procedure CloseFile;
    procedure Trace(msg: string);
    procedure OpenFile;
    procedure LoadTrace(traceStrs: TStrings);
    constructor Create;
    destructor Destroy; override;

    property Filename: string       read FFilename write FFilename;
    property TraceFileInfo: string  read FTraceFileInfo write FTraceFileInfo;

   // Default 1000 rows.
   // change storageSize to the size you want your circular file to be before
   // you create and write it. Remember to set the value to the same number before
   // trying to read it back, or you'll have trouble.
    property StorageSize: Integer   read FStorageSize write FStorageSize;
    property AddTraceMessageWhenClosing: Boolean
      read FAddTraceMessageWhenClosing write FAddTraceMessageWhenClosing;

  end;

implementation

uses SysUtils;

procedure SetMsg(pRec: PTraceBinRecord; msg: ansistring);
var
  n: Integer;
begin
  n := length(msg);
  if (n >= traceBinMsgLength) then
  begin
    msg := Copy(msg, 1, traceBinMsgLength);
    n := traceBinMsgLength;
  end;
  StrCopy({Dest} pRec^.msg, {Source} PAnsiChar(msg));
  pRec^.msg[n] := Chr(0); // ensure nul char termination
end;

function IsBlank(var aRec: TTraceRec): Boolean;
begin
  Result := (aRec.msg[0] = Chr(0));
end;

procedure TTraceBinFile.CloseFile;
begin
  if FBinaryFileOpen then
  begin
    if FAddTraceMessageWhenClosing then
    begin
      Trace('*END*');
    end;
    System.CloseFile(FBinaryFile);
    FBinaryFileOpen := False;
  end;
end;

constructor TTraceBinFile.Create;
begin
  FLastIndex := 0; // lastIndex=0 means blank file.
  FStorageSize := 1000; // default.
end;

destructor TTraceBinFile.Destroy;
begin
  CloseFile;
  inherited;
end;

procedure TTraceBinFile.InitializeFile;
var
  eofRec: TTraceRec;
  t: Integer;
begin
  Assert(FStorageSize > 0);
  Assert(Length(FFilename) > 0);
  Assign(FBinaryFile, Filename);
  FFileMode := fmOpenReadWrite;
  Rewrite(FBinaryFile);

  FBinaryFileOpen := True;

  FillChar(FHeaderRec, sizeof(TTraceRec), 0);
  FillChar(FFileRec, sizeof(TTraceRec), 0);
  FillChar(EofRec, sizeof(TTraceRec), 0);

  FLastIndex := 0;
  FHeaderRec.index := FLastIndex;
  FHeaderRec.tickcount := storageSize;
  SetMsg(@FHeaderRec, FTraceFileInfo);

  Write(FBinaryFile, FHeaderRec);
  for t := 1 to storageSize do
  begin
    Write(FBinaryFile, FFileRec);
  end;

  SetMsg(@eofRec, 'EOF');
  eofRec.index := traceEOFMARKER;
  Write(FBinaryFile, eofRec);
end;

procedure TTraceBinFile.Trace(msg: string);
// Write a trace message in circular file.
begin
  if (not FBinaryFileOpen) then
    exit;
  if (FFileMode = fmOpenRead) then
    exit; // not open for writing!
  Inc(FLastIndex);
  if (FLastIndex > FStorageSize) then
    FLastIndex := 1; // wrap around to 1 not zero! Very important!
  Seek(FBinaryFile, 0);
  FHeaderRec.index := FLastIndex;
  Write(FBinaryFile, FHeaderRec);
  FillChar(FFileRec, sizeof(TTraceRec), 0);
  Seek(FBinaryFile, FLastIndex);
  Inc(FAutoIncrementValue);
  if FAutoIncrementValue = 0 then
    FAutoIncrementValue := 1;
  FFileRec.index := FAutoIncrementValue;
  SetMsg(@FFileRec, msg);
  Write(FBinaryFile, FFileRec);
end;

procedure TTraceBinFile.OpenFile;
begin
  if FBinaryFileOpen then
  begin
    System.CloseFile(FBinaryFile);
    FBinaryFileOpen := False;
  end;
  if FileExists(FFilename) then
  begin
    //    System.FileMode :=fmOpenRead;
    FFileMode := fmOpenRead;
    AssignFile(FBinaryFile, FFilename);
    System.Reset(FBinaryFile); // open in current mode
    System.Seek(FBinaryFile, 0);
    Read(FBinaryFile, FHeaderRec);
    FLastIndex := FHeaderRec.index;
    FTraceFileInfo := string(FHeaderRec.Msg);
    FBinaryFileOpen := True;
  end
  else
  begin
    InitializeFile; // Creates the file.
  end;
end;

procedure TTraceBinFile.LoadTrace(traceStrs: TStrings);
var
  ReadAtIndex: Integer;
  Safety: Integer;

  procedure NextReadIndex;
  begin
    Inc(ReadAtIndex);
    if (ReadAtIndex > FStorageSize) then
      ReadAtIndex := 1; // wrap around to 1 not zero! Very important!
  end;

begin
  Assert(Assigned(traceStrs));
  traceStrs.Clear;

  if not FBinaryFileOpen then
  begin
    OpenFile;
  end;

  ReadAtIndex := FLastIndex;

  NextReadIndex;

  Safety := 0; // prevents endless looping.

  while True do
  begin
    if (ReadAtIndex = FLastIndex) or (Safety > FStorageSize) then
      break;
    Seek(FBinaryFile, ReadAtIndex);
    Read(FBinaryFIle, FFileRec);
    if FFileRec.msg[0] <> chr(0) then
    begin
      traceStrs.Add(FFileRec.msg);
    end;
    Inc(Safety);
    NextReadIndex;
  end;
end;

end.

Answer 3

What you are asking for is exactly what I do in one of my company's projects.

It has a service that hosts an out-of-process COM object so all of our apps can write messages to a central log file, and then a separate viewer app that uses that same COM object to receive notifications directly from the service whenever the log file changes. The COM object lets the viewer know where the log file is physically located so the viewer can open the file directly when needed.

For each notification that is received, the viewer checks the new file size and then reads only the new bytes that have been written since the last notification (the viewer keeps track of what the previous file size was). In an earlier version, I had the service actually push each individual log entry to the viewer directly, but under heavy load that is a lot of traffic to sift through, so I ended up taking that feature out and let the viewer handle reading the data instead, that way it can read multiple log entries at one time more efficiently.

Both the service and the viewer have the log file open at the same time. When the service creates/opens the log file, it sets the file to read/write access with read-only sharing. When the viewer opens the file, it sets the file to read-only access with read/write sharing (so the service can still write to it).

Needless to say, both service and viewer are run on the same machine so they can access the same local file (no remote files are used). Although the service does have a feature that forwards log entries via TCP/IP to a remote instance of the service running on another machine (then the viewer running on that machine can see them).

Answer 4

My suggestion would be to implement your logging in such a way that the log file "rolls over" on a daily basis. E.g. at midnight, your logging code renames your log file (e.g. MyLogFile.log) to a dated/archive version (e.g. MyLogFile-30082012.log), and starts a new empty "live" log (e.g. again MyLogFile.log).

Then it's simply a question of using something like BareTail to monitor your "live"/daily log file.

I accept this may not be the most network-efficient approach, but it's reasonably simple and meets your "live" requirement.

Answer 5

This may sound like a completely nutty answer but..

I use Gurock Softwares Smart Inspect.. http://www.gurock.com/smartinspect/ its great because you can send pictures, variables whatever and it logs them all, so while you want text atm, its a great for watching your app real time even on remote machines.. it can send it to a local file..

It maybe a useful answer to your problem, or a red herring - its a little unconventional but the additional features it has you may feel worth incorporating later (such as its great for capturing info should something go horribly wrong)