Replaying Session results in network timeout error

[thinkspill]

Description

What happened:

1. Installed Teleport on AWS via Terraform example code at:

https://github.com/gravitational/teleport/tree/master/examples/aws/terraform/ha-autoscale-cluster

2. Connected a server, started and ended an SSH session. Confirmed that a session was recorded and is present in the Web UI and the S3 bucket.

3. Tried to play the session, which resulted in the Web UI message "Recording for this session is not available."

4. Inspecting the browser Network panel, the connection to the events endpoint results in an HTTP 504 after 30 seconds with the response:

{
    "error": {
        "message": "Get \"https://teleport.cluster.local/v2/namespaces/default/sessions/cbd0cc91-d1bc-4a71-9929-12ad4e192339/events?print=true\": net/http: timeout awaiting response headers"
    }
}

Same issue with tsh play -- here's the debug output:

tsh play -d --cluster teleport-stage cbd0cc91-d1bc-4a71-9929-12ad4e192339
[CLIENT]    INFO no host login given. defaulting to <name> client/api.go:1132
[CLIENT]    INFO [KEY AGENT] Connected to the system agent: "/private/tmp/com.apple.launchd.zIQ1kv2Yln/Listeners" client/api.go:3075
[KEYSTORE]  DEBU Returning Teleport TLS certificate "/Users/<name>/.tsh/keys/<host>/teleport-admin-x509.pem" valid until "2022-04-01 10:17:44 +0000 UTC". client/keystore.go:307
[KEYSTORE]  DEBU Reading certificates from path "/Users/<name>/.tsh/keys/<host>/teleport-admin-ssh/teleport-stage-cert.pub". client/keystore.go:330
[KEYAGENT]  INFO Loading SSH key for user "teleport-admin" and cluster "teleport-stage". client/keyagent.go:191
[CLIENT]    INFO Connecting proxy=<host>:3023 login="root" client/api.go:2266
            DEBU No valid environment variables found. client/proxy.go:116
[HTTP:PROX] DEBU No proxy set in environment, returning direct dialer. proxy/proxy.go:268
[KEYSTORE]  DEBU Returning Teleport TLS certificate "/Users/<name>/.tsh/keys/<host>/teleport-admin-x509.pem" valid until "2022-04-01 10:17:44 +0000 UTC". client/keystore.go:307
[KEYAGENT]  DEBU "Checking key: ssh-rsa-cert-v01@openssh.com <key> client/keyagent.go:365
[KEYAGENT]  DEBU Validated host <host>:3023. client/keyagent.go:371
[CLIENT]    INFO Successful auth with proxy <host>:3023. client/api.go:2273
[CLIENT]    DEBU Found clusters: [{"name":"teleport-stage","lastconnected":"2022-03-31T22:21:25.40950602Z","status":"online"}] client/client.go:127
[KEYSTORE]  DEBU Returning Teleport TLS certificate "/Users/<name>/.tsh/keys/<host>/teleport-admin-x509.pem" valid until "2022-04-01 10:17:44 +0000 UTC". client/keystore.go:307
[CLIENT]    DEBU Client  is connecting to auth server on cluster "teleport-stage". client/client.go:969
[CLIENT]    DEBU Client  is connecting to auth server on cluster "teleport-stage". client/client.go:969

ERROR REPORT:
Original Error: *trace.ConnectionProblemError Get &#34;https://teleport.cluster.local/v2/namespaces/default/sessions/cbd0cc91-d1bc-4a71-9929-12ad4e192339/events?print=true&#34;: net/http: timeout awaiting response headers
Stack Trace:
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/lib/httplib/httplib.go:133 github.com/gravitational/teleport/lib/httplib.ConvertResponse
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/lib/auth/clt.go:288 github.com/gravitational/teleport/lib/auth.(*Client).Get
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/lib/auth/clt.go:1384 github.com/gravitational/teleport/lib/auth.(*Client).GetSessionEvents
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/lib/client/api.go:1636 github.com/gravitational/teleport/lib/client.(*TeleportClient).Play
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/tool/tsh/tsh.go:807 main.onPlay
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/tool/tsh/tsh.go:699 main.Run
	/tmp/build-darwin-amd64/go/src/github.com/gravitational/teleport/tool/tsh/tsh.go:333 main.main
	/var/folders/ys/8czjjsys38x504kj8172pd_m0000gp/T/drone-1niyp8HNfI0SzYrN/home/drone/build-11062-1648242161-toolchains/go/src/runtime/proc.go:255 runtime.main
	/var/folders/ys/8czjjsys38x504kj8172pd_m0000gp/T/drone-1niyp8HNfI0SzYrN/home/drone/build-11062-1648242161-toolchains/go/src/runtime/asm_amd64.s:1581 runtime.goexit
User Message: Get &#34;https://teleport.cluster.local/v2/namespaces/default/sessions/cbd0cc91-d1bc-4a71-9929-12ad4e192339/events?print=true&#34;: net/http: timeout awaiting response headers

5. Manually downloading the session .tar file from S3 results in an "unrecognized format" error when decompressing in MacOS Finder.

What you expected to happen:

I expected the session recording to play.

Reproduction Steps

As minimally and precisely as possible, describe step-by-step how to reproduce the problem.

1. Install Teleport via Terraform example code.
2. Record SSH session.
3. Play back SSH session recording.

Server Details

• Teleport version (run teleport version): Teleport v9.0.2 git:v9.0.2-0-g354b8c037 go1.17.7
• Server OS (e.g. from /etc/os-release):

NAME="Amazon Linux"
VERSION="2"
ID="amzn"
ID_LIKE="centos rhel fedora"
VERSION_ID="2"
PRETTY_NAME="Amazon Linux 2"
ANSI_COLOR="0;33"
CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2"
HOME_URL="https://amazonlinux.com/"

• Where are you running Teleport? (e.g. AWS, GCP, Dedicated Hardware): AWS
• Additional details:

Client Details

• Tsh version (tsh version): Teleport v9.0.2 git:v9.0.2-0-g354b8c037 go1.17.7
• Computer OS (e.g. Linux, macOS, Windows): MacOS 12.3
• Browser version (for UI-related issues): Chrome Version 99.0.4844.83 (Official Build) (x86_64)
• Installed via (e.g. apt, yum, brew, website download): I don't recall at the moment

Debug Logs

See above

[webvictim]

@thinkspill Does the recording play correctly if you run tsh play <filename>.tar?

(the files aren't actually TAR-formatted, they're a binary format which has a .tar extension for historical reasons)

[thinkspill]

Yes, it does play with tsh play <filename>.tar

[kmai]

I'm having the exact same issue with the exact same version and build (running on ARM though).

The only thing I spotted is that it's not finding the event on the DynamoDB table, even though is there.

Apr 05 14:21:05 teleport-auth-0 teleport[25232]: 2022-04-05T14:21:05Z DEBU [DYNAMODB]  Query completed. Filter:{[session.end windows.desktop.session.end] FieldsMap.#condName0 = :condValue0 {map[:condValue0:508db40d-5ead-4156-8973-c5cffb860f4b] map[#condName0:sid]}} From:0001-01-01 00:00:00 +0000 UTC Limit:500 Namespace:default Order:0 StartKey: To:2022-04-05 14:11:42.96509621 +0000 UTC duration:3.385535ms forward:true items:0 iterator:map[] dynamoevents/dynamoevents.go:938
Apr 05 14:21:05 teleport-auth-0 teleport[25232]: 2022-04-05T14:21:05Z DEBU [DYNAMODB]  Query completed. Filter:{[session.end windows.desktop.session.end] FieldsMap.#condName0 = :condValue0 {map[:condValue0:508db40d-5ead-4156-8973-c5cffb860f4b] map[#condName0:sid]}} From:0001-01-01 00:00:00 +0000 UTC Limit:500 Namespace:default Order:0 StartKey: To:2022-04-05 14:11:42.96509621 +0000 UTC duration:3.161521ms forward:true items:0 iterator:map[] dynamoevents/dynamoevents.go:938
Apr 05 14:21:05 teleport-auth-0 teleport[25232]: 2022-04-05T14:21:05Z DEBU [DYNAMODB]  Query completed. Filter:{[session.end windows.desktop.session.end] FieldsMap.#condName0 = :condValue0 {map[:condValue0:508db40d-5ead-4156-8973-c5cffb860f4b] map[#condName0:sid]}} From:0001-01-01 00:00:00 +0000 UTC Limit:500 Namespace:default Order:0 StartKey: To:2022-04-05 14:11:42.96509621 +0000 UTC duration:3.090497ms forward:true items:0 iterator:map[] dynamoevents/dynamoevents.go:938
Apr 05 14:21:05 teleport-auth-0 teleport[25232]: 2022-04-05T14:21:05Z DEBU [DYNAMODB]  Query completed. Filter:{[session.end windows.desktop.session.end] FieldsMap.#condName0 = :condValue0 {map[:condValue0:508db40d-5ead-4156-8973-c5cffb860f4b] map[#condName0:sid]}} From:0001-01-01 00:00:00 +0000 UTC Limit:500 Namespace:default Order:0 StartKey: To:2022-04-05 14:11:42.96509621 +0000 UTC duration:3.043072ms forward:true items:0 iterator:map[] dynamoevents/dynamoevents.go:938

I suspect this is because it's actually looking for the session ID in the sid key, while in the schema in the DynamoDB table calls that column SessionID. I think the source of truth in this case is this struct.

[thinkspill]

Any thoughts on if/when this issue can be fixed? Definitely a blocker for evaluating this software.

[webvictim]

Another report of this from the Community Slack:

$ tsh play 8a261030-4ba8-440e-bf3e-a6dceb5034d2   
ERROR: Get "https://teleport.cluster.local/v2/namespaces/default/sessions/8a261030-4ba8-440e-bf3e-a6dceb5034d2/events?print=true": net/http: timeout awaiting response headers

I can't reproduce this when running Teleport in a Kubernetes cluster with the teleport-cluster Helm chart, using a DynamoDB backend/audit log and S3 storage. I'm thinking it could be some kind of security group issue when deploying in EC2 directly. Trying to isolate the problem.

[webvictim]

It seems possible this may be related to
the addition of a where clause in the role allowing session playback.