search

gravitational / teleport

The easiest, and most secure way to access and protect all of your infrastructure.
https://goteleport.com
GNU Affero General Public License v3.0
17.57k stars 1.76k forks source link

Session upload failure stacktrace but it seems to have worked #9317

Closed programmerq closed 2 years ago

programmerq commented 2 years ago

Description

What happened:

When inspecting the auth server logs, a stacktrace was seen (see below for log) that indicated a session had failed to upload to S3. There doesn't seem to be any additional mention of the session id in question in the auth service logs. The session recording does appear in the web ui and does play back successfully.

A stacktrace on a successful upload suggests that at least most of the upload process completed, and the stacktrace may be a false error. If there really was an issue with the upload, it seems like a retry should kick in.

What you expected to happen:

Teleport should be able to take an additional step to verify or retry the upload before dumping the stacktrace to logging.

Reproduction Steps

The issue occasionally pops up, but there isn't a specific way to force the stacktrace to happen.

Server Details

Client Details

n/a

Debug Logs

Please include or attach debug logs, when appropriate. Obfuscate sensitive information!

Dec 08 15:38:17 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:38:17Z INFO [AUDIT]     session.start addr.remote:10.33.19.84:56052 cluster_name:teleport code:T2000I ei:0 event:session.start login:root namespace:default server_addr:10.222.92.245:48618 server_hostname:ip-10-222-92-245.ec2.internal server_id:42cc60c1-c0e9-4490-a319-1b7bcfbaccdb server_labels:mapAccountID:626595632966 AvailabilityZone:us-east-1a ImageID:ami-0d808d3beeb8b1064 InstanceID:i-58073efa15c3cv19a InstanceType:t3.micro PrivateIP:10.222.92.245 Region:us-east-1 Role:ubuntu-dev] session_recording:node sid:bf3442a8-3043-4a1e-a047-47588a7934d5 size:80:25 time:2021-12-08T15:38:17.103Z uid:58efeeb8-00b2-46aa-974c-c91ad56fc562 user:username@example.com events/emitter.go:323
Dec 08 15:40:00 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:00Z INFO [AUDIT]     session.data addr.remote:10.33.19.84:56052 cluster_name:teleport code:T2006I ei:2.147483646e+09 event:session.data login:root namespace:default rx:14106 server_id:42cc60c1-c0e9-4490-a319-1b7bcfbaccdb sid:bf3442a8-3043-4a1e-a047-47588a7934d5 time:2021-12-08T15:40:00.147Z tx:9897 uid:17bd3ee0-9822-4f42-9db0-a54fb33eb175 user:username@example.com events/emitter.go:323
Dec 08 15:40:00 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:00Z DEBU [DYNAMODB]  Got 26 new stream shard records. dynamo/shards.go:230
Dec 08 15:40:00 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:00Z INFO [AUDIT]     session.leave cluster_name:teleport code:T2003I ei:92 event:session.leave namespace:default server_addr:10.222.92.245:48618 server_hostname:ip-10-222-92-245.ec2.internal server_id:42cc60c1-c0e9-4490-a319-1b7bcfbaccdb server_labels:map[AccountID:626595632966 AvailabilityZone:us-east-1a ImageID:ami-0d808d3beeb8b1064 InstanceID:i-58073efa15c3cv19a InstanceType:t3.micro PrivateIP:10.222.92.245 Region:us-east-1 Role:ubuntu-dev] sid:59316d85-3c0d-4b3b-9fed-d7d83e829fd7 time:2021-12-08T15:40:00.147Z uid:29ea37cd-6218-4c09-b1d2-0eb408bc9e02 user:username@example.com events/emitter.go:323
Dec 08 15:40:00 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:00Z INFO [AUDIT]     session.end cluster_name:teleport code:T2004I ei:93 enhanced_recording:false event:session.end interactive:true namespace:default participants:[username@example.com] server_addr:10.222.92.245:48618 server_hostname:ip-10-222-92-245.ec2.internal server_id:42cc60c1-c0e9-4490-a319-1b7bcfbaccdb server_labels:map[AccountID:626595632966 AvailabilityZone:us-east-1a ImageID:ami-0d808d3beeb8b1064 InstanceID:i-58073efa15c3cv19a InstanceType:t3.micro PrivateIP:10.222.92.245 Region:us-east-1 Role:ubuntu-dev] session_recording:node session_start:2021-12-08T15:38:17.051167083Z session_stop:2021-12-08T15:40:00.14703395Z sid:bf3442a8-3043-4a1e-a047-47588a7934d5 time:2021-12-08T15:40:00.147Z uid:f33c3267-07f7-49c9-a0d5-a000544d2842 user:username@example.com events/emitter.go:323
Dec 08 15:40:01 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:01Z DEBU [DYNAMODB]  Got 29 new stream shard records. dynamo/shards.go:230
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [DYNAMODB]  Got 30 new stream shard records. dynamo/shards.go:230
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH:GRPC] CreateAuditStream connection from 42cc60c1-c0e9-4490-a319-1b7bcfbaccdb.teleport. auth/grpcserver.go:158
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z INFO [S3]        Upload created in 119.079937ms. s3sessions/s3stream.go:42
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH:GRPC] Created stream: <nil>. auth/grpcserver.go:201
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH]      ClientCertPool -> cert(teleport issued by teleport:228103165391091508228645344704662686602) auth/middleware.go:593
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH]      ClientCertPool -> cert(teleport issued by teleport:168018729268889502139341184602348237927) auth/middleware.go:593
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH:1]    Server certificate cert(b8322566-9bb7-40f8-a560-59b8fdbbff87.teleport issued by teleport:228103165391091508228645344704662686602). auth/middleware.go:298
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH]      ClientCertPool -> cert(teleport issued by teleport:228103165391091508228645344704662686602) auth/middleware.go:593
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH]      ClientCertPool -> cert(teleport issued by teleport:168018729268889502139341184602348237927) auth/middleware.go:593
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH:1]    Server certificate cert(b8322566-9bb7-40f8-a560-59b8fdbbff87.teleport issued by teleport:228103165391091508228645344704662686602). auth/middleware.go:298
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z INFO [S3]        UploadPart(0tHTZp21EmMkcKvEERC5VW4TkwtSy81k_aasSbvRHM9SuL1qtkJwUk2gbmY8ZaFOWz7cGWXV74KMKt8slQb4BOQ7yXmLvxZLq8I.LjyowiCNM4OtijrbKQuXTnZbQ7NFoVD31kYLwlZijlJnJ.T6Dw--) part(1) uploaded in 30.324395ms. s3sessions/s3stream.go:63
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z INFO [S3]        UploadPart(0tHTZp21EmMkcKvEERC5VW4TkwtSy81k_aasSbvRHM9SuL1qtkJwUk2gbmY8ZaFOWz7cGWXV74KMKt8slQb4BOQ7yXmLvxZLq8I.LjyowiCNM4OtijrbKQuXTnZbQ7NFoVD31kYLwlZijlJnJ.T6Dw--) completed in 87.764475ms. s3sessions/s3stream.go:89
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z INFO [AUDIT]     session.upload cluster_name:teleport code:T2005I ei:2.147483647e+09 event:session.upload sid:bf3442a8-3043-4a1e-a047-47588a7934d5 time:2021-12-08T15:40:02.774Z url:s3://teleport-sessions/bf3442a8-3043-4a1e-a047-47588a7934d5 events/emitter.go:323
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z DEBU [AUTH:GRPC] Completed stream: <nil>. auth/grpcserver.go:247
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: 2021-12-08T15:40:02Z WARN [AUTH:GRPC] Failed to flush close the stream. error:[
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: ERROR REPORT:
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: Original Error: *trace.ConnectionProblemError emitter has been closed
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: Stack Trace:
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/events/stream.go:422 github.com/gravitational/teleport/lib/events.(*ProtoStream).Close
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/events/emitter.go:453 github.com/gravitational/teleport/lib/events.(*CheckingStream).Close
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/auth/auth_with_roles.go:1966 github.com/gravitational/teleport/lib/auth.(*streamWithRoles).Close
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/auth/grpcserver.go:176 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream.func2
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/auth/grpcserver.go:251 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/vendor/github.com/gravitational/teleport/api/client/proto/authservice.pb.go:9816 github.com/gravitational/teleport/api/client/proto._AuthService_CreateAuditStream_Handler
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/lib/auth/middleware.go:386 github.com/gravitational/teleport/lib/auth.(*Middleware).StreamInterceptor
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:1336 google.golang.org/grpc.(*Server).processStreamingRPC
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:1409 google.golang.org/grpc.(*Server).handleStream
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:746 google.golang.org/grpc.(*Server).serveStreams.func1.1
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]:         /opt/go/src/runtime/asm_amd64.s:1374 runtime.goexit
Dec 08 15:40:02 ip-10-33-19-155 teleport[1026]: User Message: emitter has been closed] auth/grpcserver.go:177
zmb3 commented 2 years ago

Closing as duplicate of #9711 (even though this one was created first).