candlepin/candlepin — pull request #402 by dgoodwin (2013-10-07 19:13:59+00:00)
Title: Logging Improvements

A number of changes in this branch:

Now logging to /var/log/candlepin, candlepin.log is normal logging, error.log is WARN and ERROR messages, access.log is self-explanatory and requires running the tomcat config setup script, and audit.log is a summary of events sent out as before. logrotate config is included in RPM for all of these.

Log messages now include a unique request UUID, or the unique job ID (same as you would see in cp_jobs) if running in a pinsetter task.

When possible, an org key will be logged, but only after we progress past the security code and the @Verify annotation was used, so this will not always be present.

The request/response logger has been changed such that we can get a short one line request summary and response summary including time taken for the request even if we're logging at INFO level. The larger and more memory intensive logging of headers and request/response body is still only enabled if debug logging is on.

An example of what an autobind looks like now in the logs:

Oct 07 16:05:49 [req:cac733ac-14c2-4774-90df-d101dcb6109e] [org:admin] INFO org.candlepin.servlet.filter.logging.LoggingFilter - Request: POST https://lenovo.local.rm
-rf.ca:8443/candlepin/consumers/c60b86f9-27b0-4c7e-9655-b0f2fedf5038/entitlements
Oct 07 16:05:50 [req:cac733ac-14c2-4774-90df-d101dcb6109e] [org:admin] INFO org.candlepin.controller.CandlepinPoolManager - Granted entitlement: 4028819841944f4c0141944fa82d0024 from pool: 4028819841932b6c0141932be5f306d2
Oct 07 16:05:51 [req:cac733ac-14c2-4774-90df-d101dcb6109e] [org:admin] INFO org.candlepin.controller.CandlepinPoolManager - Granted entitlement: 4028819841944f4c0141944faa600039 from pool: 4028819841932b6c0141932bec600904
Oct 07 16:05:51 [req:cac733ac-14c2-4774-90df-d101dcb6109e] [org:admin] INFO org.candlepin.servlet.filter.logging.LoggingFilter - Response: status: 200, content-type: application/json, time: 2433ms

The request UUID can be used to grep for all log statements for a specific request which is particularly useful when requests are arriving in parallel. When errors are reported in spec tests we can hopefully find the trace in error.log, grab the request UUID, and use this to grep the candlepin.log. This will hopefully be possible in production as well.

The use of loglevel INFO has been audited a bit for most common operations. The goal is to get this enabled in larger deployments so we need to be careful with how it's used going forward.