Edgewall Software
Modify

Opened 9 years ago

Last modified 6 years ago

#10413 new enhancement

[PATCH] Descriptive component names in trac.log

Reported by: anatoly techtonik <techtonik@…> Owned by:
Priority: normal Milestone: next-major-releases
Component: general Version:
Severity: normal Keywords: patch, logging
Cc: Ryan J Ollos, osimons, ethan.jucovy@… Branch:
Release Notes:
API Changes:
Internal Changes:

Description

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)

Attachments (2)

improve_trac_logging.diff (3.6 KB ) - added by anatoly techtonik <techtonik@…> 9 years ago.
improve_trac_logging.2.diff (3.6 KB ) - added by anatoly techtonik <techtonik@…> 9 years ago.
with undocumented logging.warn() alias

Download all attachments as: .zip

Change History (26)

comment:1 by Ryan J Ollos <ryano@…>, 9 years ago

Cc: ryano@… added

comment:2 by Remy Blank, 9 years ago

Milestone: next-major-0.1X

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.

comment:3 by anatoly techtonik <techtonik@…>, 9 years ago

Keywords: patch added
Milestone: next-major-0.1X0.12.3
Summary: Non-descriptive component names in trac.log[PATCH] Descriptive component names in trac.log

by anatoly techtonik <techtonik@…>, 9 years ago

Attachment: improve_trac_logging.diff added

comment:4 by anatoly techtonik <techtonik@…>, 9 years ago

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? =)

comment:5 by anatoly techtonik <techtonik@…>, 9 years ago

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']

by anatoly techtonik <techtonik@…>, 9 years ago

Attachment: improve_trac_logging.2.diff added

with undocumented logging.warn() alias

comment:6 by Remy Blank, 9 years ago

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.

comment:7 by Remy Blank, 9 years ago

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.

comment:8 by silk, 9 years ago

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

comment:9 by anatoly techtonik <techtonik@…>, 9 years ago

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.

in reply to:  9 ; comment:10 by Remy Blank, 9 years ago

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

in reply to:  10 ; comment:11 by osimons, 9 years ago

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…??

comment:12 by osimons, 9 years ago

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.

comment:13 by osimons, 9 years ago

Cc: osimons added

in reply to:  11 comment:14 by anatoly techtonik <techtonik@…>, 9 years ago

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

comment:15 by Christian Boos, 9 years ago

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.

in reply to:  12 comment:16 by anatoly techtonik <techtonik@…>, 9 years ago

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.

in reply to:  15 comment:17 by anatoly techtonik <techtonik@…>, 9 years ago

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.

in reply to:  11 comment:18 by Remy Blank, 9 years ago

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.

comment:19 by Remy Blank, 9 years ago

Milestone: 0.12.30.13
Type: defectenhancement

(BTW, this is an enhancement.)

comment:20 by Remy Blank, 8 years ago

Milestone: 1.01.0-triage

Preparing for 1.0.

comment:21 by Christian Boos, 8 years ago

Milestone: next-stable-1.0.xnext-dev-1.1.x

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)

comment:22 by ethan.jucovy@…, 7 years ago

Cc: ethan.jucovy@… added
Keywords: logging added

comment:23 by Ryan J Ollos, 7 years ago

Cc: Ryan J Ollos added; ryano@… removed

comment:24 by Ryan J Ollos, 6 years ago

Milestone: next-dev-1.1.xnext-major-releases

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.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as new The ticket will remain with no owner.
The ticket will be disowned.
as The resolution will be set. Next status will be 'closed'.
The owner will be changed from (none) to anonymous. Next status will be 'assigned'.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.