<div dir="ltr">Hi Python-Ideas ML,<div><br></div><div>To resume quickly the idea: I wish to add "extra" attribute to LogMessage, to facilitate structured logs generation.</div><div>For more details with use case and example, you can read message below.</div><div><br></div><div>Before to push the patch on <a href="http://bugs.python.org">bugs.python.org</a>, I'm interested in by your opinions: the patch seems to be too simple to be honest.</div><div><br></div><div>Regards.</div><div><div><div class="gmail_signature"><div dir="ltr"><div>--<br><div style="font-size:small"><div>Ludovic Gasc (GMLudo)</div></div><div style="font-size:small"><a href="http://www.gmludo.eu/" target="_blank">http://www.gmludo.eu/</a></div></div></div></div></div>
<br><div class="gmail_quote">---------- Forwarded message ----------<br>From: <b class="gmail_sendername">Guido van Rossum</b> <span dir="ltr"><<a href="mailto:guido@python.org">guido@python.org</a>></span><br>Date: 2015-05-24 23:44 GMT+02:00<br>Subject: Re: [Python-Dev] An yocto change proposal in logging module to simplify structured logs support<br>To: Ludovic Gasc <<a href="mailto:gmludo@gmail.com">gmludo@gmail.com</a>><br><br><br><div dir="ltr">Ehh, python-ideas?<br></div><div class="gmail_extra"><br><div class="gmail_quote"><div><div class="h5">On Sun, May 24, 2015 at 10:22 AM, Ludovic Gasc <span dir="ltr"><<a href="mailto:gmludo@gmail.com" target="_blank">gmludo@gmail.com</a>></span> wrote:<br></div></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div class="h5"><div dir="ltr">Hi,<div><br></div><div>1. The problem</div><div><br></div><div>For now, when you want to write a log message, you concatenate the data from your context to generate a string: In fact, you convert your structured data to a string.</div><div>When a sysadmin needs to debug your logs when something is wrong, he must write regular expressions to extract interesting data.</div><div><br></div><div>Often, he must find the beginning of the interesting log and follow the path. Sometimes, you can have several requests in the same time in the log, it's harder to find interesting log.</div><div>In fact, with regular expressions, the sysadmin tries to convert the log lines strings to structured data.</div><div><br></div><div>2. A possible solution</div><div><br></div><div>You should provide a set of regular expressions to your sysadmins to help them to find the right logs, however, another approach is possible: structured logs.</div><div>Instead of to break your data structure to push in the log message, the idea is to keep the data structure, to attach that as metadata of the log message.</div><div>For now, I know at least Logstash and Journald that can handle structured logs and provide a query tool to extract easily logs.</div><div><br></div><div>3. A concrete example with structured logs</div><div><br></div><div>As most Web developers, we build HTTP daemons used by several different human clients in the same time.</div><div>In the Python source code, to support structured logs, you don't have a big change, you can use "extra" parameter for that, example:</div><div><br></div><div> [handle HTTP request]</div><div><div> LOG.debug('Receive a create_or_update request', extra={'request_id': request.request_id,</div><div> 'account_id': account_id,</div><div> 'aiohttp_request': request,</div><div> 'payload': str(payload)})</div></div><div> [create data in database]</div><div><div> LOG.debug('Callflow created', extra={'account_id': account_id,</div><div> 'request_id': request.request_id,</div><div> 'aiopg_cursor': cur,</div><div> 'results': row})</div></div><div><br></div><div>Now, if you want, you can enhance the structured log with a custom logging Handler, because the standard journald handler doesn't know how to handle aiohttp_request or aiopg_cursor.</div><div>My example is based on journald, but you can write an equivalent version with python-logstash:</div><div>####</div><div><div>from systemdream.journal.handler import JournalHandler</div><div><br></div><div>class Handler(JournalHandler):</div><div> # Tip: on a system without journald, use socat to test:</div><div> # socat UNIX-RECV:/run/systemd/journal/socket STDIN</div><div> def emit(self, record):</div><div> if record.extra:</div><div> # import ipdb; ipdb.set_trace()</div><div> if 'aiohttp_request' in record.extra:</div><div> record.extra['http_method'] = record.extra['aiohttp_request'].method</div><div> record.extra['http_path'] = record.extra['aiohttp_request'].path</div><div> record.extra['http_headers'] = str(record.extra['aiohttp_request'].headers)</div><div> del(record.extra['aiohttp_request'])</div><div> if 'aiopg_cursor' in record.extra:</div><div> record.extra['pg_query'] = record.extra['aiopg_cursor'].query.decode('utf-8')</div><div> record.extra['pg_status_message'] = record.extra['aiopg_cursor'].statusmessage</div><div> record.extra['pg_rows_count'] = record.extra['aiopg_cursor'].rowcount</div><div> del(record.extra['aiopg_cursor'])</div><div> super().emit(record)</div></div><div>####</div><div><br></div><div>And you can enable this custom handler in your logging config file like this:</div><div><div>[handler_journald]</div><div>class=XXXXXXXXXX.utils.logs.Handler<br></div><div>args=()</div><div>formatter=detailed</div><div><br></div></div><div>And now, with journalctl, you can easily extract logs, some examples:</div><div>Logs messages from 'lg' account:</div><div> journalctl ACCOUNT_ID=lg</div><div>All HTTP requests that modify the 'lg' account (PUT, POST and DELETE):</div><div> journalctl ACCOUNT_ID=lg HTTP_METHOD=PUT HTTP_METHOD=POST HTTP_METHOD=DELETE</div><div>Retrieve all logs from one specific HTTP request:</div><div> journalctl REQUEST_ID=130b8fa0-6576-43b6-a624-4a4265a2fbdd</div><div>All HTTP requests with a specific path:</div><div> journalctl HTTP_PATH=/v1/accounts/lg/callflows</div><div>All logs of "create" function in the file "example.py"</div><div> journalctl CODE_FUNC=create CODE_FILE=/path/example.py</div><div><br></div><div>If you already do a troubleshooting on a production system, you should understand the interest of this:</div><div>In fact, it's like to have SQL queries capabilities, but it's logging oriented.</div><div>We use that since a small time on one of our critical daemon that handles a lot of requests across several servers, it's already adopted from our support team.</div><div><br></div><div>4. The yocto issue with the Python logging module</div><div><br></div><div>I don't explain here a small part of my professional life for my pleasure, but to help you to understand the context and the usages, because my patch for logging is very small.</div><div>If you're an expert of Python logging, you already know that my Handler class example I provided above can't run on a classical Python logging, because LogRecord doesn't have an extra attribute.<br></div><div><br></div><div>extra parameter exists in the Logger, but, in the LogRecord, it's merged as attributes of LogRecord:</div><div><a href="https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L1386" target="_blank">https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L1386</a><br></div><div><br></div><div>It means, that when the LogRecord is sent to the Handler, you can't retrieve the dict from the extra parameter of logger.</div><div>The only way to do that without to patch Python logging, is to rebuild by yourself the dict with a list of official attributes of LogRecord, as is done in python-logstash:</div><div><a href="https://github.com/vklochan/python-logstash/blob/master/logstash/formatter.py#L23" target="_blank">https://github.com/vklochan/python-logstash/blob/master/logstash/formatter.py#L23</a><br></div><div>At least to me, it's a little bit dirty.</div><div><br></div><div>My quick'n'dirty patch I use for now on our CPython on production:</div><div><br></div><div><div>diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py</div><div>index 104b0be..30fa6ef 100644</div><div>--- a/Lib/logging/__init__.py</div><div>+++ b/Lib/logging/__init__.py</div><div>@@ -1382,6 +1382,7 @@ class Logger(Filterer):</div><div> """</div><div> rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,</div><div> sinfo)</div><div>+ rv.extra = extra</div><div> if extra is not None:</div><div> for key in extra:</div><div> if (key in ["message", "asctime"]) or (key in rv.__dict__):</div></div><div><br></div><div>At least to me, it should be cleaner to add "extra" as parameter of _logRecordFactory, but I've no idea of side effects, I understand that logging module is critical, because it's used everywhere.</div><div>However, except with python-logstash, to my knowledge, extra parameter isn't massively used.</div><div>The only backward incompatibility I see with a new extra attribute of LogRecord, is that if you have a log like this:</div><div><div> LOG.debug('message', extra={'extra': 'example'})</div></div><div>It will raise a KeyError("Attempt to overwrite 'extra' in LogRecord") exception, but, at least to me, the probability of this use case is near to 0.</div><div><br></div><div>Instead of to "maintain" this yocto patch, even it's very small, I should prefer to have a clean solution in Python directly.</div><div><br></div><div>Thanks for your remarks.</div><div><br></div><div>Regards.</div><div><div><div><div dir="ltr"><div>--<br><div style="font-size:small"><div>Ludovic Gasc (GMLudo)</div></div><div style="font-size:small"><a href="http://www.gmludo.eu/" target="_blank">http://www.gmludo.eu/</a></div></div></div></div></div>
</div></div>
<br></div></div>_______________________________________________<br>
Python-Dev mailing list<br>
<a href="mailto:Python-Dev@python.org" target="_blank">Python-Dev@python.org</a><br>
<a href="https://mail.python.org/mailman/listinfo/python-dev" target="_blank">https://mail.python.org/mailman/listinfo/python-dev</a><br>
Unsubscribe: <a href="https://mail.python.org/mailman/options/python-dev/guido%40python.org" target="_blank">https://mail.python.org/mailman/options/python-dev/guido%40python.org</a><br>
<br></blockquote></div><span class="HOEnZb"><font color="#888888"><br><br clear="all"><br>-- <br><div>--Guido van Rossum (<a href="http://python.org/~guido" target="_blank">python.org/~guido</a>)</div>
</font></span></div>
</div><br></div></div>