[DO NOT MERGE] Add tracing instrumentation #289

slashmo · 2020-08-04T10:45:43Z

Very much WIP.

Closes Make BaggageContext part of AsyncHTTPClient API slashmo/gsoc-swift-tracing#46
Closes Record HTTP requests made by AsyncHTTPClient slashmo/gsoc-swift-tracing#95

swift-server-bot · 2020-08-04T10:45:45Z

Can one of the admins verify this patch?

swift-server-bot · 2020-08-04T10:45:45Z

Can one of the admins verify this patch?

swift-server-bot · 2020-08-04T10:45:45Z

Can one of the admins verify this patch?

swift-server-bot · 2020-08-04T10:45:45Z

Can one of the admins verify this patch?

slashmo · 2020-08-04T11:18:43Z

FYI, this is how a request currently looks like in my example project:

InstrumentationSystem.bootstrap(FakeTracer())

let client = HTTPClient(eventLoopGroupProvider: .createNew)
var context = BaggageContext()
// Extracted from a prior request
context.fakeTraceID = "123456789"

var request = try HTTPClient.Request(url: "https://httpbin.org/anything", method: .POST, body: .string(#"{"hello":"World"}"#))
request.headers.add(name: "Content-Type", value: "application/json")

let response = try client
    .execute(request: request, context: context)
    .wait()

In the background, FakeTracer was automatically used to create (and end) a Span, with the following attributes being set:

[
  "http.request_content_length": TracingInstrumentation.SpanAttribute.int(17),
  "http.status_code": TracingInstrumentation.SpanAttribute.int(200),
  "http.target": TracingInstrumentation.SpanAttribute.string("/anything"), 
  "http.host": TracingInstrumentation.SpanAttribute.string("httpbin.org"), 
  "http.status_text": TracingInstrumentation.SpanAttribute.string("OK"),
  "http.scheme": TracingInstrumentation.SpanAttribute.string("https"),
  "http.response_content_length": TracingInstrumentation.SpanAttribute.int(433),
  "http.method": TracingInstrumentation.SpanAttribute.string("POST")
]

It also added a trace header to the request containing the fakeTraceID.

pokryfka · 2020-08-04T14:53:40Z

Sources/AsyncHTTPClient/HTTPClient.swift

+    public func get(url: String, context: BaggageContext, deadline: NIODeadline? = nil) -> EventLoopFuture<Response> {
+        return self.execute(.GET, url: url, context: context, deadline: deadline)


for backward compatibility, the context should be optional or have default (static?) value?

No, contexts should never be defaulted to nothing/empty - that leads to fragile APIs where dropping the traces becomes the default operation, rather than doing the right thing -- keep passing along contexts. We want our APIs to help people do the right thing. Note in a same way, Go's context values must never be defaulted to empty, we're in the same boat.

It's another discussion how and when this PR will be merged though; I do strongly believe contexts must not be optional, as that leads to breaking traces accidentally (been there, done that). See discussions in https://forums.swift.org/t/server-distributed-tracing/37464/10 and the guidelines in https://github.com/slashmo/gsoc-swift-baggage-context#argument-namingpositioning

Makes sense. This will, however, affect integration in a big way.

Please see my comment about an integration branch below.

~~Sure it will, it breaks API, we're aware.~~

My wording here was not very nice, sorry about that.

What I mean that this is a PoC branch and it's breaking here. An adoption plan will be laid forward, see https://forums.swift.org/t/the-context-passing-problem/39162/27 (AHC plan incomming there)

Sources/AsyncHTTPClient/HTTPClient.swift

pokryfka · 2020-08-04T15:02:18Z

Sources/AsyncHTTPClient/HTTPClient.swift

-                                                              deadline: NIODeadline? = nil,
-                                                              logger originalLogger: Logger?) -> Task<Delegate.Response> {
-        let logger = (originalLogger ?? HTTPClient.loggingDisabled).attachingRequestInformation(request, requestID: globalRequestID.add(1))
+        // TODO: net.peer.ip / Not required, but recommended


@ktoso @slashmo could this is be propagated in baggage shared by tracers (??)

note that its typically propagated in X-Forwarded-For header

pokryfka · 2020-08-04T15:03:15Z

Awesome 👍

Sources/AsyncHTTPClient/HTTPClient.swift

pokryfka · 2020-08-04T23:25:32Z

@ktoso

do you think its possible and makes sense to create feature/instrumentation integration branch in async-http-client?

ktoso · 2020-08-04T23:42:18Z

do you think its possible and makes sense to create feature/instrumentation integration branch in async-http-client?

Maybe an experimental/tracing branch could be a good idea indeed... so people can more earily try things out as we work on this, and before it actually fully lands hm (esp since it has API impact).

WDYT @Lukasa @artemredkin @tomerd ?

ktoso · 2020-08-04T23:44:40Z

Sources/AsyncHTTPClient/HTTPClient.swift

-    public func delete(url: String, deadline: NIODeadline? = nil, logger: Logger) -> EventLoopFuture<Response> {
-        return self.execute(.DELETE, url: url, deadline: deadline, logger: logger)
+    public func delete(url: String, context: BaggageContext, deadline: NIODeadline? = nil) -> EventLoopFuture<Response> {
+        return self.execute(.DELETE, url: url, context: context, deadline: deadline)


that's an interesting question here: so... deadline was defaulted in the public API, but on execute it's not...
Technically our rules say "context last, before defaulted" so... Technically this would mean self.execute(.DELETE, url: url, deadline: deadline, context: context) I wonder if it matters / if it is worth it to be strict about this hm...

pokryfka · 2020-08-05T00:16:39Z

Sources/AsyncHTTPClient/HTTPClient.swift

+        span.attributes.http.host = request.host
+        if let requestContentLength = request.body?.length {
+            span.attributes.http.requestContentLength = requestContentLength
+        }



there is http.url attribute in OTel example

http.url "https://example.com:8080/webshop/articles/4?s=1"

I just reread the Otel definition for HTTP client spans. Your correct, the combination of host/scheme/target is not their recommended way for client spans: https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/http.md#http-client

One of the following sets of attributes is required (in order of usual preference unless for a particular web client/framework it is known that some other set is preferable for some reason; all strings must be non-empty):

http.url

http.scheme, http.host, http.target

http.scheme, net.peer.name, net.peer.port, http.target

http.scheme, net.peer.ip, net.peer.port, http.target

Therefore I'll be replacing scheme/host/target with the full url. Thanks for pointing this out 👍

Lukasa · 2020-08-05T08:25:24Z

Maybe an experimental/tracing branch could be a good idea indeed... so people can more earily try things out as we work on this, and before it actually fully lands hm (esp since it has API impact).

I'm fine with that. By the way, right now this patch doesn't just have API impact, it's API breaking. I'd like to find a way to avoid that if we can.

slashmo · 2020-08-06T14:06:26Z

I'd like to find a way to avoid that if we can.
@Lukasa

We briefly chatted about the reasoning of having it API breaking here: slashmo/gsoc-swift-baggage-context#8

Lukasa · 2020-08-06T15:30:19Z

I don't think that conversation does a good job of making the case.

ktoso · 2020-08-07T02:02:16Z

The topic is a bit deeper than "this breaks API so it's bad", it is what is the end goal we want to head towards, and if we agree on this, we can talk more how we get there. This was touched upon in various places but as Tanner just opened up https://forums.swift.org/t/the-context-passing-problem/39162 which also relates to this, perhaps we use that forums thread to discuss this again, and then decide how to roll changes into the client here -- sounds good?

I do not think the end goal should be "context is optional" that causes all kinds of headaches in "where did I drop my trace / context" that are hard to debug (been there, it's a pain), and confirmed by others in: https://forums.swift.org/t/server-distributed-tracing/37464/28?u=ktoso (last replies, and also lessons learnt from how the Go context works and is used IMO); and here where we're in agreement with Johannes that those APIs will change in the future #227 (comment)

Long story short: Yes, context parameter replaces logger parameter, because of the insistence of the "pass a logger" yet context is the actual object that has tracing metadata so so it is the actual thing that needs passing around more than a logger even, but since we also want to pass loggers, we need e.g. a composite context protocol, like designed here: slashmo/gsoc-swift-baggage-context#9 - so we can pass one parameter, and not logger + context all the time. I believe it was very much known up front with Johannes's work and merging the logger parameter that there would have to be an API breaking change once tracing/logging is "done", I talked with Johannes about this at length back then.

As mentioned above, let's first continue in the thread that Tanner kicked off, agree there and loop back here, sounds good?

ktoso · 2020-08-07T02:47:22Z

I added a do-not-merge marker, perhaps that was partially the confusion here as well? This PR is not intended to be merged as is.

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

slashmo · 2020-08-13T12:52:16Z

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

@@ -64,7 +64,8 @@ extension HTTPClientTests {
            ("testNoResponseWithIgnoreErrorForSSLUncleanShutdown", testNoResponseWithIgnoreErrorForSSLUncleanShutdown),
            ("testWrongContentLengthForSSLUncleanShutdown", testWrongContentLengthForSSLUncleanShutdown),
            ("testWrongContentLengthWithIgnoreErrorForSSLUncleanShutdown", testWrongContentLengthWithIgnoreErrorForSSLUncleanShutdown),
-            ("testEventLoopArgument", testEventLoopArgument),
+// TODO: Comment back in once failure was resolved
+//            ("testEventLoopArgument", testEventLoopArgument),


Needs investigation as it currently leads to a failing precondition. Commented out, for now, to be able to run the full test-suite.

slashmo · 2020-08-13T12:55:02Z

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

@@ -88,7 +89,8 @@ extension HTTPClientTests {
            ("testUncleanShutdownCancelsTasks", testUncleanShutdownCancelsTasks),
            ("testDoubleShutdown", testDoubleShutdown),
            ("testTaskFailsWhenClientIsShutdown", testTaskFailsWhenClientIsShutdown),
-            ("testRaceNewRequestsVsShutdown", testRaceNewRequestsVsShutdown),
+// TODO: Comment back in once failure was resolved
+//            ("testRaceNewRequestsVsShutdown", testRaceNewRequestsVsShutdown),


Needs investigation as it currently leads to a failing assertion. Commented out, for now, to be able to run the full test-suite.

pokryfka · 2020-08-15T08:28:39Z

Sources/AsyncHTTPClient/Utils.swift

+extension SpanStatus {
+    /// Map status code to canonical code according to OTel spec
+    ///
+    /// - SeeAlso: https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/http.md#status
+    init(_ responseStatus: HTTPResponseStatus) {
+        switch responseStatus.code {


I think mapping of HTTP status code (UInt) to SpanStatus is very much reusable and as such should be provided in TracingInstrumentation, sth like

SpanStatus(code: UInt, message: String?)

otherwise each library making HTTP calls and not using AHC will need to map it on its own

Hah, this reminded me I had an not submitted review here, yeah this seems like a good candidate to move up into OpenTelemetryInstrumentationSupport/OpenTelemetrySemanticConventions 👍

Or not such a good candidate after all 😁👉 slashmo/gsoc-swift-tracing#134

ktoso

(seems I forgot to hit submit on a review here I did a while ago, submitted)

ktoso · 2020-08-13T02:39:26Z

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

@@ -88,7 +88,7 @@ extension HTTPClientTests {
            ("testUncleanShutdownCancelsTasks", testUncleanShutdownCancelsTasks),
            ("testDoubleShutdown", testDoubleShutdown),
            ("testTaskFailsWhenClientIsShutdown", testTaskFailsWhenClientIsShutdown),
-            ("testRaceNewRequestsVsShutdown", testRaceNewRequestsVsShutdown),
+//            ("testRaceNewRequestsVsShutdown", testRaceNewRequestsVsShutdown),


ktoso · 2020-08-13T12:58:59Z

Sources/AsyncHTTPClient/Utils.swift

+            self = SpanStatus(canonicalCode: .unknown, message: responseStatus.reasonPhrase)
+        }
+    }
+}


I guess this should move to OpenTelemetryInstrumentationSupport?

Btw, been thinking if that should be called OpenTelemetrySemanticConventions?

ktoso · 2020-08-20T01:34:54Z

Just as a heads up, the main development branch has been changed to main, following the Swift policy on this.

This PR has been re-targeted to main and should just work. However when performing rebases etc please keep this in mind -- you may want to fetch the main branch and rebase onto the main branch from now on since master is not up-to-date anymore and is going to be deleted shortly.

pokryfka · 2020-08-27T12:03:21Z

Tests/AsyncHTTPClientTests/HTTPClientTests.swift

+        let span = TestSpan(operationName: operationName,
+                            kind: kind,
+                            startTimestamp: timestamp,
+                            context: context.baggage)
+        recordedSpans.append(span)
+        return span
+    }


the context should be updated, see slashmo/gsoc-swift-tracing#126 (comment)

pokryfka · 2020-08-27T14:27:32Z

Sources/AsyncHTTPClient/HTTPClient.swift

+        var request = request
+        InstrumentationSystem.instrument.inject(span.context.baggage, into: &request.headers, using: HTTPHeadersInjector())
+
+        let logger = context.logger.attachingRequestInformation(request, requestID: globalRequestID.add(1))


@ktoso @slashmo

this updates an instance of logger,
should it not set requestId in baggage (which then would be used to setup logger)?

otherwise the requestId metadata will be lost in the logger passed via context

(copied from soto-project/soto-core#348 (comment))

how about sth like:

private struct RequestMetadata: CustomStringConvertible { var requestId: Int var service: String var operation: String var description: String { "aws-request-id=\(requestId) aws-service=\(service) aws-operation=\(operation)" } } private enum RequestKey: BaggageContextKey { typealias Value = RequestMetadata var name: String { "AWSRequest" } }

then updating the baggage like:

context.baggage[RequestKey.self] = RequestMetadata(requestId: Self.globalRequestID.add(1), service: serviceConfig.service, operation: "signURL")

instead of updating the logger directly (current):

context.logger = context.logger.attachingRequestId(Self.globalRequestID.add(1), operation: "signURL", service: serviceConfig.service)

pokryfka reviewed Aug 4, 2020

View reviewed changes

Sources/AsyncHTTPClient/HTTPClient.swift Outdated Show resolved Hide resolved

pokryfka reviewed Aug 4, 2020

View reviewed changes

Sources/AsyncHTTPClient/HTTPClient.swift Show resolved Hide resolved

pokryfka reviewed Aug 4, 2020

View reviewed changes

Sources/AsyncHTTPClient/HTTPClient.swift Show resolved Hide resolved

ktoso reviewed Aug 4, 2020

View reviewed changes

pokryfka reviewed Aug 5, 2020

View reviewed changes

ktoso changed the title ~~Add tracing instrumentation~~ [DO NOT MERGE] Add tracing instrumentation Aug 7, 2020

slashmo force-pushed the feature/instrumentation branch from 4d519b6 to aee6ed8 Compare August 13, 2020 10:26

slashmo commented Aug 13, 2020

View reviewed changes

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift Show resolved Hide resolved

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift Show resolved Hide resolved

slashmo commented Aug 13, 2020

View reviewed changes

pokryfka reviewed Aug 15, 2020

View reviewed changes

ktoso reviewed Aug 17, 2020

View reviewed changes

ktoso changed the base branch from master to main August 20, 2020 01:30

pokryfka mentioned this pull request Aug 27, 2020

Instrument AWSClient WIP soto-project/soto-core#348

Closed

pokryfka reviewed Aug 27, 2020

View reviewed changes

pokryfka mentioned this pull request Aug 28, 2020

Instrument AWS SDK Swift pokryfka/aws-xray-sdk-swift#19

Open

5 tasks

slashmo force-pushed the feature/instrumentation branch 3 times, most recently from 45e6adf to 577f205 Compare October 1, 2020 09:38

slashmo added 11 commits October 1, 2020 11:40

Pass BaggageContext through public API

d0fac6c

[WIP] Start Span upon request execution

5ae42f1

Set status code & text on request span

7ca5a97

Set request & response content length on request span

6853807

Don't use metadata to document BaggageContext 📖

af82915

Update to BaggageContext 0.2.0

e9a880f

[WIP] Set SpanStatus based on response code

01672ed

Comment on commented out tests

63d0d44

Use latest swift-tracing commit

0aa7e5c

Use updated Span API for TestSpan

0946749

Update Tracing package 📦

1a98075

slashmo force-pushed the feature/instrumentation branch from 577f205 to 1a98075 Compare October 1, 2020 09:42

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[DO NOT MERGE] Add tracing instrumentation #289

[DO NOT MERGE] Add tracing instrumentation #289

slashmo commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

slashmo commented Aug 4, 2020

pokryfka Aug 4, 2020 •

edited

Loading

ktoso Aug 4, 2020

pokryfka Aug 4, 2020

ktoso Aug 4, 2020 •

edited

Loading

pokryfka Aug 4, 2020

pokryfka Aug 5, 2020

pokryfka commented Aug 4, 2020

pokryfka commented Aug 4, 2020

ktoso commented Aug 4, 2020

ktoso Aug 4, 2020

pokryfka Aug 5, 2020

slashmo Aug 21, 2020

Lukasa commented Aug 5, 2020

slashmo commented Aug 6, 2020

Lukasa commented Aug 6, 2020

ktoso commented Aug 7, 2020 •

edited

Loading

ktoso commented Aug 7, 2020

slashmo Aug 13, 2020 •

edited

Loading

slashmo Aug 13, 2020

pokryfka Aug 15, 2020

ktoso Aug 17, 2020

slashmo Aug 19, 2020

ktoso left a comment

ktoso Aug 13, 2020

ktoso Aug 13, 2020

ktoso commented Aug 20, 2020

pokryfka Aug 27, 2020

pokryfka Aug 27, 2020 •

edited

Loading

pokryfka Aug 27, 2020 •

edited

Loading

		public func get(url: String, context: BaggageContext, deadline: NIODeadline? = nil) -> EventLoopFuture<Response> {
		return self.execute(.GET, url: url, context: context, deadline: deadline)

[DO NOT MERGE] Add tracing instrumentation #289

Are you sure you want to change the base?

[DO NOT MERGE] Add tracing instrumentation #289

Conversation

slashmo commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

swift-server-bot commented Aug 4, 2020

slashmo commented Aug 4, 2020

pokryfka Aug 4, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ktoso Aug 4, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pokryfka commented Aug 4, 2020

pokryfka commented Aug 4, 2020

ktoso commented Aug 4, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Lukasa commented Aug 5, 2020

slashmo commented Aug 6, 2020

Lukasa commented Aug 6, 2020

ktoso commented Aug 7, 2020 • edited Loading

ktoso commented Aug 7, 2020

slashmo Aug 13, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ktoso left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ktoso commented Aug 20, 2020

Choose a reason for hiding this comment

pokryfka Aug 27, 2020 • edited Loading

Choose a reason for hiding this comment

pokryfka Aug 27, 2020 • edited Loading

Choose a reason for hiding this comment

pokryfka Aug 4, 2020 •

edited

Loading

ktoso Aug 4, 2020 •

edited

Loading

ktoso commented Aug 7, 2020 •

edited

Loading

slashmo Aug 13, 2020 •

edited

Loading

pokryfka Aug 27, 2020 •

edited

Loading

pokryfka Aug 27, 2020 •

edited

Loading