Unable to Log In to Connected IoT Node

[thetuber]

I have several hundred remote nodes connected using IoT node tunneling. Twice in the last week, I've had a node that I cannot connect to. Here's the error I get:

$ tsh --proxy teleport ssh user@xyz
error: failed connecting to node xyz. dialing through a tunnel: no tunnel connection found: no node reverse tunnel for abc.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address

On the server, I get:

Feb 10 22:10:35 xxx teleport[183712]: ERRO [NODE] dialing through a tunnel: no tunnel connection found: no node reverse tunnel for abc.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address regular/sshserver.go:1539

Fortunately I had another way in to the node. On the node, I see that teleport is running. If I take a packet capture on both the node and the teleport server, I see that traffic is going between the two machines. I then used ss on the server to kill the TCP connection in hopes of forcing a re-connection. While a new TCP session was created, I still wasn't able to use tsh to get in.

I first saw this problem on a node last week. Without any intervention, I was able to connect to it today. The teleport process and node have running continuously for weeks.

Any ideas would be greatly appreciated. Thanks in advance.

[webvictim]

In general I would suggest this is a connectivity issue between the node and the proxy. Some questions:

• Can you see the node in tsh ls -v and get its UUID? Does it appear more than once?
  • If so, can you run tctl get nodes on the Teleport auth server and find the UUID in the list?
  • What's the time listed under "expires"?
• What version of Teleport are you running on both the auth/proxy and affected nodes?

[thetuber]

In general I would suggest this is a connectivity issue between the node and the proxy. Some questions:

I don't think it's a connectivity issue because the packet capture on the remote node and the Teleport server show traffic going back and forth.

* Can you see the node in `tsh ls -v` and get its UUID? Does it appear more than once?

Yes, I see the node and UUID with "tsh ls -v". The UUID in question only shows up once.

  * If so, can you run `tctl get nodes` on the Teleport auth server and find the UUID in the list?

Yes, I see it.

  * What's the time listed under "expires"?

expires: "2021-02-11T02:39:41.074834729Z"

"date -u" on the server gives: Thu Feb 11 02:30:25 UTC 2021

* What version of Teleport are you running on both the auth/proxy and affected nodes?

Both are running 5.0.0

Thanks for your help!

[webvictim]

Hmm, this is a weird one. Could you turn the log level on the Teleport server up to DEBUG level and grab some logs if you have this issue again? It looks like there's probably some issue preventing the proxy from finding/using the tunnel that the node has created - like you say, traffic is flowing back and forth between the two.

I suspect that something is marking the tunnel to the node as invalid for some reason - if you see a "Disconnecting connection to..." message, this would be an indication of that.

[thetuber]

I don't see the disconnecting message in the system logs, unless they rolled over. After adding the teleport log debug to the config file, can I just do a systemctl reload, or do I need to do a systemctl restart?

I saw this today, which I think is the same problem (if not, let me know and I'll open a new topic). While I was in the middle of a teleport session to a remote node, a co-worker (usera) started a new session. Something happened, and he tried to start a new session, but it failed with this message:

failed connecting to node remotenode. dialing through a tunnel: no tunnel connection found: no node reverse tunnel for remoteuuid.teleport found, dialing directly: dial tcp: address @local-node: missing port in address

The failure was roughly around 17:15.

The weird thing is that my session stayed up and I was able to continue working. However, I was not able to start a new session. Here's what I pulled from the system logs (debug has not yet enabled):

$ sudo zgrep teleport /var/log/syslog* | grep -v "Failed to run command"

/var/log/syslog:Feb 16 16:55:36 node teleport[860]: ERRO             Failed sending keepalive request: EOF sshutils/server.go:505

/var/log/syslog:Feb 16 16:56:01 node teleport[860]: ERRO [SESSION:N] Timed out waiting for PTY copy to finish, session data for uuid1 may be missing. srv/sess.go:813

/var/log/syslog:Feb 16 16:56:02 node teleport[860]: ERRO [SESSION:N] Failed to emit session print event. error:audit writer is closed events/auditwriter.go:207

/var/log/syslog:Feb 16 17:14:37 node teleport[860]: ERRO [NODE]      agent server for user "usera" stopped: accept unix /tmp/teleport-152230128/teleport-860.socket: use of closed network connection id:4066 local:x.x.x.x:42048 login:remoteuser remote:y.y.y.y:59938 teleportUser:usera regular/sshserver.go:781

/var/log/syslog:Feb 16 17:14:39 node teleport[860]: ERRO [NODE]      agent server for user "usera" stopped: accept unix /tmp/teleport-890685839/teleport-860.socket: use of closed network connection id:4067 local:x.x.x.x:42048 login:remoteuser remote:y.y.y.y:59958 teleportUser:usera regular/sshserver.go:781

/var/log/syslog:Feb 16 17:14:43 node teleport[860]: ERRO [NODE]      agent server for user "usera" stopped: accept unix /tmp/teleport-358095266/teleport-860.socket: use of closed network connection id:4099 local:x.x.x.x:42048 login:remoteuser remote:y.y.y.y:64756 teleportUser:usera regular/sshserver.go:781

/var/log/syslog:Feb 16 17:31:16 node teleport[860]: ERRO             Failed sending keepalive request: EOF sshutils/server.go:505

/var/log/syslog:Feb 16 17:31:41 node teleport[860]: ERRO [SESSION:N] Timed out waiting for PTY copy to finish, session data for 91e6380d-d281-4891-9cc3-33154f17410e may be missing. srv/sess.go:813

/var/log/syslog:Feb 16 17:31:46 node teleport[860]: ERRO [SESSION:N] Failed to emit session print event. error:audit writer is closed events/auditwriter.go:207

My gut feeling for both problems is that when the connection from the remote node to the server is broken, there seems to be a problem re-creating a new connection.

[thetuber]

Happened today again. I pulled everything related to the incoming IP and node id from the logs and got this:

DEBU [PROXY:SER] Ping <- 1.1.1.1:38370 latency:39.680236ms nodeID:XXX.teleport trace.fields:map[cluster:teleport] reversetunnel/localsite.go:405
WARN [PROXY] Subsystem request proxySubsys(cluster=default/teleport, host=SSEMWPW00011, port=0) failed: dialing through a tunnel: no tunnel connection found: no node reverse tunnel for XXX.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address. id:738514 local:10.60.146.131:3023 login:ubuntu remote:2.2.2.2:37996 teleportUser:thetuber regular/sshserver.go:1369
ERRO [NODE] dialing through a tunnel: no tunnel connection found: no node reverse tunnel for XXX.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address regular/sshserver.go:1549
WARN [PROXY] Subsystem request proxySubsys(cluster=default/teleport, host=SSEMWPW00011, port=0) failed: dialing through a tunnel: no tunnel connection found: no node reverse tunnel for XXX.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address. id:738548 local:10.60.146.131:3023 login:celona remote:3.3.3.3:38224 teleportUser:monitor regular/sshserver.go:1369
ERRO [NODE] dialing through a tunnel: no tunnel connection found: no node reverse tunnel for XXX.teleport found, dialing directly: dial tcp: address @Local-Node: missing port in address regular/sshserver.go:1549
DEBU [PROXY:SER] Ping <- 1.1.1.1:38370 latency:39.874352ms nodeID:XXX.teleport trace.fields:map[cluster:teleport] reversetunnel/localsite.go:405
DEBU [SSH:PROXY] Incoming connection 1.1.1.1:39768 -> 10.60.146.131:443 vesion: SSH-2.0-Go. sshutils/server.go:438
DEBU [SSH:PROXY] Closed connection 1.1.1.1:39768. sshutils/server.go:440

I even tried deleting the node with "tctl rm node/XXX". It deleted the node, but still wasn't able to log in later.

[thetuber]

Any ideas on this? I ran into this problem again today (though it's been going on for a while). This time, I used tcpkill to kill all connections from the remote node. Once the connection was killed, I'm guessing a new connection was established because I could now get in using tsh. The teleport.log file on both sides showed nothing during the re-establishment. It might not be so bad if I could find the remote IP address from the teleport server side, but I need a connection on the remote to find this out (which I had through a secondary connection).

[ottobolyos]

This error happend to me on one node only after upgrade to version 12.3.2, however, I can connect to the node via tsh ssh without any issues. 🤷‍♂️

[webvictim]

What's the other method you're using to connect that fails? What error do you get?

[ottobolyos]

I have installed Teleport on Ubuntu 22.04 LTS directly on the host (not in a Docker container). I run Teleport in SystemD service and the error is in the output of systemctl status teleport.

As I have already said, I can connect to the node via tsh ssh without any issues.