Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

add httptrace option #788

Merged
merged 20 commits into from Aug 5, 2020
Merged

add httptrace option #788

merged 20 commits into from Aug 5, 2020

Conversation

graphaelli
Copy link
Member

@graphaelli graphaelli commented Jul 19, 2020

image

module/apmhttp/client.go Outdated Show resolved Hide resolved
@apmmachine
Copy link
Collaborator

apmmachine commented Jul 19, 2020

💔 Build Failed

Pipeline View Test View Changes Artifacts preview

Expand to view the summary

Build stats

  • Build Cause: [Pull request #788 updated]

  • Start Time: 2020-08-04T16:24:22.069+0000

  • Duration: 13 min 50 sec

Test stats 🧪

Test Results
Failed 0
Passed 4785
Skipped 137
Total 4922

Steps errors

Expand to view the steps failures

  • Name: Build

    • Description: ./scripts/jenkins/build.sh

    • Duration: 2 min 5 sec

    • Start Time: 2020-08-04T16:30:46.915+0000

    • log

  • Name: Build

    • Description: ./scripts/jenkins/build.sh

    • Duration: 2 min 51 sec

    • Start Time: 2020-08-04T16:33:06.622+0000

    • log

  • Name: Build

    • Description: ./scripts/jenkins/build.sh

    • Duration: 2 min 0 sec

    • Start Time: 2020-08-04T16:35:09.722+0000

    • log

  • Name: Error signal

    • Description:

    • Duration: 0 min 0 sec

    • Start Time: 2020-08-04T16:37:09.435+0000

    • log

Log output

Expand to view the last 100 lines of log output

[2020-08-04T16:36:32.410Z] github.com/prometheus/client_golang/prometheus/promhttp
[2020-08-04T16:36:32.410Z] golang.org/x/net/trace
[2020-08-04T16:36:32.983Z] github.com/jinzhu/gorm/dialects/postgres
[2020-08-04T16:36:32.983Z] go.elastic.co/apm/module/apmsql/pq
[2020-08-04T16:36:32.983Z] google.golang.org/grpc/backoff
[2020-08-04T16:36:32.983Z] google.golang.org/grpc/internal/grpclog
[2020-08-04T16:36:32.983Z] google.golang.org/grpc/grpclog
[2020-08-04T16:36:32.983Z] go.elastic.co/apm/module/apmgorm/dialects/postgres
[2020-08-04T16:36:32.983Z] google.golang.org/grpc/attributes
[2020-08-04T16:36:32.983Z] google.golang.org/grpc/credentials/internal
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/serviceconfig
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/connectivity
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/internal/credentials
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/internal
[2020-08-04T16:36:33.245Z] # google.golang.org/grpc/internal/credentials
[2020-08-04T16:36:33.245Z] ../../google.golang.org/grpc/internal/credentials/spiffe.go:34:70: state.PeerCertificates[0].URIs undefined (type *x509.Certificate has no field or method URIs)
[2020-08-04T16:36:33.245Z] ../../google.golang.org/grpc/internal/credentials/spiffe.go:38:47: state.PeerCertificates[0].URIs undefined (type *x509.Certificate has no field or method URIs)
[2020-08-04T16:36:33.245Z] ../../google.golang.org/grpc/internal/credentials/spiffe.go:56:35: state.PeerCertificates[0].URIs undefined (type *x509.Certificate has no field or method URIs)
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/metadata
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/internal/grpcrand
[2020-08-04T16:36:33.245Z] github.com/astaxie/beego
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/codes
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/encoding
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/internal/backoff
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/encoding/proto
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/internal/balancerload
[2020-08-04T16:36:33.245Z] google.golang.org/grpc/binarylog/grpc_binarylog_v1
[2020-08-04T16:36:33.245Z] google.golang.org/genproto/googleapis/rpc/status
[2020-08-04T16:36:33.507Z] google.golang.org/grpc/internal/buffer
[2020-08-04T16:36:33.507Z] google.golang.org/grpc/internal/status
[2020-08-04T16:36:33.507Z] google.golang.org/grpc/internal/envconfig
[2020-08-04T16:36:33.507Z] google.golang.org/grpc/internal/grpcsync
[2020-08-04T16:36:33.772Z] golang.org/x/net/http/httpguts
[2020-08-04T16:36:33.772Z] google.golang.org/grpc/status
[2020-08-04T16:36:33.772Z] golang.org/x/net/http2/hpack
[2020-08-04T16:36:33.772Z] google.golang.org/grpc/internal/syscall
[2020-08-04T16:36:33.772Z] google.golang.org/grpc/keepalive
[2020-08-04T16:36:34.034Z] google.golang.org/grpc/stats
[2020-08-04T16:36:34.034Z] golang.org/x/net/http2
[2020-08-04T16:36:34.034Z] google.golang.org/grpc/tap
[2020-08-04T16:36:34.034Z] github.com/julienschmidt/httprouter
[2020-08-04T16:36:34.296Z] go.elastic.co/apm/module/apmhttprouter
[2020-08-04T16:36:34.296Z] github.com/aws/aws-lambda-go/lambda/messages
[2020-08-04T16:36:34.296Z] github.com/aws/aws-lambda-go/lambdacontext
[2020-08-04T16:36:34.558Z] go.elastic.co/apm/module/apmlambda
[2020-08-04T16:36:34.558Z] github.com/sirupsen/logrus
[2020-08-04T16:36:34.819Z] go.elastic.co/apm/module/apmbeego
[2020-08-04T16:36:35.081Z] go.elastic.co/apm/module/apmmongo
[2020-08-04T16:36:35.081Z] github.com/urfave/negroni
[2020-08-04T16:36:35.081Z] go.elastic.co/apm/module/apmlogrus
[2020-08-04T16:36:35.081Z] github.com/opentracing/opentracing-go/log
[2020-08-04T16:36:35.343Z] github.com/opentracing/opentracing-go
[2020-08-04T16:36:35.343Z] go.elastic.co/apm/module/apmnegroni
[2020-08-04T16:36:35.343Z] go.elastic.co/apm/module/apmprometheus
[2020-08-04T16:36:35.343Z] go.elastic.co/apm/module/apmot
[2020-08-04T16:36:35.343Z] github.com/gomodule/redigo/redis
[2020-08-04T16:36:35.605Z] github.com/emicklei/go-restful/log
[2020-08-04T16:36:35.605Z] github.com/emicklei/go-restful
[2020-08-04T16:36:35.866Z] go.uber.org/atomic
[2020-08-04T16:36:35.866Z] go.uber.org/multierr
[2020-08-04T16:36:35.866Z] go.uber.org/zap/buffer
[2020-08-04T16:36:36.127Z] go.uber.org/zap/internal/bufferpool
[2020-08-04T16:36:36.127Z] go.uber.org/zap/internal/color
[2020-08-04T16:36:36.127Z] go.uber.org/zap/internal/exit
[2020-08-04T16:36:36.127Z] go.elastic.co/apm/module/apmredigo
[2020-08-04T16:36:36.127Z] go.uber.org/zap/zapcore
[2020-08-04T16:36:36.127Z] github.com/rs/zerolog/internal/json
[2020-08-04T16:36:36.389Z] go.elastic.co/apm/module/apmrestful
[2020-08-04T16:36:36.389Z] github.com/rs/zerolog
[2020-08-04T16:36:36.389Z] github.com/rs/zerolog/pkgerrors
[2020-08-04T16:36:36.389Z] go.elastic.co/apm/scripts
[2020-08-04T16:36:36.389Z] go.elastic.co/apm/scripts/genmod
[2020-08-04T16:36:36.969Z] go.uber.org/zap
[2020-08-04T16:36:36.969Z] go.elastic.co/apm/module/apmzerolog
[2020-08-04T16:36:37.236Z] go.elastic.co/apm/module/apmzap
[2020-08-04T16:37:09.363Z] github.com/jinzhu/gorm/dialects/sqlite
[2020-08-04T16:37:09.363Z] go.elastic.co/apm/module/apmsql/sqlite3
[2020-08-04T16:37:09.363Z] go.elastic.co/apm/module/apmgorm/dialects/sqlite
[2020-08-04T16:37:09.363Z] Makefile:44: recipe for target 'install' failed
[2020-08-04T16:37:09.363Z] make: *** [install] Error 2
[2020-08-04T16:37:09.446Z] Recording test results
[2020-08-04T16:37:09.834Z] None of the test reports contained any result
[2020-08-04T16:37:09.858Z] Failed in branch Go-1.9.x
[2020-08-04T16:37:10.875Z] Stage "Coverage" skipped due to earlier failure(s)
[2020-08-04T16:37:10.906Z] Stage "Benchmark" skipped due to earlier failure(s)
[2020-08-04T16:37:10.972Z] Stage "More OS" skipped due to earlier failure(s)
[2020-08-04T16:37:11.001Z] Stage "Windows" skipped due to earlier failure(s)
[2020-08-04T16:37:11.002Z] Stage "OSX" skipped due to earlier failure(s)
[2020-08-04T16:37:11.028Z] Failed in branch Windows
[2020-08-04T16:37:11.029Z] Failed in branch OSX
[2020-08-04T16:37:11.076Z] Stage "Integration Tests" skipped due to earlier failure(s)
[2020-08-04T16:37:11.106Z] Stage "Release" skipped due to earlier failure(s)
[2020-08-04T16:37:11.120Z] Stage "Release" skipped due to earlier failure(s)
[2020-08-04T16:37:11.534Z] Running on Jenkins in /var/lib/jenkins/workspace/agent-go_apm-agent-go-mbp_PR-788
[2020-08-04T16:37:11.730Z] [INFO] getVaultSecret: Getting secrets
[2020-08-04T16:37:11.790Z] Masking supported pattern matches of $VAULT_ADDR or $VAULT_ROLE_ID or $VAULT_SECRET_ID
[2020-08-04T16:37:12.411Z] + chmod 755 generate-build-data.sh
[2020-08-04T16:37:12.411Z] + ./generate-build-data.sh https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-go/apm-agent-go-mbp/PR-788/ https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-go/apm-agent-go-mbp/PR-788/runs/15 FAILURE 770083
[2020-08-04T16:37:12.662Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-go/apm-agent-go-mbp/PR-788/runs/15/steps/?limit=10000 -o steps-info.json
[2020-08-04T16:37:13.573Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-go/apm-agent-go-mbp/PR-788/runs/15/tests/?status=FAILED -o tests-errors.json

Copy link
Member

@axw axw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looking good, thanks for this!

I think we should probably follow https://w3c.github.io/resource-timing/#processing-model for the span names, which is what we did for RUM breakdown metrics. Possible exception for separating TCP into TLS/Connect. Also, I'm not super keen on things like "Server Processing", which assumes too much knowledge on the part of the client. Better to instrument the server-side for for that.

WDYT about this?

  • DNS: DNSDone - DNSStart
  • Connect: ConnectDone - ConnectStart
  • TLS: TLSHandshakeDone - TLSHandshakeStart
  • Request: WroteRequest - GotConn
  • Response: (response end) - GotFirstResponseByte

module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
@graphaelli
Copy link
Member Author

Thanks for the review, i am still planning to follow up on this!

and including hostname in DNS lookup span name
and make a request tracer per roundtrip
@graphaelli graphaelli marked this pull request as draft July 31, 2020 02:12
@graphaelli
Copy link
Member Author

graphaelli commented Jul 31, 2020

GH is not letting me convert this back to a draft Looks like it did after all - pushing up some commits now but still missing the multiple connection handling, will flag when really ready for another review.

per httptrace docs:
	// ConnectStart is called when a new connection's Dial begins.
	// If net.Dialer.DualStack (IPv6 "Happy Eyeballs") support is
	// enabled, this may be called multiple times.
@graphaelli graphaelli marked this pull request as ready for review August 1, 2020 01:59
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
module/apmhttp/client_test.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
@graphaelli
Copy link
Member Author

@axw I don't understand the go 1.9 test failure, this is ready for review otherwise.

@graphaelli graphaelli requested a review from axw August 4, 2020 01:49
Copy link
Member

@axw axw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

almost there!

module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/client.go Outdated Show resolved Hide resolved
module/apmhttp/clienttrace.go Show resolved Hide resolved
},

WroteRequest: func(info httptrace.WroteRequestInfo) {
r.Request = tx.StartSpan("Request", "http.request", parent)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't this when we want to end the request span? I think we want to start it with GotConn

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You're right, this was not translated properly when converting it from Server Processing. Looking at this again and seeing:

	// WroteRequest is called with the result of writing the
	// request and any body. It may be called multiple times
	// in the case of retried requests.

I think we should make multiple request spans in case of retries, so if r.Request != nil r.Request.End() - objections?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cancel that, will test what happens in this case, not clear if gotconn is called again too

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now that the request span doesn't cover the server response time I'm missing that span representing the server time

image

I follow that a distributed trace into your own systems would show up there but this makes it non-trivial to monitor time in external services - any ideas here? Maybe an option for WithClientTrace to create spans for that external time? Is this not actually an issue?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I follow that a distributed trace into your own systems would show up there but this makes it non-trivial to monitor time in external services - any ideas here?

Fair point, I was really thinking about wholly-owned distributed systems.

Going back to https://w3c.github.io/resource-timing/#processing-model, "Request" is actually responseStart - requestStart. How about we do the same? GotFirstResponseByte - GotConn? If it's really interesting to know when the client finished writing the request, we could add "marks" like the RUM agent does.

Copy link
Member

@axw axw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Last thing! Then we just need to get to the bottom of the 1.9 failure. Didn't fail on master when I created a PR earlier, so I think it's related to the go.mod changes. There's also a goimports error.

module/apmhttp/clienttrace.go Outdated Show resolved Hide resolved
@axw
Copy link
Member

axw commented Aug 5, 2020

Looks good! We can investigate the 1.9 failure separately... seems unrelated.

@axw axw merged commit 00970ba into elastic:master Aug 5, 2020
@graphaelli
Copy link
Member Author

woo, thanks for all of the guidance!

@graphaelli graphaelli deleted the httptrace branch August 5, 2020 13:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants