779189 - Make crontabber logging useful

Status: RESOLVED WONTFIX

(Socorro :: Backend, task)

Description

[Laura Thomson :laura]

The logging for crontabber does not contain timestamps which makes it completely useless.  Please bring crontabber logging in line with other Socorro backend apps by adding this, the app name, and the severity level.

Comment 1

[Peter Bengtsson [:peterbe]]

Hmm... We're using the generic_app framework which standardises the logging. 
You can see the logging configuration here:
https://github.com/mozilla/socorro/blob/master/socorro/app/generic_app.py#L37
and the options for the python logging is managed here:
https://github.com/mozilla/socorro/blob/master/config/crontabber.ini#L41 
in fact, it's outside our control what options IT set. Granted, we advice them what to set. 

I'm genuinely surprised timestamps aren't included. I'll talk to Lars about that.
In fact, here's some sample lines of the logging and it contains a datetime for each line. 
https://bugzilla.mozilla.org/show_bug.cgi?id=777670#c9

What it doesn't do which we could improve is to somehow change the logging name so instead of being crontabber it's temporarily the app that crontabber executes. 
I'm not sure if this is possible at all.

Comment 2

[K Lars Lohn [:lars] [:klohn]]

the log files for the cron jobs appear to be captures of the stderr stream (crontabber.log). The lines that do not have timestamps are output by the Python interpreter to stderr.  They are not, technically, logging lines. If you look further up in the file, you'll see actual logging lines do begin with a timestamp and severity.  

When we started to use syslog, I bifurcated the Socorro logging mechanism so that it would log to two places: syslog and stderr.  There are config parameters in both the old system and the new ini system to control the format of the log lines.  For crontabber, that uses the new system, see the ini settings in logging.ini: 'syslog_line_format_string' and 'stderr_line_format_string'.  

I rarely look at the captured stderr log files.  Instead I generally grep for the appname in the syslog.  By default the syslog logging has more detail than the stderr log.  However, 'stderr_line_format_string' can have exactly the same format as 'syslog_line_format_string' just by editing logging.ini or doing a commandline or environment override.

As for changing the string dynamically during execution of different components within crontabber, that could be theoretically accomplished in two ways:

1) add another var {component_name} to the logging format string, then on every point where logging happens within the components of crontabber, add a dict with the value { 'component_name': 'some-component'}.

2) [untested/theoretical] get the logging object, from it fetch the appropriate Formatter object and change it to include a constant string containing the component name.

Comment 3

[Peter Bengtsson [:peterbe]]

:lars, 
regarding (dynamically) changing the app name I think I over-reached. I think Laura is referring to the simple fact that the logging doesn't even say it's crontabber!
Clearly, for the lines going to crontabber.log it's obviously all crontabber by context. 

Do you suggest that we morph this bug to an IT but to make stderr_line_format_string == syslog_line_format_string in /etc/socorro/logging.ini?

Comment 4

[Peter Bengtsson [:peterbe]]

:lars to be specific, if we want `stderr_line_format_string == syslog_line_format_string` which *one* should change?

Comment 5

[K Lars Lohn [:lars] [:klohn]]

logging to stderr doesn't say the appname precisely because that information can be gleaned by context.  I wanted to keep the log lines to stderr shorter so they wouldn't wrap in a shell session - appname was an obvious thing to omit.  I prefer this shorter form to stderr.

the syslog format includes more information like appname because the log lines are interleaved with everything else that's logging to the same service.  It's easy to use grep to extract just the interesting lines.

If it is necessary to unify the formats for syslog and stderr, then the stderr format should be replaced with the syslog format.  From my perspective, I think this change is neither necessary nor desirable.  However, I will defer to the opinions of others.

Comment 6

[K Lars Lohn [:lars] [:klohn]]

this bug stems from a misunderstanding about what the crontabber.log file actually is.  That file contains the all the stderr output from the app.  It happens to include the logging along with unlogged data written to stderr by the python interpreter.  This non-logged information is crucial for debugging unanticipated problems that miss being logged.  Because stderr is an unformatted stream, there will be entries without timestamps, we have no control over that.  All the entries from Socorro's logging subsystem correctly in that file are properly timestamped along with severity.

If you want to see only output from logging with timestamp, severity, appname, pid, etc, go to the syslog and grep for the appname of interest.