Page MenuHomePhabricator

Improve log message parametrization for Command
Open, Needs TriagePublic

Description

We rely on grouping by the "templated" form of the log message to identify problems. MediaWiki\Shell\Command currently logs messages like Possibly missing executable file: {command} which is not all that helpful. Not parametrizing at all would be similarly unhelpful as it would prevent grouping for commands which include a file name or similar highly variable part. Command should support some kind of middle ground.

Event Timeline

A couple options come to mind:

  • Add the caller method to the log message. This is reasonably unique but not very user-friendly.
  • Add the first segment of the command (usually the executable name) to the log message. Slightly more informative (although not that much for complex commands with pipes, sudo etc); behaves poorly when the whole command is passed as a single unescaped segment.
  • Leave it to callers to call $command->logStderr( false ) and log manually. Most callers would probably forget to do this.
  • Come up with some kind of templating system: Shell::commandTemplate( 'svn diff -r{rev1}:{rev2} --non-interactive --trust-server-cert http://svn.wikimedia.org/svnroot/mediawiki' )->execute( [ 'rev1' => 12345, 'rev2' => 23456 ] ) (this has escaping problems but that can be fixed with slightly more complex syntax). Results in the nicest log lines (and parameters could be added as such so it's easy to filter on them) but might be overkill; and maybe this wouldn't be used most of the time either?

Try $this->command as a more readable alternative to $cmd?

Yes, the wrapper script should not be part of the log message, but readability is not the main issue here. If you look at [[https://logstash.wikimedia.org/goto/a56bbdb91e72af3bc29c5dba8eda5da0|the exec channel]], what you see now is

exec.png (142×1 px, 15 KB)
which is not super informative; and manually examining a thousand entries to understand where most errors come from is not a fun way to interact with logstash.

For example one recent error message is from /usr/bin/pdfinfo -enc UTF-8 -l 9999999 -meta /tmp/pHKlcB. Right now that gets grouped like Error running {command}: {error}; with the first proposal it would be something like Error running {command} from PdfImage->retrieveMetaData(): {error}, with the second Error running /usr/bin/pdfinfo: {error}, with the last Error running '/usr/bin/pdfinfo -enc UTF-8 -l 9999999 -meta {tempfile}': {error} (but that would require a change in how Command is constructed). All much better for diagnosing problems.