Jotting
Logs that explain when, where, and why things happen.
Jotting was heavily inspired by
eliot
.
jotting
is a log system for Python 2 and 3 that can be used to record the causal history of an asynchronous or distributed system. These histories are composed of actions which, once "started", will begin "working", potentially spawn other actions, and eventually end as a "success" or "failure". In the end you're left with a breadcrumb trail of information that you can use to squash bugs with minimal boilerplate.
Quickstart
Install jotting
with pip
:
$ pip install jotting
Then requests
and flask
to follow along with the examples:
$ pip install requests flask
Bookmarking
We'll start with a function that uses requests
to return a response from a url:
import requests
def get_url(url):
r = requests.get(url)
r.raise_for_status()
return r
response = get_url("https://google.com")
Then we'll start logging what it does by adding a book.mark
decorator:
import requests
from jotting import book
@book.mark
def get_url(url):
r = requests.get(url)
r.raise_for_status()
return r
response = get_url("https://google.com")
Once we've done this we'll immediately begin to see printed log statements:
|-- started: __main__.get_url
| @ 2018-01-14 17:08:19.223383
| | url: https://google.com
| `-- success: __main__.get_url
| @ 2018-01-14 17:08:20.101563
| | returned: <Response [200]>
| | duration: 0.879 seconds
But if we need more information than this we can also use book.write
:
import requests
from jotting import book
@book.mark
def get_url(url):
r = requests.get(url)
book.write(debug="checking status...")
r.raise_for_status()
return r
response = get_url("https://google.com")
And now we get an extra log telling us what's going on inside get_url
:
|-- started: __main__.get_url
| @ 2018-01-14 17:08:19.223383
| | url: https://google.com
| |-- working: __main__.get_url
| | @ 2018-01-14 17:08:20.101401
| | | debug: checking status...
| `-- success: __main__.get_url
| @ 2018-01-14 17:08:20.101563
| | returned: <Response [200]>
| | duration: 0.879 seconds
Putting Things In Context
But wait! We have scripts or functions that have subtasks we'd like to monitor:
import requests
urls = ("https://google.com", "not-here")
responses = []
for u in urls:
r = requests.get(u)
r.raise_for_status()
responses.append(r)
We can use the book
context to define actions that exist independently of functions:
import requests
from jotting import book
urls = ("https://google.com", "not-here")
responses = []
for u in urls:
with book("getting %s" % u):
r = requests.get(u)
r.raise_for_status()
responses.append(r)
This will produce just the kind of fine grained logs we need:
|-- started: getting https://google.com
| @ 2018-01-14 17:06:22.016731
| `-- success: getting https://google.com
| @ 2018-01-14 17:06:23.006855
| | duration: 0.990 seconds
|-- started: getting not-here
| @ 2018-01-14 17:06:23.007092
| `-- failure: getting not-here
| @ 2018-01-14 17:06:23.007587
| | MissingSchema: Invalid URL 'not-here': No schema supplied. Perhaps you meant http://not-here?
| | duration: 0.001 seconds
Stashing Outputs
Under the hood, jotting
creates json encoded messages that contain the information
required to reconstruct a history of actions. If we need to reconfigure where and/or
how jotting
logs, we choose new outlets and styles. In a case where we want to
print terse logs to sdtout, but save raw json blobs to a file for later consumption,
we can use a Log
styled Print
outlet and a Raw
styled File
outlet respectively.
For the Log
style, only the successes and failures of logs where a title has been
given are reported - thus we will title our book.mark
with something explanatory:
import requests
from jotting import book, to, style
to_print = to.Print(style.Log())
to_file = to.File(path="~/Desktop/logbox.txt")
book.distribute(to_print, to_file)
# we can format the title with
# the inputs of the function
@book.mark("getting {url}")
def get_url(url):
r = requests.get(url)
r.raise_for_status()
return r
response = get_url("https://google.com")
Now we will find that we got a print out like this:
2018-02-21 19:46:03.156873 SUCCESS getting https://google.com after 0.315 seconds - returned: <Response [200]>
Along with a logbox.txt
file on our desktop with the following contents:
{"metadata": {"tag": "ca5d60ee174111e8b6348c8590280283-0", "depth": 0, "start": 1519243197.023079, "status": "started", "parent": null, "title": "getting https://google.com"}, "content": {"url": "https://google.com"}, "timestamp": 1519243197.023083}
{"metadata": {"tag": "ca5d60ee174111e8b6348c8590280283-0", "depth": 0, "start": 1519243197.023079, "status": "success", "parent": null, "title": "getting https://google.com", "stop": 1519243197.5876129}, "content": {"returned": "<Response [200]>"}, "timestamp": 1519243197.587616}
Distributed Systems
We've covered a lot of use cases, but we can go even further. In the real world
we aren't working with single threads, processes, or services. Modern systems
are asynchronous and distributed. Following the causes and effects within these
systems quickly becomes impossible. However with jotting
, it's possible to
begin a book
using the tag
of a parent task that triggered it. In this way
logs can be linked across any context. We can build a very simple Flask
app
to demonstrate how we might link a book between a client and server:
from flask import Flask, jsonify, request
from jotting import book
import json
# Server
# ------
app = Flask(__name__)
@app.route("/api/task", methods=["PUT"])
def task():
data = json.loads(request.data)
with book('api', data["parent"]):
book.close(status=200)
return jsonify({"status": 200})
# Client
# ------
with book('put') as b:
route = '/api/task'
data = json.dumps({'parent': b.tag})
app.test_client().put(route, data=data)
|-- started: get
| @ 2018-02-25 18:22:45.912632
| |-- started: api
| | @ 2018-02-25 18:22:45.922958
| | `-- success: api
| | @ 2018-02-25 18:22:45.923105
| | | status: 200
| | | duration: 0.000 seconds
| `-- success: get
| @ 2018-02-25 18:22:45.928721
| | duration: 0.016 seconds