Skip to main content

Notice: this Wiki will be going read only early in 2024 and edits will no longer be possible. Please see: https://gitlab.eclipse.org/eclipsefdn/helpdesk/-/wikis/Wiki-shutdown-plan for the plan.

Jump to: navigation, search

Difference between revisions of "SMILA/Specifications/UsefulLogMessages"

(Log in future)
(Log in future)
Line 138: Line 138:
  
 
( See [http://logging.apache.org/log4j/1.2/apidocs/index.html log4j javadocs]:  
 
( See [http://logging.apache.org/log4j/1.2/apidocs/index.html log4j javadocs]:  
The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
+
The '''DEBUG''' Level designates fine-grained informational events that are most useful to debug an application.
The INFO level designates informational messages that highlight the progress of the application at coarse-grained level. )
+
The '''INFO''' level designates informational messages that highlight the progress of the application at coarse-grained level. )
  
 
Really, it would be desirable to receive "easier" information in INFO.  
 
Really, it would be desirable to receive "easier" information in INFO.  

Revision as of 10:40, 1 October 2008

Logging (e.g., in a.log file or in a SQL data bank) is a big help during the development time as well as later to the errors search with the customer. In Smila is used a Apache log4j. Apache log4j is a Java-based logging utility and one of several Java Logging Frameworks. It is used primarily as a debugging tool. Unfortunately at the moment SMILA logging does not use all possibilities.


Current Problems

  • To much Information in the log

File EILF.log where registers a log information for Smila contains too much not the helpful information. Most of all messages arrives from debug. For example, at indexation of file EILF logging file has 33 000 lines, the majority from which a extracted context. To search for the necessary information not so conveniently. For example, at indexation of file EILF (for xml files ) EILF.log has 33 000 lines, the majority from which a extracted context. Today it is easy to get lost and not to find the necessary records in a pack of messages. The surplus information litters the log.

  • Messages do not correspond to the level

From Short introduction to log4j: INFO - for the "high level" information; DEBUG - only for the software developer interesting messages. Now in INFO is written to much information for developer.

For example this information is written down in INFO. Isn't that so here approaches DEBUG more?

- AddPipeline/extensionActivity-activity-line-36: found service MimeTypeIdentifier, processing request -> request

- AddPipeline/extensionActivity-activity-line-50: found service LuceneIndexService, processing request -> request

- AddPipeline/extensionActivity-activity-line-43: no pipelet configuration found.

- AddPipeline/extensionActivity-activity-line-43: found pipelet org.eclipse.eilf.processing.pipelets.aperture.AperturePipelet, processing request -> request

- DeletePipeline/extensionActivity-activity-line-36: found service LuceneIndexService, processing request -> request

- Initialization of BPEL engine successful


  • Insufficiently informative messages of info level

This point is connected with the previous.

Discussion

Sebastian Voigt: My Suggestion is to change the default logging settings to minimize logging information. (Question is more, what do we have to see (ODE logging messages is an example). We have to see errors messages thrown by the components, but we don't want to see every message from ode etc...

Jürgen Schumacher: From a quick look at a quite old EILF.log on my machine, I think it should be sufficient to switch the log level for org.eclipse.eilf from DEBUG to INFO. Or am I getting anything wrong?

Thomas Menzel: My opinion on this:

1. loggin is there to help you, too much just doesn't.

2. have INFO level to show where the process/program is roughfly. if u have loops that are executed often or have many iterations than I think it is a good choice to just log every N iterations. the overhead for this is minimal and the output a welcome indicator for anybody concerned about the progress and speed of a process/loop.

3. DEBUG: give verbose info that is needed for debugging purposes. that inlcudes most important the state of the process and involved objects

Allan Kaufmann: I think it could be helpful if users received errors and if log error gives important information but not too much. Currently the EILF.log shows much, so that exceptions and error like this could be overlooked.

Sofya Zhbankova: and that if to separate a logging information in the different files: debugging messages to one file (EILF.debug) and other messages to another file (EILF.log). Most of all messages arrives from debug . It seems to me that it is possible few to "unload" debug. For example, whether it is necessary to deduce in the file a extracted content.

For example, at indexation of file EILF (for xml files ) EILF.log has 33 000 lines, the majority from which a extracted context. To search for the necessary information not so conveniently.

Allan Kaufmann: In my opinion we should keep EILF.log as one logfile that hold all logs of the different levels in order of the runtime, because while searching for information it´s difficult to look and sort with different logfiles. But maybe it could be helpful to received EILF.debug or EILF.error as additional file? Sample: Our Logger is set to DEBUG, so EILF.log received all Logs until DEBUG-level. But if a developer just want information about errors, he could have a look to EILF.error. Disadvantage: More performance because information could log more than one time. If we choose the idea to separate the log in different files without a mainfile like EILF.log or otherwise, it´s necessary to design the log clearly, so that information could be found better and messages are more helpfully.

Ivan Churkin: As you already mentioned, the order of the runtime will be lost, so system have to support complete log file. Additional log files may be added but I'm not sure that it's info will be enough. bwt, for example, GREP may be used for investigating/filtering log file.

Daniel Stucky: I agree with Allan to keep one log file. I think we should set up some guidelines for developers when and what to log on which level to provide meaningful log entries.

Then it's only a matter of configuration - we should provide a default log4j configuration for development (e.g. log level DEBUG) - we should provide a default log4j configuration for the application (e.g. log level INFO)

Everybody is free to change log4j settings in his/her development or application environment if those defaults don't fit.

Sofya Zhbankova: I agree with Daniel that "..everybody is free to change log4j settings..". For me to search in separate files it is much easier. Today it is easy to get lost and not to find the necessary records in a pack of messages. The surplus information litters the log. Can be all the technical information to write down in debug and in info - only final and short messages:

- Initializing Crawler...

- some documents are processed and stored into the index

Daniel Stucky: I added a section "Logging guidelines" to our Development_Guidelines: [[1]]. Feel free to comment or improve.

Sofya Zhbankova: From general: INFO - for the "high level" information; DEBUG - only for the software developer interesting messages. I think that for Smila reasonably too.

Thomas Menzel: I have some remark to:

  • log exceptions before throwing new exceptions, e.g.

... if( paramXY == null ) {

   if (_log.isErrorEnabled()) {
       _log.error("paramXY is not set");
   }
   throw new NullPointerException("paramXY is not set"); } ////


I advise against this as it only causes the same message to be repeated at least twice, namely when the exception is created and then when the exception is logged itself. IMO it is sufficient to have a verbose error msg and this then is reported along with the stack trace when the exception is logged. if the exception is handled then this message is even confusing b/c u have ERROR log entry but wonder: what happened then? if u deem the condition so extraordinary and dangerous we could log it as warning, but since we don’t log the eception here it should not be level ERROR.

even worse than this is sometimes the habit to log an exception before (re)throwing or wrapping it, which I have seen as often (in general, not this project in particular). this then has the effect that u have the same exception logged several times which makes the log very verbose and confusing. as u think u have lot of problems/exception when it fact it is only that one case.

of course this only applies when u remain within our own system bounds. if u write a libray that is called from other code then it is wise to log the exception at ur system boundery, i.e. the method that was called by the client, that might not adhere to sound loging standards. again, there are also pitfalls with this convention, e.g. in case of an overloaded API method where u have a simple version that delegates to a more verbose other API method that also could be called from a client.

Log in future

How to improve a log for Smila and what will be a log in future?

The basic ideas stated by developers ware:

  • to change the default logging settings

The Smila is configured through a property file - log4j.properties. Configuring log4j typically involves assigning Level, defining Appender, and specifying Layout objects.

Possible configuration for Smila:

Loggin.jpg

  • to reduce messages from something sources

The configuration presented above allows to reduce essentially number of log messages.

  • to switch the log level for messages

The point especially concerns INFO and DEBUG levels. I think we should adhere to the general rules of use of levels:

INFO - Interesting runtime events (startup/shutdown). Expect these to be immediately visible on a console, so be conservative and keep to a minimum.

DEBUG - detailed information on the flow through the system. Expect these to be written to developers only.

( See log4j javadocs: The DEBUG Level designates fine-grained informational events that are most useful to debug an application. The INFO level designates informational messages that highlight the progress of the application at coarse-grained level. )

Really, it would be desirable to receive "easier" information in INFO. Like as:

- Smila started successfully

- indexing file system AAA starting

- folder for (xml, txt, html)

- file A indexing successfully - updated

- file B indexing successfully - touched

- file C indexing successfully - deleted

... - Total indexing 421 files

- touched 400 files

- updated 10 files

- deleted 11 files

- indexing time 8909 ms


  • to write down a guidelines for developers

One of results of the discussion is occurrence a section "Logging guidelines".

  • to output a logging information in the different files

Though this idea has not found support in developers, the debugging data recording in a separate file can be accepted also.

Back to the top