separator in trac.log for reload/restart

[anatoly techtonik <techtonik@…>]

It will help a lot to see a separator in trac.log that is written on restart/reload (when Trac reloads all plugins), because it is rather hard to spot session starts, especially in DEBUG mode.

Something like:

2009-09-24 07:02:41,080 Trac[perm] DEBUG: No policy allowed anonymous performing TICKET_ADMIN on None
2009-09-24 07:02:41,177 Trac[perm] DEBUG: No policy allowed anonymous performing EMAIL_VIEW on None
2009-09-24 07:11:19,017 Trac[env] INFO: Reloading environment due to configuration change
2009-09-24 07:11:19,041 --------------------------------------[ Start ]-------
2009-09-24 07:11:19,041 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect

[Christian Boos]

Good idea. I wonder if it makes sense to use "critical" level here, even if it's not an error, it's something we'd like to see at any logging level.

[anatoly techtonik <techtonik@…>]

I hope it won't pollute logs in CGI mode.

[Christian Boos]

slightly different and simpler approach, shows a '*** environment shutdown *** line upon shutdown.

[Christian Boos]

Please have a look at t8691-separator-on-restart.diff​ (applies on 0.11-stable, r8764).

I think this amounts to the same and is a bit simpler than messing with the logger_factory internals like separator.diff​ did.

[Remy Blank]

I like the simpler approach as well. But won't we get several entries every time, one for each Apache/fcgi process? That might be a bit ugly.

[Christian Boos]

Well, we also get the full list of startup messages for each process, this request was about better identify that sequence. Note also that the processes won't necessarily restart all at the same time.

I think I'll change from environment shutdown to environment startup also.

[Christian Boos]

Display an -------- environment startup -------- line in the log, when the environment is created.

[anatoly <techtonik@…>]

My original patch is messing with logger factory for three reasons:

1. Display start separator as early as possible - before any logging starts, because as a plugin/trac developer I am not aware when environment is created (shame, eh?), but if the code is in logger factory - I am absolutely sure that if I catch any bugs - there is no relevant to it output that is located above this line

I originally came to this idea when tracking reload of my plugin in development. Where comes information related to these plugin reload - before or after environment startup?

2. I want to see separator in log as clearly as possible without obscure "Trac[xxx] INFO:" prefixes.

3. Weak attempt to make it optional (advanced log analyzers can separate batches by time/date/pid)

[Christian Boos]

Replying to anatoly <techtonik@…>:

1. Display start separator as early as possible

It is done as early as possible - doing it inside logger_factory or right after the logger_factory was called makes little difference.

because as a plugin/trac developer I am not aware when environment is created

Nothing can possibly happen in plugins without an Environment. The Environment sets up the logging, then deals with plugins.

2. I want to see separator in log as clearly as possible without obscure "Trac[xxx] INFO:" prefixes.

Well, the -------------------------- ... ----------------------- line should be easy to spot. Give it a try.

3. Weak attempt to make it optional (advanced log analyzers can separate batches by time/date/pid)

Alternatively, this can be seen as a good reason to always keep the obscure prefix ;-)

Anyway, as Remy was also not that enthusiastic about the original patch, I committed the simpler version.

Latest patch applied in [8795].

[anonymous]

Replying to cboos:

1. Display start separator as early as possible

It is done as early as possible - doing it inside logger_factory or right after the logger_factory was called makes little difference.

You have my blessings then. =)

[anatoly <techtonik@…>]

I means me in above.