|
| 1 | +# Lesson 3 - Tracing RPC Requests |
| 2 | + |
| 3 | +## Objectives |
| 4 | + |
| 5 | +Learn how to: |
| 6 | + |
| 7 | +* Trace a transaction across more than one microservice |
| 8 | +* Pass the context between processes using `Inject` and `Extract` |
| 9 | +* Apply OpenTracing-recommended tags |
| 10 | + |
| 11 | +## Walkthrough |
| 12 | + |
| 13 | +### Hello-World Microservice App |
| 14 | + |
| 15 | +To save you some typing, we are going to start this lesson with a partial solution |
| 16 | +available in the [exercise](./exercise) package. We are still working with the same |
| 17 | +Hello World application, except that the `formatString` and `printHello` functions |
| 18 | +are now rewritten as RPC calls to two downstream services, `formatter` and `publisher`. |
| 19 | +The package is organized as follows: |
| 20 | + |
| 21 | + * `Hello.java` is a copy from Lesson 2 modified to make HTTP calls |
| 22 | + * `Formatter.java` is a Dropwizard-based HTTP server that responds to a request like |
| 23 | + `GET 'http://localhost:8081/format?helloTo=Bryan'` and returns `"Hello, Bryan!"` string |
| 24 | + * `Publisher.java` is another HTTP server that responds to requests like |
| 25 | + `GET 'http://localhost:8082/publish?helloStr=hi%20there'` and prints `"hi there"` string to stdout. |
| 26 | + |
| 27 | +To test it out, run the formatter and publisher services in separate terminals |
| 28 | + |
| 29 | +``` |
| 30 | +$ ./run.sh lesson03.exercise.Formatter server |
| 31 | +$ ./run.sh lesson03.exercise.Publisher server |
| 32 | +``` |
| 33 | + |
| 34 | +Execute an HTTP request against the formatter: |
| 35 | + |
| 36 | +``` |
| 37 | +$ curl 'http://localhost:8081/format?helloTo=Bryan' |
| 38 | +Hello, Bryan!% |
| 39 | +``` |
| 40 | + |
| 41 | +Execute and HTTP request against the publisher: |
| 42 | + |
| 43 | +``` |
| 44 | +$ curl 'http://localhost:8082/publish?helloStr=hi%20there' |
| 45 | +published |
| 46 | +``` |
| 47 | + |
| 48 | +The publisher stdout will show `"hi there"`. |
| 49 | + |
| 50 | +Finally, if we run the client app as we did in the previous lessons: |
| 51 | + |
| 52 | +``` |
| 53 | +$ ./run.sh lesson03.exercise.Hello Bryan |
| 54 | +2017/09/24 21:43:33 Initializing logging reporter |
| 55 | +2017/09/24 21:43:33 Reporting span 7af6719d92c3df6d:5d10cdd1a9cf004a:7af6719d92c3df6d:1 |
| 56 | +2017/09/24 21:43:33 Reporting span 7af6719d92c3df6d:538a7bfd34893922:7af6719d92c3df6d:1 |
| 57 | +2017/09/24 21:43:33 Reporting span 7af6719d92c3df6d:7af6719d92c3df6d:0:1 |
| 58 | +``` |
| 59 | + |
| 60 | +We will see the `publisher` printing the line `"Hello, Bryan!"`. |
| 61 | + |
| 62 | +### Inter-Process Context Propagation |
| 63 | + |
| 64 | +Since the only change we made in the `Hello.java` app was to replace two operations with HTTP calls, |
| 65 | +the tracing story remains the same - we get a trace with three spans, all from `hello-world` service. |
| 66 | +But now we have two more microservices participating in the transaction and we want to see them |
| 67 | +in the trace as well. In order to continue the trace over the process boundaries and RPC calls, |
| 68 | +we need a way to propagate the span context over the wire. The OpenTracing API provides two functions |
| 69 | +in the Tracer interface to do that, `inject(spanContext, format, carrier)` and `extract(format, carrier)`. |
| 70 | + |
| 71 | +The `format` parameter refers to one of the three standard encodings the OpenTracing API defines: |
| 72 | + * `TEXT_MAP` where span context is encoded as a collection of string key-value pairs, |
| 73 | + * `BINARY` where span context is encoded as an opaque byte array, |
| 74 | + * `HTTP_HEADERS`, which is similar to `TEXT_MAP` except that the keys must be safe to be used as HTTP headers. |
| 75 | + |
| 76 | +The `carrier` is an abstraction over the underlying RPC framework. For example, a carrier for `TEXT_MAP` |
| 77 | +format is an interface that allows the tracer to write key-value pairs via `put(key, value)` method, |
| 78 | +while a carrier for Binary format is simply a `ByteBuffer`. |
| 79 | + |
| 80 | +The tracing instrumentation uses `inject` and `extract` to pass the span context through the RPC calls. |
| 81 | + |
| 82 | +### Instrumenting the Client |
| 83 | + |
| 84 | +In the `formatString` function we already create a child span. In order to pass its context over the HTTP |
| 85 | +request we need to call `tracer.inject` before building the HTTP request: |
| 86 | + |
| 87 | +```java |
| 88 | +Tags.SPAN_KIND.set(tracer.activeSpan(), Tags.SPAN_KIND_CLIENT); |
| 89 | +Tags.HTTP_METHOD.set(tracer.activeSpan(), "GET"); |
| 90 | +Tags.HTTP_URL.set(tracer.activeSpan(), url.toString()); |
| 91 | +tracer.inject(tracer.activeSpan().context(), Builtin.HTTP_HEADERS, new RequestBuilderCarrier(requestBuilder)); |
| 92 | +``` |
| 93 | + |
| 94 | +In this case the `carrier` is HTTP request headers object, which we adapt to the carrier API |
| 95 | +by wrapping in `RequestBuilderCarrier` helper class. |
| 96 | + |
| 97 | +```java |
| 98 | +private static class RequestBuilderCarrier implements io.opentracing.propagation.TextMap { |
| 99 | + private final Request.Builder builder; |
| 100 | + |
| 101 | + RequestBuilderCarrier(Request.Builder builder) { |
| 102 | + this.builder = builder; |
| 103 | + } |
| 104 | + |
| 105 | + @Override |
| 106 | + public Iterator<Entry<String, String>> iterator() { |
| 107 | + throw new UnsupportedOperationException("carrier is write-only"); |
| 108 | + } |
| 109 | + |
| 110 | + @Override |
| 111 | + public void put(String key, String value) { |
| 112 | + builder.addHeader(key, value); |
| 113 | + } |
| 114 | +} |
| 115 | +``` |
| 116 | + |
| 117 | +Notice that we also add a couple additional tags to the span with some metadata about the HTTP request, |
| 118 | +and we mark the span with a `span.kind=client` tag, as recommended by the OpenTracing |
| 119 | +[Semantic Conventions][semantic-conventions]. There are other tags we could add. |
| 120 | + |
| 121 | +### Instrumenting the Servers |
| 122 | + |
| 123 | +Our servers are currently not instrumented for tracing. We need to do the following: |
| 124 | + |
| 125 | +#### Add some imports |
| 126 | + |
| 127 | +```java |
| 128 | +import io.opentracing.ActiveSpan; |
| 129 | +import io.opentracing.Tracer; |
| 130 | +import lib.Tracing; |
| 131 | +``` |
| 132 | + |
| 133 | +#### Create an instance of a Tracer, similar to how we did it in `Hello.java` |
| 134 | + |
| 135 | +Add a member variable and a constructor to the Formatter: |
| 136 | + |
| 137 | +```java |
| 138 | +private final Tracer tracer; |
| 139 | + |
| 140 | +private Formatter(Tracer tracer) { |
| 141 | + this.tracer = tracer; |
| 142 | +} |
| 143 | +``` |
| 144 | + |
| 145 | +Replace the call to `Formatter.run()` with this: |
| 146 | + |
| 147 | +```java |
| 148 | +Tracer tracer = Tracing.init("formatter"); |
| 149 | +new Formatter(tracer).run(args); |
| 150 | +``` |
| 151 | + |
| 152 | +#### Extract the span context from the incoming request using `tracer.extract` |
| 153 | + |
| 154 | +First, add a helper function: |
| 155 | + |
| 156 | +```java |
| 157 | +public static ActiveSpan startServerSpan(Tracer tracer, javax.ws.rs.core.HttpHeaders httpHeaders, |
| 158 | + String operationName) { |
| 159 | + // format the headers for extraction |
| 160 | + MultivaluedMap<String, String> rawHeaders = httpHeaders.getRequestHeaders(); |
| 161 | + final HashMap<String, String> headers = new HashMap<String, String>(); |
| 162 | + for (String key : rawHeaders.keySet()) { |
| 163 | + headers.put(key, rawHeaders.get(key).get(0)); |
| 164 | + } |
| 165 | + |
| 166 | + Tracer.SpanBuilder spanBuilder; |
| 167 | + try { |
| 168 | + SpanContext parentSpan = tracer.extract(Format.Builtin.HTTP_HEADERS, new TextMapExtractAdapter(headers)); |
| 169 | + if (parentSpan == null) { |
| 170 | + spanBuilder = tracer.buildSpan(operationName); |
| 171 | + } else { |
| 172 | + spanBuilder = tracer.buildSpan(operationName).asChildOf(parentSpan); |
| 173 | + } |
| 174 | + } catch (IllegalArgumentException e) { |
| 175 | + spanBuilder = tracer.buildSpan(operationName); |
| 176 | + } |
| 177 | + return spanBuilder.withTag(Tags.SPAN_KIND.getKey(), Tags.SPAN_KIND_SERVER).startActive(); |
| 178 | +} |
| 179 | +``` |
| 180 | + |
| 181 | +The logic here is similar to the client side instrumentation, except that we are using `tracer.extract` |
| 182 | +and tagging the span as `span.kind=server`. Instead of using a dedicated adapter class to convert |
| 183 | +JAXRS `HttpHeaders` type into `io.opentracing.propagation.TextMap`, we are copying the headers to a plain |
| 184 | +`HashMap<String, String>` and using a standard adapter `TextMapExtractAdapter`. |
| 185 | + |
| 186 | +Now change the `FormatterResource` handler method to use `startServerSpan`: |
| 187 | + |
| 188 | +```java |
| 189 | +@GET |
| 190 | +public String format(@QueryParam("helloTo") String helloTo, @Context HttpHeaders httpHeaders) { |
| 191 | + try (ActiveSpan span = Tracing.startServerSpan(tracer, httpHeaders, "format")) { |
| 192 | + String helloStr = String.format("Hello, %s!", helloTo); |
| 193 | + span.log(ImmutableMap.of("event", "string-format", "value", helloStr)); |
| 194 | + return helloStr; |
| 195 | + } |
| 196 | +} |
| 197 | +``` |
| 198 | + |
| 199 | +### Take It For s Spin |
| 200 | + |
| 201 | +As before, first run the `formatter` and `publisher` apps in separate terminals. |
| 202 | +Then run the `client/hello.go`. You should see the outputs like this: |
| 203 | + |
| 204 | +``` |
| 205 | +# client |
| 206 | +$ ./run.sh lesson03.exercise.Hello Bryan |
| 207 | +INFO com.uber.jaeger.Configuration - Initialized tracer=Tracer(...) |
| 208 | +INFO com.uber.jaeger.reporters.LoggingReporter - Span reported: 5fe2d9de96c3887a:72910f6018b1bd09:5fe2d9de96c3887a:1 - formatString |
| 209 | +INFO com.uber.jaeger.reporters.LoggingReporter - Span reported: 5fe2d9de96c3887a:62d73167c129ecd7:5fe2d9de96c3887a:1 - printHello |
| 210 | +INFO com.uber.jaeger.reporters.LoggingReporter - Span reported: 5fe2d9de96c3887a:5fe2d9de96c3887a:0:1 - say-hello |
| 211 | +
|
| 212 | +# formatter |
| 213 | +$ ./run.sh lesson03.exercise.Formatter server |
| 214 | +[skip noise] |
| 215 | +INFO org.eclipse.jetty.server.Server: Started @3968ms |
| 216 | +INFO com.uber.jaeger.reporters.LoggingReporter: Span reported: 5fe2d9de96c3887a:b73ff97ea68a36f8:72910f6018b1bd09:1 - format |
| 217 | +127.0.0.1 - - "GET /format?helloTo=Bryan HTTP/1.1" 200 13 "-" "okhttp/3.9.0" 3 |
| 218 | +
|
| 219 | +# publisher |
| 220 | +$ ./run.sh lesson03.exercise.Publisher server |
| 221 | +[skip noise] |
| 222 | +INFO org.eclipse.jetty.server.Server: Started @3388ms |
| 223 | +Hello, Bryan! |
| 224 | +INFO com.uber.jaeger.reporters.LoggingReporter: Span reported: 5fe2d9de96c3887a:4a2c39e462cb2a92:62d73167c129ecd7:1 - publish |
| 225 | +127.0.0.1 - - "GET /publish?helloStr=Hello,%20Bryan! HTTP/1.1" 200 9 "-" "okhttp/3.9.0" 80 |
| 226 | +``` |
| 227 | + |
| 228 | +Note how all recorded spans show the same trace ID `5fe2d9de96c3887a`. This is a sign |
| 229 | +of correct instrumentation. It is also a very useful debugging approach when something |
| 230 | +is wrong with tracing. A typical error is to miss the context propagation somwehere, |
| 231 | +either in-process or inter-process, which results in different trace IDs and broken |
| 232 | +traces. |
| 233 | + |
| 234 | +If we open this trace in the UI, we should see all five spans. |
| 235 | + |
| 236 | + |
| 237 | + |
| 238 | +## Conclusion |
| 239 | + |
| 240 | +The complete program can be found in the [solution](./solution) package. |
| 241 | + |
| 242 | +Next lesson: [Baggage](../lesson04). |
| 243 | + |
| 244 | +## Extra Credit |
| 245 | + |
| 246 | +Adding manual instrumentation to Dropwizard and okhttp like we did is tedious. Fortunately, we don't |
| 247 | +need to do that because that instrumentation itself is open source. For an extra credit, try to use |
| 248 | +modules from http://github.com/opentracing-contrib to avoid instrumenting your code manually. |
| 249 | + |
| 250 | +[semantic-conventions]: https://github.com/opentracing/specification/blob/master/semantic_conventions.md |
0 commit comments