Use structlog for relengapi logging

[djmitche]

Structured logging seems the way of the future, and structlog provides a nice, simple way to use it with Python's logging.

This could be useful for general logging in relengapi, but would be particularly useful for logging from celery tasks -- the structure can contain the task id, and processors can then correlate that to a badpenny task or whatever other identifier is required (so a fix for #129)

[djmitche]

structlog doesn't replace stdlib logging -- it just wraps it. So we would basically change logging.getLogger to structlog.get_logger and leave most stuff the same. We can add a bunch of processors for proper request or task context, timestamps, etc.

The one thing I think will be hard is to redirect logging from other libraries (Celery, SQLAlchemy) through structlog. We can probably just live with that -- their logs won't be in JSON, but they'll still show up in papertrail or mozdef or whatever.

[djmitche]

Good performance hints at https://structlog.readthedocs.org/en/stable/performance.html

[djmitche]

OK, I think this is ready for review. @amyrrich?

[djmitche]

Also, @Callek what is coveralls' problem.. coverage increased, yet it marks it as failed?

Buildbot's looking to switch to http://codecov.io/ since coveralls is basically unusable..

[Callek]

That's because we still have coveralls listed to fail for anything less than 98% coverage (you never bumped that with the merge), I'm marking it as passes-at-89% now...

As far as codecov.io I'm happy to expiriment with that here, but I don't want to decide to drop coveralls until I've played with it a bit

[djmitche]

@jbryner I'd like to send this to mozdef. Does it look OK? Sample output is

{"timestamp": "2015-06-17T14:34:08.100818Z", "logger": "relengapi.blueprints.slaveloan.bugzilla", "relengapi": true, "event": "No bugzilla user specified. (Set BUGZILLA_USER in config to fix)", "level": "warning"}
{"timestamp": "2015-06-17T14:34:08.100958Z", "logger": "relengapi.blueprints.slaveloan.bugzilla", "relengapi": true, "event": "No bugzilla password specified. (Set BUGZILLA_PASS in config to fix)", "level": "warning"}
{"relengapi": true, "level": "info", "timestamp": "2015-06-17T14:34:08.104276Z", "logger": "relengapi.app", "event": "registering blueprint tokenauth"}
{"relengapi": true, "level": "info", "timestamp": "2015-06-17T14:34:08.105875Z", "logger": "relengapi.app", "event": "registering blueprint tooltool"}

[djmitche]

I'm going to refactor this a bit to make it look like mozdef wants it to look (with most of the interesting stuff in "details").

[codecov-io]

Current coverage is 89.46%

Merging #220 into master will increase coverage by +0.29% as of f090bb9

Powered by Codecov

[djmitche]

@jeffbryner this now looks like

{
    "processid": 16208,
    "severity": "WARNING",
    "tags": [
        "relengapi"
    ],
    "timestamp": "2015-07-27T16:07:51.739134",
    "summary": "frobnication failed",
    "processname": "relengapi",
    "source": "relengapi.app",
    "details": {
        "frobnication_id": "12345",
        "permissions": [
            "frob",
            "blob"
        ],
        "user": "human:dustin@mozilla.com",
        "request_id": "fb6590d2-74eb-4e78-90a0-27f8ddcf57d4"
    }
}

(note: "summary" rather than "message" as you suggested in your email)

Does that seem about right?

I'll fix up the code coverage in a second.

[edit: formatted JSON]

[djmitche]

(coverage is fixed)

[djmitche]

(and as usual, the coveralls result is completely bogus)

[jeffbryner]

looks good to me

[djmitche]

Rebased and logging for bug 1137793 added. I'd like one more review of the final form here before I land this. @lundjordan do you mind?

[lundjordan]

assuming travis is happy with archiver and the expiry tests this time, wfm. more structure!