Jump to content
Mike Torrettinni

Detailed logging (for debugging)

Recommended Posts

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!

Share this post


Link to post

@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!

 

Share this post


Link to post

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 by edwinyzh

Share this post


Link to post
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? :classic_biggrin:

  • Haha 1

Share this post


Link to post

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.

 

 

Share this post


Link to post

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 by Dany Marmur

Share this post


Link to post

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).

Share this post


Link to post

@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.

Share this post


Link to post
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 by dummzeuch
  • Like 2
  • Thanks 1

Share this post


Link to post

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 :classic_dry: Generates a `CALL` that points to a single `RET` instruction instead. This should not happen in 2018.

Edited by Zacherl

Share this post


Link to post
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 :classic_dry: 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 ?

Share this post


Link to post
2 hours ago, dummzeuch said:

Have you tried to declare the function inline ?

This should not happen with not inline functions too.:classic_cool:

Share this post


Link to post

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.

Share this post


Link to post
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 by Zacherl

Share this post


Link to post

@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 by Kryvich

Share this post


Link to post
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..

 

Share this post


Link to post

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

 

  • Like 2

Share this post


Link to post

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!

Share this post


Link to post

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now

×