|
| 1 | +# Lesson 1 - Hello World |
| 2 | + |
| 3 | +## Objectives |
| 4 | + |
| 5 | +Learn how to: |
| 6 | + |
| 7 | +* Instantiate a Tracer |
| 8 | +* Create a simple trace |
| 9 | +* Annotate the trace |
| 10 | + |
| 11 | +## Walkthrough |
| 12 | + |
| 13 | +### A simple Hello-World program |
| 14 | + |
| 15 | +Let's create a simple Python program `lesson01/exercise/hello.py` that takes an argument and prints "Hello, {arg}!". |
| 16 | + |
| 17 | +``` |
| 18 | +mkdir lesson01/exercise |
| 19 | +touch lesson01/exercise/__init__.py |
| 20 | +``` |
| 21 | + |
| 22 | +```python |
| 23 | +# lesson01/exercise/hello.py |
| 24 | +import sys |
| 25 | + |
| 26 | +def say_hello(hello_to): |
| 27 | + hello_str = 'Hello, %s!' % hello_to |
| 28 | + print(hello_str) |
| 29 | + |
| 30 | +assert len(sys.argv) == 2 |
| 31 | + |
| 32 | +hello_to = sys.argv[1] |
| 33 | +say_hello(hello_to) |
| 34 | +``` |
| 35 | + |
| 36 | +Run it: |
| 37 | +``` |
| 38 | +$ python ./lesson01/hello.py Bryan |
| 39 | +Hello, Bryan! |
| 40 | +``` |
| 41 | + |
| 42 | +### Create a trace |
| 43 | + |
| 44 | +A trace is a directed acyclic graph of spans. A span is a logical representation of some work done in your application. |
| 45 | +Each span has these minimum attributes: an operation name, a start time, and a finish time. |
| 46 | + |
| 47 | +Let's create a trace that consists of just a single span. To do that we need an instance of the `opentracing.Tracer`. |
| 48 | +We can use a global instance stored in `opentracing.tracer`. |
| 49 | + |
| 50 | +```python |
| 51 | +import opentracing |
| 52 | + |
| 53 | +tracer = opentracing.tracer |
| 54 | + |
| 55 | +def say_hello(hello_to): |
| 56 | + span = tracer.start_span('say-hello') |
| 57 | + hello_str = 'Hello, %s!' % hello_to |
| 58 | + print(hello_str) |
| 59 | + span.finish() |
| 60 | +``` |
| 61 | + |
| 62 | +We are using the following basic features of the OpenTracing API: |
| 63 | + * a `tracer` instance is used to start new spans via `start_span` function |
| 64 | + * each `span` is given an _operation name_, `'say-hello'` in this case |
| 65 | + * each `span` must be finished by calling its `finish()` function |
| 66 | + * the start and end timestamps of the span will be captured automatically by the tracer implementation |
| 67 | + |
| 68 | +However, calling `finish()` manually is a bit tedious, we can use span as a context manager instead: |
| 69 | + |
| 70 | +```python |
| 71 | +def say_hello(hello_to): |
| 72 | + with tracer.start_span('say-hello') as span: |
| 73 | + hello_str = 'Hello, %s!' % hello_to |
| 74 | + print(hello_str) |
| 75 | +``` |
| 76 | + |
| 77 | +If we run this program, we will see no difference, and no traces in the tracing UI. |
| 78 | +That's because the variable `opentracing.tracer` points to a no-op tracer by default. |
| 79 | + |
| 80 | +### Initialize a real tracer |
| 81 | + |
| 82 | +Let's create an instance of a real tracer, such as Jaeger (http://github.com/uber/jaeger-client-python). |
| 83 | + |
| 84 | +```python |
| 85 | +import logging |
| 86 | +from jaeger_client import Config |
| 87 | + |
| 88 | + |
| 89 | +def init_tracer(service): |
| 90 | + logging.getLogger('').handlers = [] |
| 91 | + logging.basicConfig(format='%(message)s', level=logging.DEBUG) |
| 92 | + |
| 93 | + config = Config( |
| 94 | + config={ |
| 95 | + 'sampler': { |
| 96 | + 'type': 'const', |
| 97 | + 'param': 1, |
| 98 | + }, |
| 99 | + 'logging': True, |
| 100 | + }, |
| 101 | + service_name=service, |
| 102 | + ) |
| 103 | + |
| 104 | + # this call also sets opentracing.tracer |
| 105 | + return config.initialize_tracer() |
| 106 | +``` |
| 107 | + |
| 108 | +To use this instance, let's change the main function: |
| 109 | + |
| 110 | +```python |
| 111 | +tracer = init_tracer('hello-world') |
| 112 | +``` |
| 113 | + |
| 114 | +Note that we are passing a string `'hello-world'` to the init method. It is used to mark all spans emitted by |
| 115 | +the tracer as originating from a `hello-world` service. |
| 116 | + |
| 117 | +There's one more thing we need to do. Jaeger Tracer is primarily designed for long-running server processes, |
| 118 | +so it has an internal buffer of spans that is flushed by a background thread. Since our program exists immediately, |
| 119 | +it may not have time to flush the spans to Jaeger backend. Let's add the following to the end of `hello.py`: |
| 120 | + |
| 121 | +``` |
| 122 | +# yield to IOLoop to flush the spans |
| 123 | +time.sleep(2) |
| 124 | +tracer.close() |
| 125 | +``` |
| 126 | + |
| 127 | +If we run the program now, we should see a span logged: |
| 128 | + |
| 129 | +``` |
| 130 | +$ python -m lesson01.exercise.hello Bryan |
| 131 | +Initializing Jaeger Tracer with UDP reporter |
| 132 | +Using sampler ConstSampler(True) |
| 133 | +opentracing.tracer initialized to <jaeger_client.tracer.Tracer object at 0x110342f10>[app_name=hello-world] |
| 134 | +Hello, Bryan! |
| 135 | +Reporting span 5d42508ffcc40cc1:5d42508ffcc40cc1:0:1 hello-world.say-hello |
| 136 | +``` |
| 137 | + |
| 138 | +If you have Jaeger backend running, you should be able to see the trace in the UI. |
| 139 | + |
| 140 | +### Annotate the Trace with Tags and Logs |
| 141 | + |
| 142 | +Right now the trace we created is very basic. If we call our program with argument `Susan` |
| 143 | +instead of `Bryan`, the resulting traces will be nearly identical. It would be nice if we could |
| 144 | +capture the program arguments in the traces to distinguish them. |
| 145 | + |
| 146 | +One naive way is to use the string `"Hello, Bryan!"` as the _operation name_ of the span, instead of `"say-hello"`. |
| 147 | +However, such practice is highly discouraged in distributed tracing, because the operation name is meant to |
| 148 | +represent a _class of spans_, rather than a unique instance. For example, in Jaeger UI you can select the |
| 149 | +operation name from a dropdown when searching for traces. It would be very bad user experience if we ran the |
| 150 | +program to say hello to a 1000 people and the dropdown then contained 1000 entries. Another reason for choosing |
| 151 | +more general operation names is to allow the tracing systems to do aggregations. For example, Jaeger tracer |
| 152 | +has an option of emitting metrics for all the traffic going through the application. Having a unique |
| 153 | +operation name for each span would make the metrics useless. |
| 154 | + |
| 155 | +The recommended solution is to annotate spans with tags or logs. A span _tag_ is a key-value pair that provides |
| 156 | +certain metadata about the span. A span _log_ is pretty much the same as a regular log statement, it contains |
| 157 | +a timestamp and some data. |
| 158 | + |
| 159 | +When should we use tags vs. logs? The tags are meant to describe attributes of the span that apply |
| 160 | +to the whole duration of the span. For example, if a span represents an HTTP request, then the URL of the |
| 161 | +request should be recorded as a tag because it does not make sense to think of the URL as something |
| 162 | +that's only relevant at different points in time on the span. On the other hand, if the server responded |
| 163 | +with a redirect URL, logging it would make more sense since there is a clear timestamp associated with such |
| 164 | +event. The OpenTracing Specification provides guidelines called [Semantic Conventions][semantic-conventions] |
| 165 | +for recommended tags and log fields. |
| 166 | + |
| 167 | +#### Using Tags |
| 168 | + |
| 169 | +In the case of `hello Bryan`, the string "Bryan" is a good candidate for a span tag, since it applies |
| 170 | +to the whole span and not to a particular moment in time. We can record it like this: |
| 171 | + |
| 172 | +```python |
| 173 | +with tracer.start_span('say-hello') as span: |
| 174 | + span.set_tag('hello-to', hello_to) |
| 175 | +``` |
| 176 | + |
| 177 | +#### Using Logs |
| 178 | + |
| 179 | +Our hello program is so simple that it's difficult to find a relevant example of a log, but let's try. |
| 180 | +Right now we're formatting the `helloStr` and then printing it. Both of these operations take certain |
| 181 | +time, so we can log their completion: |
| 182 | + |
| 183 | +```python |
| 184 | +hello_str = 'Hello, %s!' % hello_to |
| 185 | +span.log_kv({'event': 'string-format', 'value': hello_str}) |
| 186 | + |
| 187 | +print(hello_str) |
| 188 | +span.log_kv({'event': 'println'}) |
| 189 | +``` |
| 190 | + |
| 191 | +The log statements might look a bit strange if you have not previosuly worked with structured logging API. |
| 192 | +Rather than formatting a log message into a single string that is easy for humans to read, structured |
| 193 | +logging APIs encourage you to separate bits and pieces of that message into key-value pairs that can be |
| 194 | +automatically processed by log aggregation systems. The idea comes from the realization that today most |
| 195 | +logs are processed by machines rather than humans. Just [google "structured-logging"][google-logging] |
| 196 | +for many articles on this topic. |
| 197 | + |
| 198 | +The OpenTracing API for Python exposes structured logging API method `log_kv` that takes a dictionary |
| 199 | +of key-value pairs. |
| 200 | + |
| 201 | +The OpenTracing Specification also recommends all log statements to contain an `event` field that |
| 202 | +describes the overall event being logged, with other attributes of the event provided as additional fields. |
| 203 | + |
| 204 | +If you run the program with these changes, then find the trace in the UI and expand its span (by clicking on it), |
| 205 | +you will be able to see the tags and logs. |
| 206 | + |
| 207 | +## Conclusion |
| 208 | + |
| 209 | +The complete program can be found in the [solution](./solution) package. We moved the `initJaeger` |
| 210 | +helper function into its own package so that we can reuse it in the other lessons as `tracing.Init`. |
| 211 | + |
| 212 | +Next lesson: [Context and Tracing Functions](../lesson02). |
| 213 | + |
| 214 | +[semantic-conventions]: https://github.com/opentracing/specification/blob/master/semantic_conventions.md |
| 215 | +[google-logging]: https://www.google.com/search?q=structured-logging |
0 commit comments