Teleport IoT: the connection was closed on the remote side

[re-mscho]

I'm new to teleport and want to connect a node using a reverse tunnel as described here.

When I try to login to the node using WEB-UI or on command line the connection is immediately closed:

$> tsh --debug ssh configurator@factory-01
                                                                                                                                
INFO [CLIENT]    [KEY AGENT] Connected to the system agent: "/run/user/1000/keyring/ssh" client/api.go:2453
DEBU [KEYSTORE]  Returning SSH certificate "/home/linuxuser/.tsh/keys/teleport.xyz-test.com/test-cert.pub" valid until "2021-04-12 23:42:26 +0200 CEST", TLS certificate "/home/linuxuser/.tsh/keys/teleport.xyz-test.com/test-x509.pem" valid until "2021-04-12 21:42:26 +0000 UTC". client/keystore.go:355
INFO [KEYAGENT]  Loading key for "test" client/keyagent.go:144
INFO [CLIENT]    Connecting proxy=teleport.xyz-test.com:3023 login='configurator' method=0 client/api.go:1826
DEBU [KEYAGENT]  Validated host teleport.xyz-test.com:3023. client/keyagent.go:321
INFO [CLIENT]    Successful auth with proxy teleport.xyz-test.com:3023 client/api.go:1836
DEBU [CLIENT]    Found clusters: [{"name":"teleport.xyz-test.com","lastconnected":"2021-04-12T18:06:15.521987754+02:00","status":"online"}] client/client.go:110
INFO [CLIENT]    Client= connecting to node=factory-01 on cluster teleport.xyz-test.com client/client.go:591
DEBU [KEYAGENT]  Validated host factory-01:0@[email protected]. client/keyagent.go:321

the connection was closed on the remote side on  12 Apr 21 18:06 CEST

Everything looks fine and the node(factory-01) is connected. At least it's visible in WEB-UI and tsh ls -v lists the node:

Node Name                 Node ID                              Address        Labels 
------------------------- ------------------------------------ -------------- ------ 
factory-01             f97aaeb5-7061-4691-882b-5fe75ccd3065 <-- Tunnel              
pbteuw01vmteleport-master ab76d9d9-2553-4002-b268-bec28f61f1b4 127.0.0.1:3022   

I found only one hint about an error and that's in the node log:
DEBU [SESSION:N] Copying from PTY to writer completed with error read /dev/ptmx: input/output error. srv/sess.go:788

Maybe someone can help me because I'm stuck here and don't know what to do.

---

Node log when trying to connect:

DEBU [NODE]      Successfully authenticated fingerprint:[email protected] SHA256:<removed> local:192.168.1.10:33816 remote:178.162.223.164:40031 user:configurator srv/authhandlers.go:224
DEBU [NODE]      Checking permissions for (test,configurator) to login to node with RBAC checks. srv/authhandlers.go:338
DEBU [SSH:NODE]  Incoming connection 178.162.223.164:40031 -> 192.168.1.10:33816 vesion: SSH-2.0-Go. sshutils/server.go:443
DEBU [SSH:NODE]  Received out-of-band request: &{Type:x-teleport-version WantReply:true Payload:[] ch:<nil> mux:0xc000290770}. sshutils/server.go:498
DEBU [KEEPALIVE] Starting keep-alive loop with with interval 5m0s and max count 3. srv/keepalive.go:65
DEBU [NODE]      Handling request env, want reply true. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU [NODE]      Handling request env, want reply true. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU [NODE]      Handling request env, want reply true. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU             Will create new session for SSH connection 178.162.223.164:40031. srv/ctx.go:433
DEBU [NODE]      Handling request pty-req, want reply true. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU [NODE]      Requested terminal "xterm-256color" of size {239 26} id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test srv/termhandlers.go:73
DEBU             Set permissions on /dev/pts/0 to 2409:5 with mode -rw-------. srv/term.go:407
DEBU [SESSION:N] Unable to update window size, no session found in context. srv/sess.go:389
DEBU             Will create new session for SSH connection 178.162.223.164:40031. srv/ctx.go:433
DEBU [NODE]      Handling request shell, want reply true. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
INFO [NODE]      Creating (interactive) session b45b4fcf-a221-40a0-a74f-c9770ad58cbb. id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test srv/sess.go:211
DEBU [SESSION:N] Using async streamer for session b45b4fcf-a221-40a0-a74f-c9770ad58cbb. srv/sess.go:1043
INFO [SESSION:N] New party ServerContext(178.162.223.164:40031->192.168.1.10:33816, user=configurator, id=1) party(id=550d9e3d-9d1a-4492-868b-969865385aef) joined session: b45b4fcf-a221-40a0-a74f-c9770ad58cbb srv/sess.go:1219
DEBU             Will join session b45b4fcf-a221-40a0-a74f-c9770ad58cbb for SSH connection 178.162.223.164:40031. srv/ctx.go:435
INFO [AUDIT]     session.start addr.remote:178.162.223.164:40031 cluster_name:teleport.xyz-test.com code:T2000I ei:0 event:session.start login:configurator namespace:default server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb size:239:26 time:2021-04-12T09:59:34.225Z uid:44c194fa-47b3-44b0-89ec-c8361e222d71 user:test events/emitter.go:317
DEBU [SESSION:N] Starting poll and sync of terminal size to all parties. srv/sess.go:1161
DEBU [SESSION:N] Copying from PTY to writer completed with error read /dev/ptmx: input/output error. srv/sess.go:788
DEBU [NODE]      Exec request ("/usr/local/bin/teleport") complete: 2 id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1249
INFO [SESSION:N] Closing party 550d9e3d-9d1a-4492-868b-969865385aef srv/sess.go:1410
DEBU [SESSION:N] Sent session.join to 178.162.223.164:40031. srv/sess.go:290
INFO [NODE]      Removing party ServerContext(178.162.223.164:40031->192.168.1.10:33816, user=configurator, id=1) party(id=550d9e3d-9d1a-4492-868b-969865385aef) from session b45b4fcf-a221-40a0-a74f-c9770ad58cbb id:1 local:192.168.1.10:33816 login:configurator remote:178.162.223.164:40031 teleportUser:test srv/sess.go:1083
INFO [SESSION:N] Session b45b4fcf-a221-40a0-a74f-c9770ad58cbb will be garbage collected. srv/sess.go:323
INFO [SESSION:N] Closing session b45b4fcf-a221-40a0-a74f-c9770ad58cbb. srv/sess.go:632
DEBU             Closing session writer: session-recorder. srv/sess.go:1327
DEBU [SESSION:N] Stopping poll and sync of terminal size to all parties. srv/sess.go:1182
INFO [AUDIT]     session.leave cluster_name:teleport.xyz-test.com code:T2003I ei:1 event:session.leave namespace:default server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:550d9e3d-9d1a-4492-868b-969865385aef time:2021-04-12T09:59:34.262Z uid:899e5073-5e9d-4e5f-974e-3bb2b7cdab45 user:test events/emitter.go:317
INFO [AUDIT]     session.data addr.remote:178.162.223.164:40031 cluster_name: code:T2006I ei:2.147483646e+09 event:session.data login:configurator namespace:default rx:4266 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb time:2021-04-12T09:59:34.373Z tx:4493 uid:7bac5c74-d0d5-48cc-b351-3f8fbbf68722 user:test events/emitter.go:317
INFO [SESSION:N] Party member 550d9e3d-9d1a-4492-868b-969865385aef left session b45b4fcf-a221-40a0-a74f-c9770ad58cbb. srv/sess.go:1228
DEBU [TERM:LOCA] Closed PTY srv/term.go:300
DEBU [SSH:NODE]  Closed connection 178.162.223.164:40031. sshutils/server.go:448
INFO [AUDIT]     session.end cluster_name:teleport.xyz-test.com code:T2004I ei:2 enhanced_recording:false event:session.end interactive:true namespace:default participants:[test] server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 session_start:2021-04-12T09:59:34.15479179Z session_stop:2021-04-12T09:59:34.262682365Z sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb time:2021-04-12T09:59:34.263Z uid:24e93eca-9416-4ea2-9854-e8ac5a047e61 user:test events/emitter.go:317
DEBU [UPLOAD]    Scanned 1 uploads, started 1 in /var/lib/teleport/log/upload/streaming/default. filesessions/fileasync.go:286
DEBU [UPLOAD]    Failed to close stream. error:[EOF] filesessions/fileasync.go:487
DEBU [UPLOAD]    Session upload completed. duration:163.677918ms session-id:b45b4fcf-a221-40a0-a74f-c9770ad58cbb filesessions/fileasync.go:440

Server log when trying to connect:

DEBU [PROXY]     conn(178.162.223.164:40031->10.10.0.4:3023, user=configurator) auth attempt fingerprint:[email protected] SHA256:<removed> local:10.10.0.4:3023 remote:178.162.223.164:40031 user:configurator srv/authhandlers.go:163
DEBU [PROXY]     conn(178.162.223.164:40031->10.10.0.4:3023, user=configurator) auth attempt with key [email protected] SHA256:<removed>, &ssh.Certificate{Nonce:[]uint8{0x87, 0x8a, 0x9b, 0x65, 0x9e, 0x55, 0x37, 0x97, 0x26, 0xd9, 0xe3, 0xb1, 0xac, 0x50, 0x62, 0x6d, 0xdb, 0x11, 0x42, 0xf9, 0x70, 0x64, 0x1b, 0x4b, 0x2a, 0x32, 0x61, 0x7e, 0xbb, 0x73, 0x64, 0xb0}, Key:(*ssh.rsaPublicKey)(0xc002801b40), Serial:0x0, CertType:0x1, KeyId:"test", ValidPrincipals:[]string{"configurator"}, ValidAfter:0x607415c6, ValidBefore:0x6074bec2, Permissions:ssh.Permissions{CriticalOptions:map[string]string{}, Extensions:map[string]string{"permit-agent-forwarding":"", "permit-port-forwarding":"", "permit-pty":"", "teleport-roles":"{\"version\":\"v1\",\"roles\":[\"editor\",\"access\"]}", "teleport-route-to-cluster":"teleport.xyz-test.com", "teleport-traits":"{\"logins\":[\"configurator\"]}"}}, Reserved:[]uint8{}, SignatureKey:(*ssh.rsaPublicKey)(0xc002801b80), Signature:(*ssh.Signature)(0xc0027fe2c0)} fingerprint:[email protected] SHA256:<removed> local:10.10.0.4:3023 remote:178.162.223.164:40031 user:configurator srv/authhandlers.go:166
DEBU [PROXY]     Successfully authenticated fingerprint:[email protected] SHA256:<removed> local:10.10.0.4:3023 remote:178.162.223.164:40031 user:configurator srv/authhandlers.go:224
DEBU [SSH:PROXY] Incoming connection 178.162.223.164:40031 -> 10.10.0.4:3023 vesion: SSH-2.0-Go. sshutils/server.go:443
DEBU [KEEPALIVE] Starting keep-alive loop with with interval 5m0s and max count 3. srv/keepalive.go:65
DEBU [PROXY]     Handling request subsystem, want reply true. id:5 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU [PROXY]     Subsystem request: proxySites(). id:5 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1384
DEBU [NODE]      proxysites.start(ServerContext(178.162.223.164:40031->10.10.0.4:3023, user=configurator, id=5)) regular/sites.go:54
DEBU [NODE]      Subsystem proxySites() finished with result: <nil>. regular/sshserver.go:1394
DEBU [PROXY]     Close session request: <nil>. id:5 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1231
DEBU [SSH:PROXY] Received out-of-band request: &{Type:[email protected] WantReply:true Payload:[] ch:<nil> mux:0xc000429b90}. sshutils/server.go:498
DEBU [NODE]      Global request ([email protected], true) received regular/sshserver.go:1433
DEBU [NODE]      Replied to global request ([email protected], true): false regular/sshserver.go:1456
DEBU [KEEPALIVE] Starting keep-alive loop with with interval 5m0s and max count 3. srv/keepalive.go:65
DEBU [PROXY]     Handling request subsystem, want reply true. id:6 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1269
DEBU [NODE]      parse_proxy_subsys("proxy:factory-01:0@[email protected]") regular/proxy.go:77
DEBU [NODE]      newProxySubsys({default factory-01 0 teleport.xyz-test.com}). regular/proxy.go:179
DEBU [PROXY]     Subsystem request: proxySubsys(cluster=default/teleport.xyz-test.com, host=factory-01, port=0). id:6 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1384
DEBU [SUBSYSTEM] Starting subsystem trace.fields:map[dst:10.10.0.4:3023 src:178.162.223.164:40031] regular/proxy.go:208
DEBU [SUBSYSTEM] proxy connecting to host=factory-01 port=0, exact port=false trace.fields:map[dst:10.10.0.4:3023 src:178.162.223.164:40031] regular/proxy.go:328
DEBU [PROXY:SER] Dialing from: "178.162.223.164:40031" to: "@local-node". trace.fields:map[cluster:teleport.xyz-test.com] reversetunnel/localsite.go:184
DEBU [PROXY:SER] Tunnel dialing to f97aaeb5-7061-4691-882b-5fe75ccd3065.teleport.xyz-test.com. trace.fields:map[cluster:teleport.xyz-test.com] reversetunnel/localsite.go:267
DEBU [PROXY:SER] Connecting to 212.67.235.185:33816 through tunnel. trace.fields:map[cluster:teleport.xyz-test.com] reversetunnel/localsite.go:454
DEBU [PROXY:SER] Succeeded dialing from: "178.162.223.164:40031" to: "@local-node". trace.fields:map[cluster:teleport.xyz-test.com] reversetunnel/localsite.go:190
INFO [AUDIT]     session.start addr.remote:178.162.223.164:40031 cluster_name:teleport.xyz-test.com code:T2000I ei:0 event:session.start login:configurator namespace:default server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb size:239:26 time:2021-04-12T09:59:34.225Z uid:44c194fa-47b3-44b0-89ec-c8361e222d71 user:test events/emitter.go:317
INFO [AUDIT]     session.leave cluster_name:teleport.xyz-test.com code:T2003I ei:1 event:session.leave namespace:default server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:550d9e3d-9d1a-4492-868b-969865385aef time:2021-04-12T09:59:34.262Z uid:899e5073-5e9d-4e5f-974e-3bb2b7cdab45 user:test events/emitter.go:317
DEBU [SSH:PROXY] Closed connection 178.162.223.164:40031. sshutils/server.go:448
DEBU [NODE]      Subsystem proxySubsys(cluster=default/teleport.xyz-test.com, host=factory-01, port=0) finished with result: <nil>. regular/sshserver.go:1394
DEBU [PROXY]     Client 178.162.223.164:40031 disconnected. id:6 local:10.10.0.4:3023 login:configurator remote:178.162.223.164:40031 teleportUser:test regular/sshserver.go:1236
INFO [AUDIT]     session.data addr.remote:178.162.223.164:40031 cluster_name: code:T2006I ei:2.147483646e+09 event:session.data login:configurator namespace:default rx:4266 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb time:2021-04-12T09:59:34.373Z tx:4493 uid:7bac5c74-d0d5-48cc-b351-3f8fbbf68722 user:test events/emitter.go:317
INFO [AUDIT]     session.end cluster_name:teleport.xyz-test.com code:T2004I ei:2 enhanced_recording:false event:session.end interactive:true namespace:default participants:[test] server_addr:192.168.1.10:33816 server_hostname:factory-01 server_id:f97aaeb5-7061-4691-882b-5fe75ccd3065 session_start:2021-04-12T09:59:34.15479179Z session_stop:2021-04-12T09:59:34.262682365Z sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb time:2021-04-12T09:59:34.263Z uid:24e93eca-9416-4ea2-9854-e8ac5a047e61 user:test events/emitter.go:317
DEBU [AUTH:GRPC] CreateAuditStream connection from f97aaeb5-7061-4691-882b-5fe75ccd3065.teleport.xyz-test.com. auth/grpcserver.go:120
DEBU [AUTH:GRPC] Created stream: <nil>. auth/grpcserver.go:163
INFO [AUDIT]     session.upload cluster_name:teleport.xyz-test.com code:T2005I ei:2.147483647e+09 event:session.upload sid:b45b4fcf-a221-40a0-a74f-c9770ad58cbb time:2021-04-12T09:59:37.18Z url:file:///var/lib/teleport/log/records/multi/b45b4fcf-a221-40a0-a74f-c9770ad58cbb events/emitter.go:317
DEBU [AUTH:GRPC] Completed stream: <nil>. auth/grpcserver.go:209
WARN [AUTH:GRPC] Failed to flush close the stream. error:[
ERROR REPORT:
Original Error: *trace.ConnectionProblemError emitter has been closed
Stack Trace:
	/go/src/github.com/gravitational/teleport/lib/events/stream.go:422 github.com/gravitational/teleport/lib/events.(*ProtoStream).Close
	/go/src/github.com/gravitational/teleport/lib/events/emitter.go:438 github.com/gravitational/teleport/lib/events.(*CheckingStream).Close
	/go/src/github.com/gravitational/teleport/lib/auth/auth_with_roles.go:1695 github.com/gravitational/teleport/lib/auth.(*streamWithRoles).Close
	/go/src/github.com/gravitational/teleport/lib/auth/grpcserver.go:138 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream.func2
	/go/src/github.com/gravitational/teleport/lib/auth/grpcserver.go:213 github.com/gravitational/teleport/lib/auth.(*GRPCServer).CreateAuditStream
	/go/src/github.com/gravitational/teleport/vendor/github.com/gravitational/teleport/api/client/proto/authservice.pb.go:8069 github.com/gravitational/teleport/api/client/proto._AuthService_CreateAuditStream_Handler
	/go/src/github.com/gravitational/teleport/lib/auth/middleware.go:386 github.com/gravitational/teleport/lib/auth.(*Middleware).StreamInterceptor
	/go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:1336 google.golang.org/grpc.(*Server).processStreamingRPC
	/go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:1409 google.golang.org/grpc.(*Server).handleStream
	/go/src/github.com/gravitational/teleport/vendor/google.golang.org/grpc/server.go:746 google.golang.org/grpc.(*Server).serveStreams.func1.1
	/opt/go/src/runtime/asm_amd64.s:1374 runtime.goexit
User Message: emitter has been closed] auth/grpcserver.go:139

Node config:

---
teleport:
  nodename: factory-01
  log:
    output: /var/log/teleport/teleport.log
    severity: DEBUG
  ca_pin: "sha256:<removed>"
  auth_token: <removed>
  auth_servers:
  - teleport.xyz-test.com:443
ssh_service:
  enabled: "yes"
auth_service:
  enabled: "no"
proxy_service:
  enabled: "no"

Server config:

---
teleport:
  nodename: pbteuw01vmteleport-master
  data_dir: /var/lib/teleport
  log:
    output: /var/log/teleport/teleport.log
    severity: DEBUG
  ca_pin: ""

auth_service:
  enabled: "yes"
  listen_addr: 0.0.0.0:3025
  cluster_name: teleport.xyz-test.com
  authentication:
    type: local
    second_factor: off
  tokens:
    # This static token allows new hosts to join the cluster as "node"
    - "node:<removed>"

ssh_service:
  enabled: "yes"
  # IP and the port for SSH service to bind to.
  listen_addr: 0.0.0.0:3022

proxy_service:
  enabled: "yes"
  listen_addr: 0.0.0.0:3023
  web_listen_addr: 0.0.0.0:443
  tunnel_listen_addr: 0.0.0.0:443
  public_addr: teleport.xyz-test.com:443
  ssh_public_addr: teleport.xyz-test.com:3023
  tunnel_public_addr: teleport.xyz-test.com:443
  https_keypairs: []
  acme:
    enabled: "yes"
    email: <removed>

[re-mscho]

SOLVED

I just updated teleport on the node from version Teleport v6.0.3 git:v6.0.3-0-g95a652648 go1.15.5 to Teleport v6.1.1 git:v6.1.1-0-geacd474d8 go1.15.5 and now it works.