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.

Sign up for GitHub

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

Jump to bottom

Teleport fails to upload session recording to UI when Teleport service is restarted during tsh session #6125

Closed
jon-can opened this issue Mar 24, 2021 · 5 comments
Closed

Teleport fails to upload session recording to UI when Teleport service is restarted during tsh session #6125

jon-can opened this issue Mar 24, 2021 · 5 comments
Assignees
@quinqu
Labels
blocker Blocker for the milestone bug sales-onboarding Issues related to prospects
Milestone
6.2 "Buffalo"

Comments

@jon-can
Copy link
Contributor

jon-can commented Mar 24, 2021

Description

What happened:
A session recording does not get uploaded to the web UI when the Teleport service is restarted in the middle of a tsh ssh
What you expected to happen:
Session recordings should eventually appear in the web UI

Reproduction Steps

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

  1. tsh ssh into a node
  2. Enter: echo "test" or something similiar
  3. systemctl restart teleport

Server Details

  • Teleport version (run teleport version): 6.0.2
  • Server OS (e.g. from /etc/os-release): Ubuntu
  • Where are you running Teleport? (e.g. AWS, GCP, Dedicated Hardware): AWS

Debug Logs

These are the logs when the Teleport service is stopped. Once Teleport restarts I don't see anything in the logs related to session recordings/upload attempts/etc.

Mar 24 15:13:32 ip-172-31-25-182 systemd[1]: Stopping Teleport SSH Service...
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Broadcasting event. event:TeleportExit service/supervisor.go:333
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [KUBERNETE] Exited. service/kubernetes.go:290
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:kube.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:common.rotate service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [APP:SERVI] Cache is closing, returning from update loop. cache/cache.go:653
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: WARN [APP:SERVI] Failed to set tombstone: database is closed cache/cache.go:697
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU             Reporting client is shutting down. client/client.go:119
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [ENFORCER]  Heartbeat loop is exiting. enforcer/enforcer.go:158
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [ENFORCER]  Enforce loop is exiting. enforcer/enforcer.go:136
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [KEYGEN]    Stopping key precomputation routine. native/native.go:139
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [REVERSE:A] Cache is closing, returning from update loop. cache/cache.go:653
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: WARN [REVERSE:A] Failed to set tombstone: database is closed cache/cache.go:697
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [APP:SERVI] Pool is closing agent. leaseID:1 target:localhost:3024 reversetunnel/agentpool.go:234
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROXY:AGE] Closing. cluster:aws-west reversetunnel/agentpool.go:250
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROXY:AGE] Halting seek event processing (pool closing) cluster:aws-west reversetunnel/agentpool.go:192
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: WARN [APP:SERVI] Unable to continue processesing requests: heartbeat: agent is stopped. leaseID:1 target:localhost:3024 reversetunnel/agent.go:371
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: WARN [PROC:1]    Teleport process has exited with error: context canceled service:apps.start service/supervisor.go:251
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Broadcasting event. event:ServiceExitedWithError service/supervisor.go:333
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:apps.start service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH]      ClientCertPool -> cert(aws-west issued by aws-west:122932108803982799327912107690831020675) auth/middleware.go:593
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH]      ClientCertPool -> cert(aws-west issued by aws-west:156191204548917725019236077938065176078) auth/middleware.go:593
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:1]    Server certificate cert(d99f1fcb-bc9b-4573-8b38-f826ab8f1c48.aws-west issued by aws-west:122932108803982799327912107690831020675). auth/middleware.go:298
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:auth.broadcast service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUTH:1]    Shutting down immediately. service/service.go:1377
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [NODE:1]    Shutting down immediately. service/service.go:1823
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [SESSION:N] Closing Session Registry. srv/sess.go:121
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [NODE:1]    Exited. service/service.go:1846
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:ssh.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [APP:SERVI] Shutting down. service/service.go:3059
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [APP:SERVI] Exited. service/service.go:3067
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:apps.stop service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Closed client for Node. service/service.go:1863
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:GRPC] Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled auth/grpcserver.go:101
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [SSH:PROXY] Closed connection 127.0.0.1:54608. sshutils/server.go:448
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:GRPC] Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled auth/grpcserver.go:101
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROXY:SER] Cluster agent disconnected. trace.fields:map[cluster:aws-west] reversetunnel/localsite.go:392
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [DISCOVERY] Disconnecting connection to aws-west 127.0.0.1:54608: agent disconnected. reversetunnel/conn.go:178
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROXY:SER] Cluster connection closed. trace.fields:map[cluster:aws-west] reversetunnel/localsite.go:369
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:auth.client.node service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Closed client for Kube. service/service.go:1863
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:auth.client.kube service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Closed client for App. service/service.go:1863
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Closed client for Proxy. service/service.go:1863
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Shutting down. service/service.go:1935
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Exited. service/service.go:1937
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:uploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [SSH:PROXY] Closed connection 18.237.28.68:53311. sshutils/server.go:448
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [SSH:PROXY] Closed connection 18.237.28.68:5221. sshutils/server.go:448
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader is shutting down. service/service.go:1961
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader has shut down. service/service.go:1963
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.service service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader is shutting down. service/service.go:1961
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader has shut down. service/service.go:1963
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.service service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [MX:PROXY:] backoff on accept error: accept tcp [::]:3026: use of closed network connection multiplexer/multiplexer.go:192
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [PROXY:SER] Shutting down immediately. service/service.go:2784
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [WEB]       Closing session cache. web/sessions.go:463
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [SESSION:P] Closing Session Registry. srv/sess.go:121
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:proxy.kube service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Shutting down. service/service.go:1935
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Exited. service/service.go:1937
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:uploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUDIT]     Uploader is exiting. events/uploader.go:158
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:uploader.service service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader is shutting down. service/service.go:1961
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   File uploader has shut down. service/service.go:1963
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:fileuploader.service service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Shutting down. service/service.go:1935
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: INFO [AUDIT:1]   Exited. service/service.go:1937
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:uploader.shutdown service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUDIT]     Uploader is exiting. events/uploader.go:158
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:uploader.service service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [APP:SERVI] Heartbeat exited. srv/heartbeat.go:269
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:BEAT] Heartbeat exited. srv/heartbeat.go:269
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [PROC:1]    Service is completed and removed. service:auth.heartbeat service/supervisor.go:222
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [KUBERNETE] Cache is closing, returning from update loop. cache/cache.go:653
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: WARN [KUBERNETE] Failed to set tombstone: database is closed cache/cache.go:697
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:GRPC] Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled auth/grpcserver.go:101
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:1:CA] Cache is closing, returning from update loop. cache/cache.go:653
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [BUFFER]    Removed watcher 0xc0001d0070 via external close. backend/buffer.go:254
Mar 24 15:13:32 ip-172-31-25-182 teleport[709513]: DEBU [AUTH:GRPC] Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled auth/grpcserver.go:101
Mar 24 15:13:32 ip-172-31-25-182 systemd[1]: teleport.service: Succeeded.
Mar 24 15:13:32 ip-172-31-25-182 systemd[1]: Stopped Teleport SSH Service.```
@jon-can jon-can added bug blocker Blocker for the milestone sales-onboarding Issues related to prospects labels Mar 24, 2021
@russjones
Copy link
Contributor

@jon-can Can you share your systemd unit file?

@jon-can
Copy link
Contributor Author

jon-can commented Mar 24, 2021

systemd unit file:

Description=Teleport SSH Service
After=network.target

[Service]
Type=simple
Restart=on-failure
EnvironmentFile=-/etc/default/teleport
ExecStart=/usr/local/bin/teleport start --pid-file=/run/teleport.pid
ExecReload=/bin/kill -HUP $MAINPID
PIDFile=/run/teleport.pid

[Install]
WantedBy=multi-user.target

@russjones
Copy link
Contributor

Closing as I suspect you are using node-async mode (the default). If you want the session to be streamed as it occurs and not buffered to disk and streamed at the end, use node-sync mode. https://goteleport.com/docs/changelog/#440

@jon-can jon-can reopened this Mar 29, 2021
@jon-can
Copy link
Contributor Author

jon-can commented Mar 29, 2021

Tried using node-sync mode and I still do not see the session recording.

@russjones russjones added this to the 6.2 "Buffalo" milestone Apr 15, 2021
@quinqu
Copy link
Contributor

quinqu commented Apr 27, 2021

Closing because sessions do eventually get uploaded by the upload completer and the fix is opened up in this issue #6606

@quinqu quinqu closed this as completed Apr 27, 2021
@quinqu quinqu mentioned this issue May 6, 2021
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@quinqu quinqu

Labels
blocker Blocker for the milestone bug sales-onboarding Issues related to prospects
Projects
None yet
Milestone
6.2 "Buffalo"
Development

No branches or pull requests
3 participants
@russjones @jon-can @quinqu