-
Notifications
You must be signed in to change notification settings - Fork 0
/
Copy pathpython-microservice-logging.html
300 lines (239 loc) · 24.5 KB
/
python-microservice-logging.html
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
<!DOCTYPE html>
<html lang="english">
<head>
<meta charset="utf-8" />
<meta http-equiv="X-UA-Compatible" content="IE=edge" />
<meta name="HandheldFriendly" content="True" />
<meta name="viewport" content="width=device-width, initial-scale=1.0" />
<meta name="robots" content="index, follow" />
<link href='//fonts.googleapis.com/css?family=Source+Sans+Pro:300,400,700,400italic' rel='stylesheet' type='text/css'>
<link rel="stylesheet" type="text/css" href="http://olipratt.co.uk/theme/stylesheet/style.min.css">
<link rel="stylesheet" type="text/css" href="http://olipratt.co.uk/theme/pygments/monokai.min.css">
<link rel="stylesheet" type="text/css" href="http://olipratt.co.uk/theme/font-awesome/css/font-awesome.min.css">
<link href="http://olipratt.co.uk/static/custom.css" rel="stylesheet">
<link href="http://olipratt.co.uk/feeds/all.atom.xml" type="application/atom+xml" rel="alternate" title="Oli Pratt's Blog Atom">
<link rel="shortcut icon" href="/favicon.ico" type="image/x-icon">
<link rel="icon" href="/favicon.ico" type="image/x-icon">
<!-- Chrome, Firefox OS and Opera -->
<meta name="theme-color" content="#282828">
<!-- Windows Phone -->
<meta name="msapplication-navbutton-color" content="#282828">
<!-- iOS Safari -->
<meta name="apple-mobile-web-app-capable" content="yes">
<meta name="apple-mobile-web-app-status-bar-style" content="black-translucent">
<!-- Microsoft EDGE -->
<meta name="msapplication-TileColor" content="#282828">
<meta name="author" content="Oli Pratt" />
<meta name="description" content="After looking into microservices recently, I was running multiple terminals and switching between them to look at logs as they are written to screen. This was a little awkward so I thought it was worth looking for the right way to log to a central location from multiple microservices. Ideally I wanted do this just using the Python logging library, and without adding more dependencies to every service. This meant a lot of reading around …" />
<meta name="keywords" content="Python, logging, syslog, microservice">
<meta property="og:site_name" content="Oli Pratt's Blog"/>
<meta property="og:title" content="Python Microservice Logging"/>
<meta property="og:description" content="After looking into microservices recently, I was running multiple terminals and switching between them to look at logs as they are written to screen. This was a little awkward so I thought it was worth looking for the right way to log to a central location from multiple microservices. Ideally I wanted do this just using the Python logging library, and without adding more dependencies to every service. This meant a lot of reading around …"/>
<meta property="og:locale" content="en_GB"/>
<meta property="og:url" content="http://olipratt.co.uk/python-microservice-logging.html"/>
<meta property="og:type" content="article"/>
<meta property="article:published_time" content="2017-02-25 14:39:00+00:00"/>
<meta property="article:modified_time" content=""/>
<meta property="article:author" content="http://olipratt.co.uk/author/oli-pratt.html">
<meta property="article:section" content="Logging"/>
<meta property="article:tag" content="Python"/>
<meta property="article:tag" content="logging"/>
<meta property="article:tag" content="syslog"/>
<meta property="article:tag" content="microservice"/>
<meta property="og:image" content="http://olipratt.co.uk/static/images/site_logo.png">
<title>Oli Pratt's Blog – Python Microservice Logging</title>
</head>
<body>
<aside>
<div>
<a href="http://olipratt.co.uk">
<img src="http://olipratt.co.uk/static/images/site_logo.png" alt="Oli Pratt" title="Oli Pratt">
</a>
<h1><a href="http://olipratt.co.uk">Oli Pratt</a></h1>
<p>Software Engineer</p>
<nav>
<ul class="list">
<li><a href="http://olipratt.co.uk/pages/about-me.html#about-me">About Me</a></li>
<li><a href="https://www.metaswitch.com/" target="_blank">Metaswitch</a></li>
</ul>
</nav>
<ul class="social">
<li><a class="sc-github" href="https://github.com/olipratt" target="_blank"><i class="fa fa-github"></i></a></li>
<li><a class="sc-linkedin" href="https://www.linkedin.com/in/olipratt/" target="_blank"><i class="fa fa-linkedin"></i></a></li>
<li><a class="sc-rss" href="/feeds/all.atom.xml" target="_blank"><i class="fa fa-rss"></i></a></li>
</ul>
</div>
</aside>
<main>
<nav>
<a href="http://olipratt.co.uk"> Home
</a>
<a href="/archives.html">Archives</a>
<a href="/categories.html">Categories</a>
<a href="/tags.html">Tags</a>
<a href="http://olipratt.co.uk/feeds/all.atom.xml"> Atom
</a>
</nav>
<article class="single">
<header>
<h1 id="python-microservice-logging">Python Microservice Logging</h1>
<p>
Posted on Sat 25 February 2017 in <a href="http://olipratt.co.uk/category/logging.html">Logging</a>
• 5 min read
</p>
</header>
<div>
<p>After looking into <a href="http://olipratt.co.uk/python-rest-api-with-swaggerui.html">microservices</a> <a href="http://olipratt.co.uk/python-rest-api-client-adhering-to-a-swagger-schema.html">recently</a>, I was running multiple terminals and switching between them to look at logs as they are written to screen. This was a little awkward so I thought it was worth looking for the right way to log to a central location from multiple microservices. Ideally I wanted do this just using the Python logging library, and without adding more dependencies to every service.</p>
<p>This meant a lot of reading around to reach a rather boring and obvious solution. I documented my whistle-stop tour around the world of logging, but jump to the end to just see the <a href="#real-solution">solution</a> I went with.</p>
<h2 id="picking-a-format">Picking a format</h2>
<h4 id="open-standards">Open Standards</h4>
<p>Straight off - there’s no obvious standardised server package for receiving logs over the network from the Python logging module. I initially thought this whole thing would just take a 5 minute search - maybe this should have been a clue.</p>
<p>So I started looking around for other open logging formats and log stores. Turns out there’s quite a few of these. <a href="http://docs.graylog.org/en/2.2/pages/gelf.html">GELF</a> seemed like maybe a good option. It’s open, JSON structured format, integrates with many log stores, and has a <a href="https://github.com/severb/graypy">Python logging module handler</a>.</p>
<p><a href="http://docs.graylog.org/en/2.2/pages/installation.html">The GELF server</a> is pretty massive though - delivered as a whole VM, ideally I just wanted a simple listener script I could run. I did find a <a href="http://idlethreat.com/blog/graylog/gelf-listener-in-python/">single simple server implementation</a>, but that was it. I got it all running easily enough, and though I could have tidied it up and used it, I felt I was off the beaten path and had added a new dependency to every service for logging so kept digging for a bit.</p>
<h4 id="too-cumbersome-back-to-simple-http">Too Cumbersome - Back to Simple HTTP</h4>
<p>Going back to the logging module, it looked like basic <a href="https://docs.python.org/3/library/logging.handlers.html#httphandler">HTTPHandler</a> would do, and meant no dependencies. However, I found <a href="http://ericshtiv.blogspot.co.uk/2012/12/python-fast-http-logging-handler.html">warnings that it was slow</a>, but then a <a href="http://plumberjack.blogspot.co.uk/2010/09/improved-queuehandler-queuelistener.html">solution</a> to that using the logging module’s <a href="https://docs.python.org/3.6/library/logging.handlers.html#queuehandler">queuehandler</a>.</p>
<p>I got that working, but the POST body from the HTTPHandler was not JSON but just a <a href="http://stackoverflow.com/a/14551320">URL encoded string</a>. I could easily decode this in a Flask server, but then it was still a lot of code to copy paste and I might as well just shove in a JSON body instead. So I reworked that into a REST log handler - which I still have lying around:</p>
<div class="highlight"><pre><span></span><span class="k">def</span> <span class="nf">configure_remote_logging</span><span class="p">(</span><span class="n">url</span><span class="p">,</span> <span class="n">client_name</span><span class="p">,</span> <span class="n">level</span><span class="o">=</span><span class="n">logging</span><span class="o">.</span><span class="n">INFO</span><span class="p">):</span>
<span class="sd">"""Set up remote logging to the specified url.</span>
<span class="sd"> This sets up a queue which logs are placed onto, and then they are sent on</span>
<span class="sd"> a background thread so they don't slow down the code making the logs.</span>
<span class="sd"> """</span>
<span class="c1"># The handler which will send logs remotely - definition and an instance.</span>
<span class="k">class</span> <span class="nc">RESTHandler</span><span class="p">(</span><span class="n">logging</span><span class="o">.</span><span class="n">Handler</span><span class="p">):</span>
<span class="sd">"""Handler which sends logs to a REST log server."""</span>
<span class="k">def</span> <span class="nf">__init__</span><span class="p">(</span><span class="bp">self</span><span class="p">,</span> <span class="n">url</span><span class="p">,</span> <span class="n">client_name</span><span class="p">):</span>
<span class="nb">super</span><span class="p">(</span><span class="n">RESTHandler</span><span class="p">,</span> <span class="bp">self</span><span class="p">)</span><span class="o">.</span><span class="fm">__init__</span><span class="p">()</span>
<span class="bp">self</span><span class="o">.</span><span class="n">url</span> <span class="o">=</span> <span class="n">url</span>
<span class="bp">self</span><span class="o">.</span><span class="n">client_name</span> <span class="o">=</span> <span class="n">client_name</span>
<span class="k">def</span> <span class="nf">format</span><span class="p">(</span><span class="bp">self</span><span class="p">,</span> <span class="n">log_record</span><span class="p">):</span>
<span class="n">formatted</span> <span class="o">=</span> <span class="n">log_record</span><span class="o">.</span><span class="vm">__dict__</span>
<span class="n">formatted</span><span class="p">[</span><span class="s2">"processName"</span><span class="p">]</span> <span class="o">=</span> <span class="bp">self</span><span class="o">.</span><span class="n">client_name</span>
<span class="k">return</span> <span class="n">formatted</span>
<span class="k">def</span> <span class="nf">emit</span><span class="p">(</span><span class="bp">self</span><span class="p">,</span> <span class="n">log_record</span><span class="p">):</span>
<span class="kn">import</span> <span class="nn">requests</span>
<span class="n">requests</span><span class="o">.</span><span class="n">post</span><span class="p">(</span><span class="bp">self</span><span class="o">.</span><span class="n">url</span><span class="p">,</span> <span class="n">json</span><span class="o">=</span><span class="bp">self</span><span class="o">.</span><span class="n">format</span><span class="p">(</span><span class="n">log_record</span><span class="p">))</span>
<span class="n">rest_handler</span> <span class="o">=</span> <span class="n">RESTHandler</span><span class="p">(</span><span class="n">url</span><span class="p">,</span> <span class="n">client_name</span><span class="p">)</span>
<span class="n">rest_handler</span><span class="o">.</span><span class="n">setLevel</span><span class="p">(</span><span class="n">level</span><span class="p">)</span>
<span class="c1"># Create queue handlers so that logs are processed in a background thread.</span>
<span class="c1"># Set up an unbounded size queue and assume logs are processed faster than</span>
<span class="c1"># they are made.</span>
<span class="n">logging_queue</span> <span class="o">=</span> <span class="n">queue</span><span class="o">.</span><span class="n">Queue</span><span class="p">()</span>
<span class="n">queue_handler</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">handlers</span><span class="o">.</span><span class="n">QueueHandler</span><span class="p">(</span><span class="n">logging_queue</span><span class="p">)</span>
<span class="n">queue_listener</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">handlers</span><span class="o">.</span><span class="n">QueueListener</span><span class="p">(</span><span class="n">logging_queue</span><span class="p">,</span>
<span class="n">rest_handler</span><span class="p">)</span>
<span class="c1"># Add the remote logging handler and start the background queue running.</span>
<span class="n">root</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">getLogger</span><span class="p">()</span>
<span class="n">root</span><span class="o">.</span><span class="n">addHandler</span><span class="p">(</span><span class="n">queue_handler</span><span class="p">)</span>
<span class="n">queue_listener</span><span class="o">.</span><span class="n">start</span><span class="p">()</span>
<span class="c1"># Should call this on exit to ensure all final logs are flushed.</span>
<span class="c1"># queue_listener.stop()</span>
</pre></div>
<p>Then receiving the log is simple on the Flask server side - just:</p>
<div class="highlight"><pre><span></span><span class="k">class</span> <span class="nc">LogsCollection</span><span class="p">(</span><span class="n">Resource</span><span class="p">):</span>
<span class="k">def</span> <span class="nf">post</span><span class="p">(</span><span class="bp">self</span><span class="p">):</span>
<span class="sd">"""Receives a log."""</span>
<span class="n">log</span><span class="o">.</span><span class="n">handle</span><span class="p">(</span><span class="n">logging</span><span class="o">.</span><span class="n">makeLogRecord</span><span class="p">(</span><span class="n">request</span><span class="o">.</span><span class="n">get_json</span><span class="p">()))</span>
<span class="k">return</span> <span class="kc">None</span><span class="p">,</span> <span class="mi">201</span>
</pre></div>
<p>But now:</p>
<ul>
<li>I should really be calling the commented out <code>stop</code> method on the queue when the app exits, otherwise logs can end up not being flushed - which means some kind of global state to store a reference to that queue and a hook to call it.</li>
<li>The overhead of a HTTP POST for every log seems high - especially at the debug level.</li>
<li>I’ve still got a huge block of code to copy/paste into every service, or otherwise write a package and add another dependency.</li>
<li>I’ve added a dependency on <code>requests</code> in there.</li>
</ul>
<p>Sigh.</p>
<h4 id="no-no-lets-use-a-standard">No, No - Let’s Use a Standard</h4>
<p>Clearly that’s the wrong approach - throw it away and start over. Really we should be going with a standard so we can integrate with other things, and that ended up with me looking into syslog since</p>
<ul>
<li>it seemed frequently <a href="http://www.structlog.org/en/stable/logging-best-practices.html#syslog-again">recommended</a>,</li>
<li>well used and supported by every client/server,</li>
<li>has a built in <a href="https://docs.python.org/3/library/logging.handlers.html#sysloghandler">Python logging handler</a>,</li>
<li>I <a href="https://gist.github.com/marcelom/4218010">found a tiny Python listener for it</a>,</li>
<li>and <a href="https://tools.ietf.org/html/rfc5424">it’s so standardised it has an RFC</a>!</li>
</ul>
<p>This <em>had</em> to be the right answer, so I wrote some client code for that:</p>
<div class="highlight"><pre><span></span><span class="k">def</span> <span class="nf">configure_logging</span><span class="p">(</span><span class="n">client_name</span><span class="p">,</span> <span class="n">host</span><span class="o">=</span><span class="bp">None</span><span class="p">,</span> <span class="n">level</span><span class="o">=</span><span class="n">logging</span><span class="o">.</span><span class="n">INFO</span><span class="p">):</span>
<span class="sd">"""Set up logging to stderr and optionally a remote syslog server."""</span>
<span class="n">handlers</span> <span class="o">=</span> <span class="p">[]</span>
<span class="k">if</span> <span class="n">host</span> <span class="ow">is</span> <span class="ow">not</span> <span class="bp">None</span><span class="p">:</span>
<span class="n">syslog_fmt</span> <span class="o">=</span> <span class="p">(</span><span class="s1">'1 </span><span class="si">%(asctime)s</span><span class="s1">.</span><span class="si">%(msecs)03d</span><span class="s1">Z {} {} - - - '</span>
<span class="s1">'</span><span class="si">%(message)s</span><span class="s1">'</span><span class="p">)</span><span class="o">.</span><span class="n">format</span><span class="p">(</span><span class="n">socket</span><span class="o">.</span><span class="n">getfqdn</span><span class="p">(),</span> <span class="n">client_name</span><span class="p">)</span>
<span class="n">syslog_date</span> <span class="o">=</span> <span class="s1">'%Y-%m-</span><span class="si">%d</span><span class="s1">T%H:%M:%S'</span>
<span class="n">syslog_formatter</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">Formatter</span><span class="p">(</span><span class="n">syslog_fmt</span><span class="p">,</span> <span class="n">datefmt</span><span class="o">=</span><span class="n">syslog_date</span><span class="p">)</span>
<span class="c1"># Force UTC time so we can just stick `Z` at the end of the timestamp.</span>
<span class="n">syslog_formatter</span><span class="o">.</span><span class="n">converter</span> <span class="o">=</span> <span class="n">time</span><span class="o">.</span><span class="n">gmtime</span>
<span class="n">syslog_handler</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">handlers</span><span class="o">.</span><span class="n">SysLogHandler</span><span class="p">(</span><span class="n">address</span><span class="o">=</span><span class="p">(</span><span class="n">host</span><span class="p">,</span> <span class="mi">514</span><span class="p">))</span>
<span class="n">syslog_handler</span><span class="o">.</span><span class="n">setFormatter</span><span class="p">(</span><span class="n">syslog_formatter</span><span class="p">)</span>
<span class="n">handlers</span><span class="o">.</span><span class="n">append</span><span class="p">(</span><span class="n">syslog_handler</span><span class="p">)</span>
<span class="n">stderr_fmt</span> <span class="o">=</span> <span class="s1">'</span><span class="si">%(asctime)-23s</span><span class="s1">:</span><span class="si">%(levelname)-8s</span><span class="s1">:</span><span class="si">%(message)s</span><span class="s1">'</span>
<span class="n">stderr_formatter</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">Formatter</span><span class="p">(</span><span class="n">stderr_fmt</span><span class="p">)</span>
<span class="n">stderr_handler</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">StreamHandler</span><span class="p">()</span>
<span class="n">stderr_handler</span><span class="o">.</span><span class="n">setFormatter</span><span class="p">(</span><span class="n">stderr_formatter</span><span class="p">)</span>
<span class="n">handlers</span><span class="o">.</span><span class="n">append</span><span class="p">(</span><span class="n">stderr_handler</span><span class="p">)</span>
<span class="n">root</span> <span class="o">=</span> <span class="n">logging</span><span class="o">.</span><span class="n">getLogger</span><span class="p">()</span>
<span class="n">root</span><span class="o">.</span><span class="n">setLevel</span><span class="p">(</span><span class="n">level</span><span class="p">)</span>
<span class="k">for</span> <span class="n">handler</span> <span class="ow">in</span> <span class="n">handlers</span><span class="p">:</span>
<span class="n">root</span><span class="o">.</span><span class="n">addHandler</span><span class="p">(</span><span class="n">handler</span><span class="p">)</span>
</pre></div>
<p><em>Aside: I had to build the formatter to match the RFC standard syslog format because I couldn’t easily find one elsewhere - might come in handy.</em></p>
<p>So this now works fine, it’s a reasonable chunk of code, but it’s mostly just boilerplate stuff setting up the built in logging module, and the only custom part is setting up the right formatter. All done?</p>
<h2 id="real-solution">Real Solution</h2>
<p>So after all that, I think I’m done and move on to something else - containerising these apps was up next for me - …and that’s when I stumble across the <em>right</em> answer. It’s right <a href="https://12factor.net/logs">here</a> in these <a href="https://12factor.net/">guidelines to writing services</a>:</p>
<p><strong><em>Just write your logs to stdout.</em></strong></p>
<p>That’s it! Then whatever is running your app pipes them out and handles them appropriately. Anything else you do is just another system someone has to worry about integrating into their setup. <a href="https://docs.docker.com/engine/reference/commandline/logs/#/extended-description">Docker by default assumes an app will send logs to stdout</a> and handles them as configured. I saw this in action when I started using Docker - I’ll write that up soon.</p>
<hr>
<p>So that was an interesting bit of investigation, and I learnt some stuff, but damn if it doesn’t feel like a waste of time.</p>
<p>How do you handle logging from your Python apps?</p>
</div>
<div class="tag-cloud">
<p>
<a href="http://olipratt.co.uk/tag/python.html">Python</a>
<a href="http://olipratt.co.uk/tag/logging.html">logging</a>
<a href="http://olipratt.co.uk/tag/syslog.html">syslog</a>
<a href="http://olipratt.co.uk/tag/microservice.html">microservice</a>
</p>
</div>
<div class="neighbors">
<a class="btn float-left" href="http://olipratt.co.uk/rest-apis-notes-and-references.html" title="REST APIs Notes and References">
<i class="fa fa-angle-left"></i> Previous Post
</a>
<a class="btn float-right" href="http://olipratt.co.uk/docker-container-for-a-simple-flask-app.html" title="Docker Container for a simple Flask App">
Next Post
<i class="fa fa-angle-right"></i>
</a>
</div>
</article>
<footer>
<p>© Oli Pratt </p>
<p> Powered by <a href="http://getpelican.com" target="_blank">Pelican</a> - <a href="https://github.com/alexandrevicenzi/flex" target="_blank">Flex</a> theme by <a href="http://alexandrevicenzi.com" target="_blank">Alexandre Vicenzi</a>
</p> </footer>
</main>
<script type="application/ld+json">
{
"@context": "http://schema.org",
"@type": "BlogPosting",
"name": "Python Microservice Logging",
"headline": "Python Microservice Logging",
"datePublished": "2017-02-25 14:39:00+00:00",
"dateModified": "2017-02-25 14:39:00+00:00",
"author": {
"@type": "Person",
"name": "Oli Pratt"
},
"publisher": {
"@type": "Organization",
"name": "Oli Pratt",
"logo": {
"@type": "ImageObject",
"url": "http://olipratt.co.uk/static/images/site_logo.png"
}
},
"image": "http://olipratt.co.uk/static/images/site_logo.png",
"mainEntityOfPage": "http://olipratt.co.uk/python-microservice-logging.html",
"url": "http://olipratt.co.uk/python-microservice-logging.html",
"description": "After looking into microservices recently, I was running multiple terminals and switching between them to look at logs as they are written to screen. This was a little awkward so I thought it was worth looking for the right way to log to a central location from multiple microservices. Ideally I wanted do this just using the Python logging library, and without adding more dependencies to every service. This meant a lot of reading around …"
}
</script>
</body>
</html>