Logging

Overview

A few different kinds of logging are used to serve different purposes:

• Prints to stdout by test jobs. Used to provide progress indication with lots of semantics. Intended for post-mortem analysis by humans. Not intended for automated analysis.
• Prints to stderr by AVE daemons. Used to provide debugging information. Intended for post-mortem analysis by humans.
• Consolidation of log files and other test job artifacts. Used to store logs in a way that can be tied to a single run of a test job. Intended for post-mortem analysis by humans.
• Automatic emission of structured entries to a centralized store. Used to log resource utilization and system malfunctions and unexpected events in AVE itself. Intended for automated business intelligence analysis.
• Explicit emission of test results from test jobs. Used to store the pass/fail status of individual test cases. Intended for manual as well as automated analysis.
• Explicit emission of domain specific measurements from test jobs. Used to store e.g. performance data collected by test jobs. Intended for manual as well as automated analysis.

stdout Prints by Test Jobs

Test jobs are executed by vcsjob, which is able to intercept all prints to stdout and stderr. A scheduler may redirect this output to a file. See vcsjob.execute_job(..., log_path=None, ...).

The job itself has access to this file so that it may upload its own log to Flocker: vcsjob.get_log_path() returns the path that was selected by the scheduler, or raises an exception if not set.

stderr Prints by Daemons

Daemons are initialized with writable file handles that replace stdout and stderr (the handles may point to the same file). Consequently all prints by the daemon, the Python interpreter and functions called by the daemon will end up in the log file(s).

Left to do:

• Log files are currently created under /var/tmp and should move to .ave/logs in AVE’s home directory.
• Implement log file rotation or garbage collection against a maximum disk usage.

Consolidation of Job Logs

API’s on the Workspace class may be used to push files and log entries to Flocker. Test jobs should use this to store artifacts that may be needed in post-mortem analysis.

Flocker itself implements parallel uploads from multiple clients, configurable garbage collection and log rotation. The logs will eventually be purged as they are not considered business critical in the long term. It is enough if they are available for a “reasonable” amount of time after the test job has finished.

Structured Logging to Panotti

Panotti is a mythical creature of antiquity with very large ears. Presumably it has excellent hearing and will faithfully record everything it hears.

Schedulers may use vcsjob to set a globally unique ID on job executions: vcsjob.execute_job(..., guid=None, ...). If set, this GUID is picked up by the RPC marshalling mechanism (see ave.network.control.RemoteControl) and used to created JSON compatible log entries of all remote procedure calls that generate an exception.

The GUID may also be read by the job, using vcsjob.get_guid().

The function ave.panotti.shout() is used to post a message to CouchDB. It will do nothing if no GUID is provided or the file .ave/config/panotti.json does not contain the configuration data needed to connect to the database.

Left to do:

• Log daemon stderr prints to Panotti on hosts that enable this behavior.
• Trace all calls from test jobs to AVE on hosts that enable this behavior.

Test Results

Test results that fit the pass/fail/error model may be uploaded to deciBel with Workspace.report() if the result was generated with Handset.run_junit() or Handset.run_gtest()``. In other cases, the result may be built using calls to ave.report.decibel function and then posted directly to deciBel.

Left to do:

• Document the ave.report.decibel module.

Performance Results

Test results that fit a tabulated data model may be uploaded to MySQL.

Left to do:

• Document the oursql module or refer the reader to existing documentation on the Internet.

Scheduler Work Performed on a Job’s Behalf

Schedulers are expected to use GUID’s (as outlined above) to connect the logs of test jobs with the logs of preparatory work performed by the scheduler. E.g. if a scheduler has flashed a handset before the job allocates it, then the log from the flashing should be possible to find through the log for the test job.