[PATCH] Descriptive component names in trac.log

[anatoly techtonik <techtonik@…>]

trac.log doesn't contain full component names and as a result it is hard to filter information relevant to plugins.

Consider the following excerpt:

2011-10-15 01:24:47,716 Trac[main] DEBUG: Dispatching <Request "POST '/login'">
2011-10-15 01:24:47,744 Trac[svn_fs] DEBUG: Subversion bindings imported
2011-10-15 01:24:47,747 Trac[api] INFO: Synchronized '' repository in 0.03 seconds
2011-10-15 01:24:47,747 Trac[web_ui] DEBUG: authenticate() method called
2011-10-15 01:24:47,747 Trac[session] DEBUG: Retrieving session for ID ''
2011-10-15 01:24:47,748 Trac[web_ui] DEBUG: user_locked: False
2011-10-15 01:24:47,753 Trac[chrome] DEBUG: Prepare chrome data for request
2011-10-15 01:24:47,755 Trac[web_ui] DEBUG: authenticate() method called

Here:

• Trac[main] is probably trac.core.main
• Trac[web_ui] is acct_mgr.web_ui
• Trac[session] is ???

I'd propose to change that default format to replace Trac[] with full module name (i.e. name)

[Remy Blank]

That's a good idea, and probably not so easy to implement, as the expansion must be done in the logging module at log time.

[anatoly techtonik <techtonik@…>]

Here is the patch. It modifies logging concept from being driven by single 'Trac' logger to hierarchy of loggers named after module and class names. This allows much greater flexibility when debugging Trac issues. For example, you can use logging.Filter('myplugin.Class') to filter out irrelevant messages from top level, or you can get logging.getLogger('myplugin.Class') specific to your class and assign handler to route all messages to some file.

How is that? =)

[anatoly techtonik <techtonik@…>]

New output format:

2011-10-20 11:20:30,478 [trac.web.main.RequestDispatcher] DEBUG: Dispatching <Request "POST '/login'">
2011-10-20 11:20:30,585 [trac.versioncontrol.svn_fs.SubversionConnector] DEBUG: Subversion bindings imported
2011-10-20 11:20:30,623 [trac.versioncontrol.api.RepositoryManager] INFO: Synchronized '' repository in 0.11 seconds
2011-10-20 11:20:30,645 [acct_mgr.web_ui.LoginModule] DEBUG: acct_mgr.web_ui.LoginModule user: None
2011-10-20 11:20:30,667 [acct_mgr.web_ui.LoginModule] DEBUG: acct_mgr.web_ui.LoginModule enduser: None
2011-10-20 11:20:30,686 [trac.web.session.Session] DEBUG: Retrieving session for ID 'b3e996a7ffcfb682c9376c85'
2011-10-20 11:20:30,704 [acct_mgr.web_ui.LoginModule] DEBUG: user_locked: False
2011-10-20 11:20:30,770 [trac.web.chrome.Chrome] DEBUG: Prepare chrome data for request
2011-10-20 11:20:30,802 [acct_mgr.web_ui.LoginModule] DEBUG: acct_mgr.web_ui.LoginModule user: None
2011-10-20 11:20:30,825 [acct_mgr.web_ui.LoginModule] DEBUG: acct_mgr.web_ui.LoginModule enduser: None
2011-10-20 11:20:30,854 [trac.ticket.api.TicketSystem] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']

[anatoly techtonik <techtonik@…>]

with undocumented logging.warn() alias

[Remy Blank]

Interesting. I have the feeling that your chosen approach may increase the overhead of logging unnecessarily:

• It adds one function call overhead.
• It performs stack frame inspection on every log statement.
• It gets a logger from logging.getLogger() on every log statement. Even though the instances are cached, there's some heavy locking in there.

Fortunately, it's probably possible to implement this with no additional overhead. Every component has a reference to a logger as its .log attribute. Currently, all components share the same logger instance. You could assign a different logger (retrieved through logging.getLogger()) to each component at creation time. This would even avoid having to use stack inspection, as you would have a reference to the component at this point.

[Remy Blank]

OT but related: I have been browsing the standard logging module, and boy is this heavy machinery! I wouldn't be surprised if we could gain a significant performance improvement by implementing a more lightweight logging infrastructure.

[silk]

techtonik: have you thought about making the component section [] fixed width? it would greatly increase readability I think

[anatoly techtonik <techtonik@…>]

silk: I thought only about releasing this patch ASAP before I run out of time. It surely needs more care. As for fixed width, I don't know what len should it be, because names include class names and can be pretty lengthy.

rblank - good idea about components, but there are quite many places where logging is called with 'env.log' or even 'self.env.log'. Although it is interesting to measure actual performance, in my environment performance is not an issue.

[Remy Blank]

Replying to anatoly techtonik <techtonik@…>:

rblank - good idea about components, but there are quite many places where logging is called with 'env.log' or even 'self.env.log'.

There shouldn't be too many, we changed most of them to use the component's own .log a while ago. Mostly they should be model classes (and in general, non-Component classes).

[osimons]

Replying to rblank:

There shouldn't be too many, we changed most of them to use the component's own .log a while ago. Mostly they should be model classes (and in general, non-Component classes).

Right… And ~800 plugins at Trac-Hacks have no doubt already aligned with the the current Trac practice…??

[osimons]

BTW, remember that standard logging contains facilities for including both the full pathname and linenumer which is usually an even better alternative as it also verifies what version of the code actually loads and where it is located. Particularly plugin issues are so often confused by wrong versions - plugins uploaded at different versions in different projects, old versions still loading and so on.

Here is a more elaborate logging example for shared project logging - a variation of what I currently use:

[logging]
log_format = [$(project)s $(asctime)s p$(process)d:t$(thread)d] $(pathname)s:$(lineno)d $(levelname)s: $(message)s

I've included Process and Thread as it makes it easier to figure out what messages belong to which request. With parallel requests, the log is usually rather jumbled and hard to parse unless you know the internals of request handling order.

I'd rather prefer to just update the default log_format to contain a bit more useful information, and perhaps update TracLogging (or some debug wiki page) to include an even more elaborate log_format example.

[anatoly techtonik <techtonik@…>]

Replying to osimons:

Replying to rblank:

There shouldn't be too many, we changed most of them to use the component's own .log a while ago. Mostly they should be model classes (and in general, non-Component classes).

Right… And ~800 plugins at Trac-Hacks have no doubt already aligned with the the current Trac practice…??

I also though about this point. How about this plan then:

• leave patch above for env.log and static calls
• the first time the env.log is called - log a warning message that component log() function should be used as it is more effective in getting component names
• implement more effective logging aspect injection in component loader

[Christian Boos]

I'm not even sure a change like this is really needed… if you want a very precise description of the location of the log statement, you can already add something like:

... $(funcName)s() in $(pathname)s:$(lineno)s ...

in you logger_format.

And if you want filtering, filter your log file accordingly.

[anatoly techtonik <techtonik@…>]

Replying to osimons:

BTW, remember that standard logging contains facilities for including both the full pathname and linenumer which is usually an even better alternative as it also verifies what version of the code actually loads and where it is located.

Doesn't trac.loader already reports that in log in DEBUG mode? With filenames info log will become pretty unreadable without some filtering tools.

I'd rather prefer to just update the default log_format to contain a bit more useful information, and perhaps update TracLogging (or some debug wiki page) to include an even more elaborate log_format example.

Perhaps this ​http://docs.python.org/library/logging.config.html#module-logging.config can be useful for you as well. It is possible to provide several logging config files for users to troubleshoot particular problems.

[anatoly techtonik <techtonik@…>]

Replying to cboos:

I'm not even sure a change like this is really needed…

…

And if you want filtering, filter your log file accordingly.

Not all Trac users are Linux guru to be able to filter logs from console. I also want to be able to setup several log files for different aspects of Trac like separate log for trac.web.auth and friends with very-very detailed DEBUG coverage of the process. If I add these DEBUG statement here and somebody add them there - the log can quickly grow out of control in a few weeks before you get a chance to filter it.

Needless to say that write operations for info you don't need require your time or the time of your SSD drive.

[Remy Blank]

Replying to osimons:

Right… And ~800 plugins at Trac-Hacks have no doubt already aligned with the the current Trac practice…??

Of course not, I never said that. A large proportion of Trac plugins seems to be one-shot implementations that are never touched before they break. I have long since stopped hoping that plugin authors would follow Trac development. Actually, we should break stuff more often (like Mercurial does), then plugins would either be maintained or stop working.

</rant>

Using the filename expansion does indeed give all the necessary information, but it's a shame that all entries will end up looking like:

2011-10-19 12:34:56.789 Trac[/usr/lib/python2.7/site-packages/...] ...

But TBH I don't really care if we leave things as they are today.

[Remy Blank]

(BTW, this is an enhancement.)

[Remy Blank]

Preparing for 1.0.

[Christian Boos]

Wondering if we couldn't take another approach…

(as a reminder for self: per component log methods overriders, + per components debug levels in the config)

[Ryan J Ollos]

Retargetting tickets to narrow focus for milestone:1.2. Please move the ticket back to milestone:next-dev-1.1.x if you intend to resolve it by milestone:1.2.