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
16.97k stars 1.71k forks source link

OpenSSH Connections hang on exiting because authentication channel is not closed #3784

Closed tcannonfodder closed 1 year ago

tcannonfodder commented 4 years ago

Description

What happened:

When connecting to a server using OpenSSH, the SSH connection is not completely closed when exiting the connection. When debugging, it looks like the initial connection to the teleport Auth Service is not closed

What you expected to happen:

All SSH connections (including the one created by the ProxyJump should be closed automatically

How to reproduce it (as minimally and precisely as possible):

I'm not entirely sure. I just updated Teleport to 4.2.10 and encountered this issue.

Environment

VPS instances

Relevant Debug Logs If Applicable

Below is a snippet of the debug output from SSH when I run the following command:

ssh AUTH-SERVER-ALIAS
USER@AUTH-SERVER-ALIAS exit
... [stuck]
^C
debug1: Setting implicit ProxyCommand from ProxyJump: ssh -p 3023 -vvv -W '[%h]:%p' AUTH-SERVER-ALIAS
debug1: Executing proxy command: exec ssh -p 3023 -vvv -W '[NODE-SERVER-IP]:3022' AUTH-SERVER-ALIAS
...
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 2097152 rmax 32768
debug2: channel 0: rcvd adjust 588
debug3: receive packet: type 90
debug1: client_input_channel_open: ctype auth-agent@openssh.com rchan 1 win 2097152 max 32768
debug2: fd 8 setting O_NONBLOCK
debug3: fd 8 is O_NONBLOCK
debug1: channel 1: new [authentication agent connection]
debug1: confirm auth-agent@openssh.com
debug3: send packet: type 91
debug2: channel 0: rcvd adjust 44
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
USER@NODE-SERVER:~$ debug2: channel 0: rcvd adjust 36
debug3: receive packet: type 98
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug3: receive packet: type 97
debug2: channel 0: rcvd close
debug2: channel 0: output open -> drain
debug2: channel 0: chan_shutdown_read (i0 o1 sock -1 wfd 3 efd 7 [write])
debug2: channel 0: input open -> closed
debug3: receive packet: type 80
debug1: client_input_global_request: rtype x-teleport-event want_reply 0
debug3: channel 0: will not send data after close

logout
debug3: channel 0: will not send data after close
debug2: channel 0: obuf empty
debug2: channel 0: chan_shutdown_write (i3 o1 sock -1 wfd 6 efd 7 [write])
debug2: channel 0: output drain -> closed
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug3: send packet: type 97
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 2
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/7 sock -1 cc -1)
  #1 authentication agent connection (t4 r1 i0/0 o0/0 e[closed]/0 fd 8/8/-1 sock 8 cc -1)

debug2: channel 0: rcvd adjust 36
^Cdebug3: send packet: type 1
debug3: send packet: type 1
debug1: channel 1: free: authentication agent connection, nchannels 1
debug3: channel 1: status: The following connections are open:
  #1 authentication agent connection (t4 r1 i0/0 o0/0 e[closed]/0 fd 8/8/-1 sock 8 cc -1)

debug1: channel 0: free: direct-tcpip: listening port 0 for NODE-SERVER-IP port 3022, connect from 127.0.0.1 port 65535 to UNKNOWN port 65536, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 direct-tcpip: listening port 0 for NODE-SERVER-IP port 3022, connect from 127.0.0.1 port 65535 to UNKNOWN port 65536 (t4 r0 i0/0 o0/0 e[closed]/0 fd 6/7/-1 sock -1 cc -1)

debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
Killed by signal 2.
debug3: fd 1 is not O_NONBLOCK
Killed by signal 2.
webvictim commented 4 years ago

@tcannonfodder Do you have SSH agent forwarding enabled? I think this is a bug that was introduced in https://github.com/gravitational/teleport/pull/3613 (which was backported to Teleport 4.2.9). We're currently working on a fix via https://github.com/gravitational/teleport/pull/3741.

If you're curious about a workaround for now, you could downgrade your Teleport proxy server to a Teleport version <=4.2.8, or disable SSH agent forwarding if you don't require it.

tcannonfodder commented 4 years ago

@webvictim I do have agent forwarding enabled. I can wait for a fix, thankfully this is more an annoyance than a showstopper. :)

awly commented 3 years ago

I just encountered a similar bug with port forwarding using openssh client:

$ ssh -L 8080:google.com:443 talos.root
% # use the tunnel via a browser
% <ctrl-d> 
# hangs
<ctrl-c> # this actually closes the connection
$

($ is local shell prompt, % is remote shell prompt, # is my commentary)

Curiously, this does not happen if no connections are made over the forwarded port. So, something about the connection lingers and prevents SSH from closing. It also does exit on its own after a few minutes.

Server logs:

DEBU [PROXY]     conn(127.0.0.1:40594->127.0.0.1:3023, user=awly) auth attempt fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3023 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:167
DEBU [PROXY]     conn(127.0.0.1:40594->127.0.0.1:3023, user=awly) auth attempt with key ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo, &ssh.Certificate{Nonce:[]uint8{0x64, 0xb2, 0x56, 0x14, 0xdb, 0x22, 0xd0, 0xda, 0xc1, 0x49, 0x30, 0xbb, 0xba, 0x9a, 0x8, 0x4b, 0xd1, 0xc1, 0xbc, 0x9f, 0x30, 0xb9, 0xb0, 0xf8, 0xa0, 0x90, 0xc9, 0xc0, 0x2e, 0x68, 0x6a, 0xcf}, Key:(*ssh.rsaPublicKey)(0xc0010a80b0), Serial:0x0, CertType:0x1, KeyId:"awly", ValidPrincipals:[]string{"awly"}, ValidAfter:0x60660706, ValidBefore:0x6066b002, Permissions:ssh.Permissions{CriticalOptions:map[string]string{}, Extensions:map[string]string{"permit-port-forwarding":"", "permit-pty":"", "teleport-roles":"{\"version\":\"v1\",\"roles\":[\"admin-root\"]}", "teleport-route-to-cluster":"root", "teleport-traits":"{\"logins\":[\"awly\"]}"}}, Reserved:[]uint8{}, SignatureKey:(*ssh.rsaPublicKey)(0xc0010a80f0), Signature:(*ssh.Signature)(0xc001ed6000)} fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3023 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:170
DEBU [PROXY]     Successfully authenticated fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3023 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:228
DEBU [SSH:PROXY] Incoming connection 127.0.0.1:40594 -> 127.0.0.1:3023 vesion: SSH-2.0-OpenSSH_8.5. sshutils/server.go:442
DEBU [PROXY]     Handling request subsystem, want reply true. id:31 local:127.0.0.1:3023 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1272
DEBU [NODE]      parse_proxy_subsys("proxy:talos.root:3022") regular/proxy.go:77
DEBU [KEEPALIVE] Starting keep-alive loop with with interval 5m0s and max count 3. srv/keepalive.go:65
DEBU [NODE]      Proxy subsystem: routing user "awly" to cluster "root" based on the route to cluster extension. regular/proxy.go:168
DEBU [NODE]      newProxySubsys({default talos.root 3022 root}). regular/proxy.go:179
DEBU [PROXY]     Subsystem request: proxySubsys(cluster=default/root, host=talos.root, port=3022). id:31 local:127.0.0.1:3023 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1387
DEBU [SUBSYSTEM] Starting subsystem trace.fields:map[dst:127.0.0.1:3023 src:127.0.0.1:40594] regular/proxy.go:208
DEBU [SUBSYSTEM] proxy connecting to host=talos.root port=3022, exact port=true trace.fields:map[dst:127.0.0.1:3023 src:127.0.0.1:40594] regular/proxy.go:328
DEBU [PROXY:SER] Dialing from: "127.0.0.1:40594" to: "127.0.0.1:3022". trace.fields:map[cluster:root] reversetunnel/localsite.go:185
DEBU [PROXY:SER] Error occurred while dialing through a tunnel. address:127.0.0.1:3022 error:[
ERROR REPORT:
Original Error: *trace.NotFoundError no tunnel connection found: no node reverse tunnel for 82434e45-0bd7-4b87-b3c7-43c808fa0c50.root found
Stack Trace:
    /home/awly/src/teleport/lib/reversetunnel/localsite.go:265 github.com/gravitational/teleport/lib/reversetunnel.(*localSite).dialTunnel
    /home/awly/src/teleport/lib/reversetunnel/localsite.go:289 github.com/gravitational/teleport/lib/reversetunnel.(*localSite).getConn
    /home/awly/src/teleport/lib/reversetunnel/localsite.go:187 github.com/gravitational/teleport/lib/reversetunnel.(*localSite).DialTCP
    /home/awly/src/teleport/lib/reversetunnel/localsite.go:180 github.com/gravitational/teleport/lib/reversetunnel.(*localSite).Dial
    /home/awly/src/teleport/lib/srv/regular/proxy.go:427 github.com/gravitational/teleport/lib/srv/regular.(*proxySubsys).proxyToHost
    /home/awly/src/teleport/lib/srv/regular/proxy.go:249 github.com/gravitational/teleport/lib/srv/regular.(*proxySubsys).Start
    /home/awly/src/teleport/lib/srv/regular/sshserver.go:1390 github.com/gravitational/teleport/lib/srv/regular.(*Server).handleSubsystem
    /home/awly/src/teleport/lib/srv/regular/sshserver.go:1279 github.com/gravitational/teleport/lib/srv/regular.(*Server).dispatch
    /home/awly/src/teleport/lib/srv/regular/sshserver.go:1242 github.com/gravitational/teleport/lib/srv/regular.(*Server).handleSessionRequests
    /home/awly/.go/src/runtime/asm_amd64.s:1371 runtime.goexit
User Message: no tunnel connection found: no node reverse tunnel for 82434e45-0bd7-4b87-b3c7-43c808fa0c50.root found] trace.fields:map[cluster:root] reversetunnel/localsite.go:298
DEBU [HTTP:PROX] No valid environment variables found. proxy/proxy.go:207
DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:122
DEBU [PROXY:SER] Succeeded dialing from: "127.0.0.1:40594" to: "127.0.0.1:3022". trace.fields:map[cluster:root] reversetunnel/localsite.go:191
DEBU [NODE]      conn(127.0.0.1:40594->127.0.0.1:3022, user=awly) auth attempt fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3022 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:167
DEBU [NODE]      conn(127.0.0.1:40594->127.0.0.1:3022, user=awly) auth attempt with key ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo, &ssh.Certificate{Nonce:[]uint8{0x64, 0xb2, 0x56, 0x14, 0xdb, 0x22, 0xd0, 0xda, 0xc1, 0x49, 0x30, 0xbb, 0xba, 0x9a, 0x8, 0x4b, 0xd1, 0xc1, 0xbc, 0x9f, 0x30, 0xb9, 0xb0, 0xf8, 0xa0, 0x90, 0xc9, 0xc0, 0x2e, 0x68, 0x6a, 0xcf}, Key:(*ssh.rsaPublicKey)(0xc0010a8e30), Serial:0x0, CertType:0x1, KeyId:"awly", ValidPrincipals:[]string{"awly"}, ValidAfter:0x60660706, ValidBefore:0x6066b002, Permissions:ssh.Permissions{CriticalOptions:map[string]string{}, Extensions:map[string]string{"permit-port-forwarding":"", "permit-pty":"", "teleport-roles":"{\"version\":\"v1\",\"roles\":[\"admin-root\"]}", "teleport-route-to-cluster":"root", "teleport-traits":"{\"logins\":[\"awly\"]}"}}, Reserved:[]uint8{}, SignatureKey:(*ssh.rsaPublicKey)(0xc0010a8e70), Signature:(*ssh.Signature)(0xc001ed6800)} fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3022 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:170
DEBU [NODE]      Successfully authenticated fingerprint:ssh-rsa-cert-v01@openssh.com SHA256:/hgzIodl92Zx9gJYdL2vcZXPm5RqkMR4PWVsplEVkHo local:127.0.0.1:3022 remote:127.0.0.1:40594 user:awly srv/authhandlers.go:228
DEBU [NODE]      Checking permissions for (awly,awly) to login to node with RBAC checks. srv/authhandlers.go:342
DEBU [SSH:NODE]  Incoming connection 127.0.0.1:40594 -> 127.0.0.1:3022 vesion: SSH-2.0-OpenSSH_8.5. sshutils/server.go:442
DEBU [NODE]      Handling request pty-req, want reply true. id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1272
DEBU [NODE]      Requested terminal "xterm-256color" of size {147 73} id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly srv/termhandlers.go:73
DEBU [KEEPALIVE] Starting keep-alive loop with with interval 5m0s and max count 3. srv/keepalive.go:65
DEBU             Set permissions on /dev/pts/5 to 1000:5 with mode -rw-------. srv/term.go:407
DEBU [SESSION:N] Unable to update window size, no session found in context. srv/sess.go:390
DEBU [NODE]      Handling request shell, want reply true. id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1272
INFO [NODE]      Creating (interactive) session 9e439415-92df-4334-9bee-819bccca3798. id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly srv/sess.go:212
DEBU [SESSION:N] Using async streamer for session 9e439415-92df-4334-9bee-819bccca3798. srv/sess.go:1048
INFO [SESSION:N] New party ServerContext(127.0.0.1:40594->127.0.0.1:3022, user=awly, id=32) party(id=31aacc9c-1c57-4bb9-ad86-c179d98f5088) joined session: 9e439415-92df-4334-9bee-819bccca3798 srv/sess.go:1224
DEBU             Will join session 9e439415-92df-4334-9bee-819bccca3798 for SSH connection 127.0.0.1:40594. srv/ctx.go:425
INFO [AUDIT]     session.start addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 cluster_name:root code:T2000I ei:0 event:session.start login:awly namespace:default server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:9e439415-92df-4334-9bee-819bccca3798 size:147:73 time:2021-04-01T18:00:06.074Z uid:b80d6fe0-fac9-49da-930c-d9be7988aec0 user:awly events/emitter.go:317
DEBU [SESSION:N] Starting poll and sync of terminal size to all parties. srv/sess.go:1166
INFO [AUDIT]     session.start addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 cluster_name:root code:T2000I ei:0 event:session.start login:awly namespace:default server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:9e439415-92df-4334-9bee-819bccca3798 size:147:73 time:2021-04-01T18:00:06.074Z uid:b80d6fe0-fac9-49da-930c-d9be7988aec0 user:awly events/emitter.go:317
DEBU [RBAC]      Check access to role(Proxy) rc(leaf, labels=map[]) matchLabels=true, msg=matched, err=<nil> allow=map[*:[*]] rcLabels=map[] services/role.go:1369
DEBU [RBAC]      Check access to role(Proxy) rc(leaf, labels=map[]) matchLabels=true, msg=matched, err=<nil> allow=map[*:[*]] rcLabels=map[] services/role.go:1369
DEBU [NODE]      Opening direct-tcpip channel from 127.0.0.1:44506 to google.com:443. id:33 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1073
DEBU [RBAC]      Check access to role(Proxy) rc(leaf, labels=map[]) matchLabels=true, msg=matched, err=<nil> allow=map[*:[*]] rcLabels=map[] services/role.go:1369
DEBU [SESSION:N] Copying from PTY to writer completed with error read /dev/ptmx: input/output error. srv/sess.go:791
DEBU [NODE]      Exec request ("/home/awly/src/teleport/build/teleport") complete: 0 id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1252
INFO [SESSION:N] Closing party 31aacc9c-1c57-4bb9-ad86-c179d98f5088 srv/sess.go:1415
DEBU [SESSION:N] Sent session.join to 127.0.0.1:40594. srv/sess.go:291
INFO [NODE]      Removing party ServerContext(127.0.0.1:40594->127.0.0.1:3022, user=awly, id=32) party(id=31aacc9c-1c57-4bb9-ad86-c179d98f5088) from session 9e439415-92df-4334-9bee-819bccca3798 id:32 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly srv/sess.go:1088
INFO [AUDIT]     session.leave cluster_name:root code:T2003I ei:9 event:session.leave namespace:default server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:31aacc9c-1c57-4bb9-ad86-c179d98f5088 time:2021-04-01T18:00:24.493Z uid:2b321d0a-4274-4a9d-b6ca-048ded35b534 user:awly events/emitter.go:317
INFO [SESSION:N] Party member 31aacc9c-1c57-4bb9-ad86-c179d98f5088 left session 9e439415-92df-4334-9bee-819bccca3798. srv/sess.go:1233
INFO [SESSION:N] Session 9e439415-92df-4334-9bee-819bccca3798 will be garbage collected. srv/sess.go:324
DEBU [SESSION:N] Session has encountered 1 slow writes out of 11. Check disk and network on this server. events/auditwriter.go:366
INFO [SESSION:N] Closing session 9e439415-92df-4334-9bee-819bccca3798. srv/sess.go:634
DEBU             Closing session writer: session-recorder. srv/sess.go:1332
DEBU [SESSION:N] Stopping poll and sync of terminal size to all parties. srv/sess.go:1187
DEBU [TERM:LOCA] Closed PTY srv/term.go:300
DEBU [SESSION:N] Session has encountered 1 slow writes out of 11. Check disk and network on this server. events/auditwriter.go:366
INFO [AUDIT]     session.leave cluster_name:root code:T2003I ei:9 event:session.leave namespace:default server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:31aacc9c-1c57-4bb9-ad86-c179d98f5088 time:2021-04-01T18:00:24.493Z uid:2b321d0a-4274-4a9d-b6ca-048ded35b534 user:awly events/emitter.go:317
INFO [AUDIT]     session.data addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T2006I ei:2.147483646e+09 event:session.data login:awly namespace:default rx:7642 server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:9e439415-92df-4334-9bee-819bccca3798 time:2021-04-01T18:00:24.495Z tx:6956 uid:09bd79e6-54a1-42e5-9e08-62353c2edaca user:awly events/emitter.go:317
INFO [AUDIT]     session.data addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T2006I ei:2.147483646e+09 event:session.data login:awly namespace:default rx:7642 server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid:9e439415-92df-4334-9bee-819bccca3798 time:2021-04-01T18:00:24.495Z tx:6956 uid:09bd79e6-54a1-42e5-9e08-62353c2edaca user:awly events/emitter.go:317
INFO [AUDIT]     session.end cluster_name:root code:T2004I ei:10 enhanced_recording:false event:session.end interactive:true namespace:default participants:[awly] server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 session_start:2021-04-01T18:00:06.072294947Z session_stop:2021-04-01T18:00:24.493329665Z sid:9e439415-92df-4334-9bee-819bccca3798 time:2021-04-01T18:00:24.493Z uid:4b6bc181-9e99-41e2-a246-73c19a3238b1 user:awly events/emitter.go:317
INFO [AUDIT]     session.end cluster_name:root code:T2004I ei:10 enhanced_recording:false event:session.end interactive:true namespace:default participants:[awly] server_addr:127.0.0.1:3022 server_hostname:talos.root server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 session_start:2021-04-01T18:00:06.072294947Z session_stop:2021-04-01T18:00:24.493329665Z sid:9e439415-92df-4334-9bee-819bccca3798 time:2021-04-01T18:00:24.493Z uid:4b6bc181-9e99-41e2-a246-73c19a3238b1 user:awly events/emitter.go:317
DEBU [RBAC]      Check access to role(Proxy) rc(leaf, labels=map[]) matchLabels=true, msg=matched, err=<nil> allow=map[*:[*]] rcLabels=map[] services/role.go:1369
DEBU [UPLOAD]    Scanned 1 uploads, started 1 in /home/awly/src/teleport-config/trusted-cluster/data-root/log/upload/streaming/default. filesessions/fileasync.go:286
DEBU [AUTH:GRPC] CreateAuditStream connection from 82434e45-0bd7-4b87-b3c7-43c808fa0c50.root. auth/grpcserver.go:121
DEBU [AUTH:GRPC] Created stream: <nil>. auth/grpcserver.go:164
DEBU [UPLOAD]    Scan is skipping recording 9e439415-92df-4334-9bee-819bccca3798.tar that is locked by another process. filesessions/fileasync.go:270
DEBU [UPLOAD]    Scanned 1 uploads, started 0 in /home/awly/src/teleport-config/trusted-cluster/data-root/log/upload/streaming/default. filesessions/fileasync.go:286
INFO [AUDIT]     session.upload cluster_name:root code:T2005I ei:2.147483647e+09 event:session.upload sid:9e439415-92df-4334-9bee-819bccca3798 time:2021-04-01T18:00:25.563Z url:file:///home/awly/src/teleport-config/trusted-cluster/data-root/log/records/multi/9e439415-92df-4334-9bee-819bccca3798 events/emitter.go:317
DEBU [AUTH:GRPC] Completed stream: <nil>. auth/grpcserver.go:210
WARN [AUTH:GRPC] Failed to flush close the stream. error:[
ERROR REPORT:
Original Error: *trace.ConnectionProblemError emitter has been closed
Stack Trace:
    /home/awly/src/teleport/lib/events/stream.go:422 github.com/gravitational/teleport/lib/events.(*ProtoStream).Close
    /home/awly/src/teleport/lib/events/emitter.go:438 github.com/gravitational/teleport/lib/events.(*CheckingStream).Close
    /home/awly/src/teleport/lib/auth/auth_with_roles.go:1915 github.com/gravitational/teleport/lib/auth.(*streamWithRoles).Close
    /home/awly/src/teleport/lib/auth/grpcserver.go:139 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream.func2
    /home/awly/src/teleport/lib/auth/grpcserver.go:214 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream
    /home/awly/src/teleport/vendor/github.com/gravitational/teleport/api/client/proto/authservice.pb.go:9114 github.com/gravitational/teleport/api/client/proto._AuthService_CreateAuditStream_Handler
    /home/awly/src/teleport/lib/auth/middleware.go:386 github.com/gravitational/teleport/lib/auth.(*Middleware).StreamInterceptor
    /home/awly/src/teleport/vendor/google.golang.org/grpc/server.go:1336 google.golang.org/grpc.(*Server).processStreamingRPC
    /home/awly/src/teleport/vendor/google.golang.org/grpc/server.go:1409 google.golang.org/grpc.(*Server).handleStream
    /home/awly/src/teleport/vendor/google.golang.org/grpc/server.go:746 google.golang.org/grpc.(*Server).serveStreams.func1.1
    /home/awly/.go/src/runtime/asm_amd64.s:1371 runtime.goexit
User Message: emitter has been closed] auth/grpcserver.go:140
DEBU [UPLOAD]    Failed to close stream. error:[EOF] filesessions/fileasync.go:487
DEBU [UPLOAD]    Session upload completed. duration:22.945696ms session-id:9e439415-92df-4334-9bee-819bccca3798 filesessions/fileasync.go:440

# end up here right after <ctrl-d> in the terminal

...
a few minutes of silence (unrelated logs from node heartbeats)
...

WARN [NODE]      Connection problem in "direct-tcpip" channel: read |0: file already closed *fs.PathError. regular/sshserver.go:1136
DEBU [SSH:PROXY] Closed connection 127.0.0.1:40594. sshutils/server.go:447
DEBU [PROXY]     Client 127.0.0.1:40594 disconnected. id:31 local:127.0.0.1:3023 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1239
DEBU [NODE]      Subsystem proxySubsys(cluster=default/root, host=talos.root, port=3022) finished with result: read tcp 127.0.0.1:35644->127.0.0.1:3022: use of closed network connection. regular/sshserver.go:1397
DEBU [SSH:NODE]  Closed connection 127.0.0.1:40594. sshutils/server.go:447
DEBU [NODE]      Closing direct-tcpip channel from 127.0.0.1:44506 to google.com:443. id:33 local:127.0.0.1:3022 login:awly remote:127.0.0.1:40594 teleportUser:awly regular/sshserver.go:1172
INFO [AUDIT]     port addr:google.com:443 addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T3003I ei:0 event:port login:awly success:true time:2021-04-01T18:03:07.015Z uid:d346d9ca-ff93-4fdc-9478-8035851ffebd user:awly events/emitter.go:317
INFO [AUDIT]     port addr:google.com:443 addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T3003I ei:0 event:port login:awly success:true time:2021-04-01T18:03:07.015Z uid:d346d9ca-ff93-4fdc-9478-8035851ffebd user:awly events/emitter.go:317
INFO [AUDIT]     session.data addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T2006I ei:2.147483646e+09 event:session.data login:awly namespace:default rx:7974 server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid: time:2021-04-01T18:03:07.015Z tx:7280 uid:804a5ac2-ad25-46c0-9836-cdb3a8e1468b user:awly events/emitter.go:317
INFO [AUDIT]     session.data addr.local:127.0.0.1:3022 addr.remote:127.0.0.1:40594 code:T2006I ei:2.147483646e+09 event:session.data login:awly namespace:default rx:7974 server_id:82434e45-0bd7-4b87-b3c7-43c808fa0c50 sid: time:2021-04-01T18:03:07.015Z tx:7280 uid:804a5ac2-ad25-46c0-9836-cdb3a8e1468b user:awly events/emitter.go:317
ravwojdyla commented 1 year ago

👋 @awly I just hit the same issue, did you find any workarounds? Do you know if this is a known OpenSSH issue? Would appreciate any pointers :)

ravwojdyla commented 1 year ago

FYI the port forwarding behaviour may be expected: https://serverfault.com/a/20715/217299

From ssh man:

The session terminates when the command or shell on the remote machine exits and all X11 and TCP connections have been closed.

awly commented 1 year ago

@ravwojdyla I have not looked into this issue since that last comment. My guess is that this is indeed expected behavior. With forwarded connection, either the client (browser) or the server (teleport) keep the connection alive for potential reuse.