Detailed logging (for debugging)

[Mike Torrettinni 198]

Hi

 

My application processes log files and generates reports. Now I have a customer that is not getting expected results and I can't reproduce it, since there are some specifics how application works based on the system and other connecting components, which I can't replicate.

I'm preparing a version that will log methods that I think are involved in causing the issue/odd results. I'm adding LogLine calls in these methods and log:

 

LogLine('start method processA');

...

LogLine('accessing log file = '+filename);

..

LogLine('in For loop = +inttostr(i));

LogLine(details of loop);

...

LogLine('close log file = '+filename);

...

LogLine('end method processA');

 

The I can show, save the full log.

 

So, basically I'm adding logging before/after any line I want to know what is going on. This is tedious work.

And at the end I don't want to have all these LogLine lines in my methods, since the code becomes unreadable and a mess. So, I delete these lines when I don't need them anymore... and then add them to another places I need to debug.

 

Anybody else is doing similar thing and found easier way to manage these kind of ad-hoc need for detailed logging? Any suggestions?

 

Thanks!

[Markus Kinzler 174]

Have a look at this tool: https://github.com/grijjy/GrijjyCloudLogger

[Mike Torrettinni 198]

@Markus Kinzlerthank you, good tool.

 

Right now I'm more looking for advice on how to manage adding ('injecting') and removing these log lines, not the actual logging mechanism. I just added 50+ lines into a few methods I want to get detailed log. I will need to remove all these lines, once I'm done debugging because I don't want to leave them in the code.

 

A tedious job. So, any advice how to simplify this, is most welcome!

 

[Edwin Yip 154]

Two options off my head:

1.  Tools->CodeSite->CodeSite Method Tracer, which can auto add method enter/exit tracing to your code. Once you have identified the method, you can manually add the logging for each time as you tried.
2. Utilize DelphiAST to write an IDE plugin or a tool to do that :) If you do this, don't forget to share it with the community :)

Edited November 6, 2018 by edwinyzh

[Ralf Kaiser 2]

3 minutes ago, edwinyzh said:

If you do this, forget to share it with the community 🙂

I think here is a "do not" missing, is it?

[Lars Fosdal 1788]

I have a DebugOut call that I mostly leave in the code as needed.  By default it writes to OutputDebugString, but it also writes to a 4K line buffer internally, and I have patched the system menu to add a "Log to file" option. If the user enables logging to file, it first dumps the 4K line buffer then appends anything else being logged after that.  For server apps, there is a midnight rollover routine that creates a new logfile, and deletes logfiles older than <configurable> days.

As for adding / removing logging - I can ifdef or comment things in and out by hand, but mostly I just leave it in there, if it is not pure development test code, that is.

More logging > less logging - when you actually need to figure out what happens.

 

 

[Guest]

Last time (so tired of all the IFDEFs for debug logging) i tried Assert. The basic idea of Assert is nice as (correct me if i'm wrong) the compiler does not produce any code for production. But it does not help with th issue of cluttered-up sources. Also it would be nice with a version of Assert that is a bit more flexible.

 

@edwinyzh second idea seems most apt. In my mind it will not be a small project. But i have not used the full-blown tool for these things enough to have any constructive input.

Edited November 5, 2018 by Guest

[Zacherl 3]

Assert is fine, but sometimes you want to have logging code in your productive version. Asserting is not a good idea here as it will raise an exception. Besides that only one event can be logged at a time (as the application crashes after the first assertion / or executes the exception handler what will them prevent execution of successive assertions).

[Guest]

@Zacherl, i know, there are workarounds to make it log, but it becomes too shaky. That's what i meant with "a more flexible variant". Still it does not solve the problem anyway.

[dummzeuch 1495]

2 hours ago, Zacherl said:

Assert is fine, but sometimes you want to have logging code in your productive version. Asserting is not a good idea here as it will raise an exception. Besides that only one event can be logged at a time (as the application crashes after the first assertion / or executes the exception handler what will them prevent execution of successive assertions).

But you could use assert to mask out the logging:

function MyLogging(const _Text: string): boolean;
begin
  doLogging(_Text);
  Result := true;
end;

Assert(MyLogging('My very important log message'));

 

This would remove all calls to the logging function when you disable assertions.

Edited November 5, 2018 by dummzeuch

[Zacherl 3]

Isn't the optimizer smart enough to remove empty function calls? Well ... I know ... it's Delphi ... and Delphi is not really known for perfectly optimized code, but detecting empty functions is a really easy task. Using `IFDEF`s inside the logging function itself would be a better solution in this case.

 

Edit;

2 minutes ago, Zacherl said:

Isn't the optimizer smart enough to remove empty function calls?

Well tested it, and ... ofc it does not eliminate calls to empty functions  Generates a `CALL` that points to a single `RET` instruction instead. This should not happen in 2018.

Edited November 5, 2018 by Zacherl

[dummzeuch 1495]

1 hour ago, Zacherl said:

Isn't the optimizer smart enough to remove empty function calls? Well ... I know ... it's Delphi ... and Delphi is not really known for perfectly optimized code, but detecting empty functions is a really easy task. Using `IFDEF`s inside the logging function itself would be a better solution in this case.

 

Edit;

Well tested it, and ... ofc it does not eliminate calls to empty functions  Generates a `CALL` that points to a single `RET` instruction instead. This should not happen in 2018.

Have you tried to declare the function inline ?

[Georgge Bakh 29]

2 hours ago, dummzeuch said:

Have you tried to declare the function inline ?

This should not happen with not inline functions too.

[Kryvich 165]

The best way to fix a bug is to identify it as early as possible. I use asserts to validate the input parameters of subroutines, to verify the result of a function, and sometimes inside a subroutine if needed. Asserts always enabled during development, at alpha and beta testing stages. After release, they can be disabled if they noticeably affect the speed of the application.

[Zacherl 3]

14 hours ago, Kryvich said:

The best way to fix a bug is to identify it as early as possible. I use asserts to validate the input parameters of subroutines, to verify the result of a function, and sometimes inside a subroutine if needed. Asserts always enabled during development, at alpha and beta testing stages. After release, they can be disabled if they noticeably affect the speed of the application.

You are correct ofc, but assertions are only used to detect programming errors (should be at least ^^) and allow for advanced tests like fuzzing, etc. They should in no case be used as a replacement for runtime exceptions. If a runtime exception occurs on a productive system, you need a real logging functionality included in your product to be able to reproduce the bug (independently of the assertions, which are always good to have 🙂 ).

 

There is madExcept and stuff like that which will provide you callstacks in case of a runtime exception, but sometimes event that is not sufficient (e.g. in cases where code fails silently without exception and so on).

Edited November 6, 2018 by Zacherl

[Kryvich 165]

@Zacherl If a runtime exception occurs it means that you forgot to put an assertion somewhere. :) 

OK madExcept is a great tool, as well as 100% test coverage is very desirable. I just want to say that exceptions are probably the easiest and least time-consuming way to deal with bugs.

 

Another point is the use of custom enumerated types instead of general types Integer, Byte, Char etc. We, Delphi programmers, love strong typing. (And do not love the Variant type :) ).

Edited November 6, 2018 by Kryvich

[FredS 138]

On 11/5/2018 at 9:15 AM, dummzeuch said:

Have you tried to declare the function inline ?

 

I just tried that and it failed in a complex unit. When I move that out into a simple demo it works with INLINE but otherwise fails.

 

So now I have a MAP file showing me that all these methods are in the EXE even though they have been turned INLINE, while the simplistic demo works.

 

I have used the INC file which is used in the complex unit in the simple one and still all works.

So at best we can say this works only sometimes.. surely a reason for bloated EXEs..

 

[Clément 148]

Hi,

Why can't you write your log in levels. For example:
 MyLog.Info('Entering method X');

Mylog.Debug(1, 'Connecting to database');

MyLog.Debug(2, 'Connected to database = '+FDatabase.ConnectionString );

 

And the constructor

Mylog := TMyLog.Create( 0 ); // No Debug information

Mylog := TMyLog.Create( 1 ); // Only Debug 1

Mylog := TMyLog.Create( 2 ); // Debug up to level 2.

 

This way you can activate debug using a INI file.

[Settings]

Debuglevel = 0; // Or 1 or 2

 

HTH,

Clément

 

[Nathan Wild 3]

Another vote for CodeSite.  I've been using a simple collection of functions that wrap it's behavior and it is an excellent, maybe even essential, tool for client-side debugging!

[Berocoder 13]

Look at https://stackoverflow.com/questions/4652958/is-there-a-way-to-log-every-gui-event-in-delphi. It try to intercept all events. Advantage is that you need much less modifications of your code. Disadvantage is that not all your methods is logged.

[Mike Torrettinni 198]

Thanks, will look into that.

[ConstantGardener 31]

Look at http://blog.barrkel.com/2010/09/virtual-method-interception.html too.