Beyond grep – EuroPython Edition

Slide 1

Slide 1 text

Beyond grep Pragmatic Logging & Metrics Hynek Schlawack

Slide 2

Slide 2 text

Hi! @hynek https://hynek.me https://github.com/hynek

Slide 3

Slide 3 text

www.variomedia.de

Slide 4

Slide 4 text

ox.cx/b

Slide 5

Slide 5 text

Agenda

Slide 6

Slide 6 text

Agenda

Slide 7

Slide 7 text

Agenda

Slide 8

Slide 8 text

Agenda

Slide 9

Slide 9 text

Errors

Slide 10

Slide 10 text

Errors

Slide 11

Slide 11 text

Requirements

Slide 12

Slide 12 text

Requirements •fast

Slide 13

Slide 13 text

Requirements •fast •once

Slide 14

Slide 14 text

Requirements •fast •once

Slide 15

Slide 15 text

Requirements •fast •once •context

Slide 16

Slide 16 text

Requirements •fast •once •context

Slide 17

Slide 17 text

No content

Slide 18

Slide 18 text

No content

Slide 19

Slide 19 text

No content

Slide 20

Slide 20 text

No content

Slide 21

Slide 21 text

No content

Slide 22

Slide 22 text

No content

Slide 23

Slide 23 text

No content

Slide 24

Slide 24 text

No content

Slide 25

Slide 25 text

No content

Slide 26

Slide 26 text

No content

Slide 27

Slide 27 text

Raven-Python

Slide 28

Slide 28 text

Raven-Python Transports:

Slide 29

Slide 29 text

Raven-Python Transports: • gevent

Slide 30

Slide 30 text

Raven-Python Transports: • gevent • aiohttp

Slide 31

Slide 31 text

Raven-Python Transports: • gevent • aiohttp • Twisted

Slide 32

Slide 32 text

Raven-Python Transports: • gevent • aiohttp • Twisted • …8 others

Slide 33

Slide 33 text

Raven-Python Integrations: Transports: • gevent • aiohttp • Twisted • …8 others

Slide 34

Slide 34 text

Raven-Python Integrations: • logging Transports: • gevent • aiohttp • Twisted • …8 others

Slide 35

Slide 35 text

Raven-Python Integrations: • logging • Django Transports: • gevent • aiohttp • Twisted • …8 others

Slide 36

Slide 36 text

Raven-Python Integrations: • logging • Django • WSGI Transports: • gevent • aiohttp • Twisted • …8 others

Slide 37

Slide 37 text

Raven-Python Integrations: • logging • Django • WSGI • …9 others Transports: • gevent • aiohttp • Twisted • …8 others

Slide 38

Slide 38 text

Vanilla from raven import Client client = Client("https://yoursentry") try: 1 / 0 except ZeroDivisionError: client.captureException()

Slide 39

Slide 39 text

Vanilla from raven import Client client = Client("https://yoursentry") try: 1 / 0 except ZeroDivisionError: client.captureException()

Slide 40

Slide 40 text

Vanilla from raven import Client client = Client("https://yoursentry") try: 1 / 0 except ZeroDivisionError: client.captureException()

Slide 41

Slide 41 text

Vanilla @client.capture_exceptions def foo(): raise Exception()

Slide 42

Slide 42 text

Django INSTALLED_APPS = ( … "raven.contrib.django.raven_compat", … )

Slide 43

Slide 43 text

Progress!

Slide 44

Slide 44 text

Progress! ✓

Slide 45

Slide 45 text

hynek2015

Slide 46

Slide 46 text

Metrics

Slide 47

Slide 47 text

Metrics?

Slide 48

Slide 48 text

Metrics? • numbers in a DB

Slide 49

Slide 49 text

Metrics? • numbers in a DB • guessing vs knowing

Slide 50

Slide 50 text

–D. J. Bernstein “Measure. Don’t speculate.”

Slide 51

Slide 51 text

System Metrics vs App Metrics • load • network trafﬁc • I/O • …

Slide 52

Slide 52 text

System Metrics vs App Metrics • load • network trafﬁc • I/O • … • counters

Slide 53

Slide 53 text

System Metrics vs App Metrics • load • network trafﬁc • I/O • … • counters • timers

Slide 54

Slide 54 text

System Metrics vs App Metrics • load • network trafﬁc • I/O • … • counters • timers • gauges

Slide 55

Slide 55 text

System Metrics vs App Metrics • load • network trafﬁc • I/O • … • counters • timers • gauges • …

Slide 56

Slide 56 text

Aggregation

Slide 57

Slide 57 text

Correlation

Slide 58

Slide 58 text

Math

Slide 59

Slide 59 text

Math • # reqs / s?

Slide 60

Slide 60 text

Math • # reqs / s? • worst 0.01% ⟨req time⟩?

Slide 61

Slide 61 text

Math • # reqs / s? • worst 0.01% ⟨req time⟩? • don’t try this alone!

Slide 62

Slide 62 text

Monitoring

Slide 63

Slide 63 text

Monitoring • latency

Slide 64

Slide 64 text

Monitoring • latency • error rates

Slide 65

Slide 65 text

Monitoring • latency • error rates • anomalies

Slide 66

Slide 66 text

Storage

Slide 67

Slide 67 text

Librato Metrics

Slide 68

Slide 68 text

Graphite 800 pound gorilla

Slide 69

Slide 69 text

Grafana

Slide 70

Slide 70 text

InﬂuxDB Graphite++ in Go

Slide 71

Slide 71 text

InﬂuxDB Graphite++ in Go

Slide 72

Slide 72 text

Collecting

Slide 73

Slide 73 text

Approaches

Slide 74

Slide 74 text

Approaches 1. external aggregation: StatsD, Riemann

Slide 75

Slide 75 text

Approaches 1. external aggregation: StatsD, Riemann + no state, simple

Slide 76

Slide 76 text

Approaches 1. external aggregation: StatsD, Riemann + no state, simple – no direct introspection

Slide 77

Slide 77 text

Approaches 1. external aggregation: StatsD, Riemann + no state, simple – no direct introspection 2. aggregate in-app, deliver to DB

Slide 78

Slide 78 text

Approaches 1. external aggregation: StatsD, Riemann + no state, simple – no direct introspection 2. aggregate in-app, deliver to DB + in-app dashboard, useful in dev

Slide 79

Slide 79 text

Approaches 1. external aggregation: StatsD, Riemann + no state, simple – no direct introspection 2. aggregate in-app, deliver to DB + in-app dashboard, useful in dev – state w/i app

Slide 80

Slide 80 text

No content

Slide 81

Slide 81 text

(g|py)?statsd(py|-client)? import statsd c = statsd.StatsClient( "statsd.local", 8125 )

Slide 82

Slide 82 text

(g|py)?statsd(py|-client)?

Slide 83

Slide 83 text

(g|py)?statsd(py|-client)? c.incr("foo")

Slide 84

Slide 84 text

(g|py)?statsd(py|-client)? c.incr("foo") c.timing("stats.timed", 320)

Slide 85

Slide 85 text

Scales from greplin import scales from greplin.scales.meter import MeterStat STATS = scales.collection( "/Resource", MeterStat("reqs"), scales.PmfStat("request_time") )

Slide 86

Slide 86 text

Scales from greplin import scales from greplin.scales.meter import MeterStat STATS = scales.collection( "/Resource", MeterStat("reqs"), scales.PmfStat("request_time") )

Slide 87

Slide 87 text

Scales

Slide 88

Slide 88 text

Scales STATS.reqs.mark()

Slide 89

Slide 89 text

Scales STATS.reqs.mark() with STATS.request_time.time():

Slide 90

Slide 90 text

Scales STATS.reqs.mark() with STATS.request_time.time(): do_something_expensive()

Slide 91

Slide 91 text

Dashboard Scales

Slide 92

Slide 92 text

Dashboard Scales

Slide 93

Slide 93 text

Dashboard Scales … "request_time": { "count": 567315293, "99percentile": 0.10978688716888428, "75percentile": 0.013181567192077637, "min": 0.0002448558807373047, "max": 30.134822130203247, "98percentile": 0.08934824466705339, "95percentile": 0.027234303951263434, "median": 0.009176492691040039, "999percentile": 0.14235656142234793, "stddev": 0.01676855570363413, "mean": 0.013247184020535955 }, …

Slide 94

Slide 94 text

from greplin.scales import graphite pusher = graphite.GraphitePeriodicPusher( "graphite.host", 2003, period=30, prefix="yourapp", ) pusher.allow("**") pusher.start()

Slide 95

Slide 95 text

Progress! ✓

Slide 96

Slide 96 text

Progress! ✓ ✓

Slide 97

Slide 97 text

Logging

Slide 98

Slide 98 text

Splunk

Slide 99

Slide 99 text

Splunk

Slide 100

Slide 100 text

Papertrail

Slide 101

Slide 101 text

loggly

Slide 102

Slide 102 text

ELK Elasticsearch + Logstash + Kibana

Slide 103

Slide 103 text

No content

Slide 104

Slide 104 text

No content

Slide 105

Slide 105 text

Logstash

Slide 106

Slide 106 text

Elasticsearch Logstash

Slide 107

Slide 107 text

Elasticsearch Logstash

Slide 108

Slide 108 text

Elasticsearch Logstash Kibana

Slide 109

Slide 109 text

Graylog

Slide 110

Slide 110 text

Graylog

Slide 111

Slide 111 text

Graylog

Slide 112

Slide 112 text

Graylog

Slide 113

Slide 113 text

No content

Slide 114

Slide 114 text

No content

Slide 115

Slide 115 text

Goal @400000005270e0d604afce64 { "event": "logged_in", "user": "guido", "ip": "8.8.8.8", "referrer": "http://google.com" }

Slide 116

Slide 116 text

Context & Format

Slide 117

Slide 117 text

structlog

Slide 118

Slide 118 text

BoundLogger structlog

Slide 119

Slide 119 text

Original Logger BoundLogger structlog e.g. logging.Logger

Slide 120

Slide 120 text

Original Logger BoundLogger bind values log.bind(key=value) Context structlog

Slide 121

Slide 121 text

Original Logger BoundLogger bind values log.bind(key=value) Context log events log.info(event, another_key=another_value) + structlog

Slide 122

Slide 122 text

Original Logger BoundLogger Processor 1 Processor n Return Value Return Value bind values log.bind(key=value) Context log events log.info(event, another_key=another_value) + structlog

Slide 123

Slide 123 text

>>> import structlog >>> log = structlog.get_logger() >>> log.error("ohai", why=42, wtf=True) why=42 wtf=True event='ohai'

Slide 124

Slide 124 text

>>> import structlog >>> log = structlog.get_logger() >>> log.error("ohai", why=42, wtf=True) why=42 wtf=True event='ohai'

Slide 125

Slide 125 text

>>> import structlog >>> log = structlog.get_logger() >>> log.error("ohai", why=42, wtf=True) why=42 wtf=True event='ohai'

Slide 126

Slide 126 text

>>> import structlog >>> log = structlog.get_logger() >>> log.error("ohai", why=42, wtf=True) why=42 wtf=True event='ohai'

Slide 127

Slide 127 text

>>> from structlog import get_logger >>> log = get_logger() >>> log = log.bind(user='anonymous', some_key=23) >>> log = log.bind(user='hynek', another_key=42) >>> log.info('user.logged_in', happy=True) some_key=23 user='hynek' another_key=42 happy=True event='user.logged_in'

Slide 128

Slide 128 text

Slide 129

Slide 129 text

Slide 130

Slide 130 text

Slide 131

Slide 131 text

Slide 132

Slide 132 text

def view(request): log = logger.bind(request=request) log.info("view_rendered") return "hello, world"

Slide 133

Slide 133 text

def view(request): log = logger.bind(request=request) log.info("view_rendered") return "hello, world"

Slide 134

Slide 134 text

def view(request): log = logger.bind(request=request) log.info("view_rendered") return "hello, world"

Slide 135

Slide 135 text

def request_extractor(_, __, event): req = event.pop("request", None) if req is not None: event.update({ "client_addr": req.client_addr, "user_id": req.authenticated_userid, }) return event

Slide 136

Slide 136 text

def request_extractor(_, __, event): req = event.pop("request", None) if req is not None: event.update({ "client_addr": req.client_addr, "user_id": req.authenticated_userid, }) return event

Slide 137

Slide 137 text

def request_extractor(_, __, event): req = event.pop("request", None) if req is not None: event.update({ "client_addr": req.client_addr, "user_id": req.authenticated_userid, }) return event

Slide 138

Slide 138 text

def request_extractor(_, __, event): req = event.pop("request", None) if req is not None: event.update({ "client_addr": req.client_addr, "user_id": req.authenticated_userid, }) return event

Slide 139

Slide 139 text

{"client_addr": "192.168.42.42", "user_id": null, "event": "view_rendered"}

Slide 140

Slide 140 text

import logging, sys logger = logging.getLogger() logger.addHandler( logging.StreamHandler( sys.stdout ) )

Slide 141

Slide 141 text

import logging, sys logger = logging.getLogger() logger.addHandler( logging.StreamHandler( sys.stdout ) )

Slide 142

Slide 142 text

Capture

Slide 143

Slide 143 text

Capture • into ﬁles

Slide 144

Slide 144 text

Capture • into ﬁles • to syslog / a queue

Slide 145

Slide 145 text

Capture • into ﬁles • to syslog / a queue • pipe into a logging agent

Slide 146

Slide 146 text

No content

Slide 147

Slide 147 text

log = log.bind(user="guido") log.info("user.login")

Slide 148

Slide 148 text

{"event": "user.login", "user": "guido"} log = log.bind(user="guido") log.info("user.login") structlog

Slide 149

Slide 149 text

{"event": "user.login", "user": "guido"} log = log.bind(user="guido") log.info("user.login") structlog stdout logging

Slide 150

Slide 150 text

{"event": "user.login", "user": "guido"} log = log.bind(user="guido") log.info("user.login") structlog stdout logging /var/log/app/current runit’s svlogd (adds TAI64 timestamp)

Slide 151

Slide 151 text

{"event": "user.login", "user": "guido"} log = log.bind(user="guido") log.info("user.login") structlog logstash-forwarder logstash stdout logging /var/log/app/current runit’s svlogd (adds TAI64 timestamp)

Slide 152

Slide 152 text

{"event": "user.login", "user": "guido"} log = log.bind(user="guido") log.info("user.login") structlog logstash-forwarder logstash 1010001101 Elasticsearch stdout logging /var/log/app/current runit’s svlogd (adds TAI64 timestamp)

Slide 153

Slide 153 text

Progress! ✓ ✓

Slide 154

Slide 154 text

Progress! ✓ ✓ ✓

Slide 155

Slide 155 text

Wait a Minute…

Slide 156

Slide 156 text

Wait a Minute…

Slide 157

Slide 157 text

Ugh try: STATS.time.timing(): something() except Exception as e: log.error("omg", exc_info=e) raven_client.captureError() STATS.errors.mark()

Slide 158

Slide 158 text

Ugh try: STATS.time.timing(): something() except Exception as e: log.error("omg", exc_info=e) raven_client.captureError() STATS.errors.mark()

Slide 159

Slide 159 text

Awww try: something() except Exception as e: log.exception("omg")

Slide 160

Slide 160 text

Errors

Slide 161

Slide 161 text

Errors • logging integration

Slide 162

Slide 162 text

Errors • logging • structlog

Slide 163

Slide 163 text

Errors • logging • structlog • web apps: error views

Slide 164

Slide 164 text

Error View @view_config(context=Exception) def err(exc, request): return Response( "oops: " + raven_client.captureException() )

Slide 165

Slide 165 text

No content

Slide 166

Slide 166 text

Metrics measure from outside

Slide 167

Slide 167 text

WSGI Servers

Slide 168

Slide 168 text

WSGI Servers • gunicorn: --statsd-host

Slide 169

Slide 169 text

WSGI Servers • gunicorn: --statsd-host • uWSGI:

Slide 170

Slide 170 text

WSGI Servers • gunicorn: --statsd-host • uWSGI: • --stats-push statsd:

Slide 171

Slide 171 text

WSGI Servers • gunicorn: --statsd-host • uWSGI: • --stats-push statsd: • --carbon

Slide 172

Slide 172 text

Middleware def timing_tween_factory(handler, registry): def timing_tween(request): with STATS.request_time.time(): return handler(request) return timing_tween

Slide 173

Slide 173 text

Middleware def timing_tween_factory(handler, registry): def timing_tween(request): with STATS.request_time.time(): return handler(request) return timing_tween

Slide 174

Slide 174 text

Extract from Logs

Slide 175

Slide 175 text

Extract from Logs logstash

Slide 176

Slide 176 text

Extract from Logs logstash • StatsD

Slide 177

Slide 177 text

Extract from Logs logstash • StatsD • Graphite

Slide 178

Slide 178 text

Extract from Logs logstash • StatsD • Graphite • librato

Slide 179

Slide 179 text

Extract from Logs logstash • StatsD • Graphite • librato • …

Slide 180

Slide 180 text

Extract from Logs logstash • StatsD • Graphite • librato • … or structlog