zlux icon indicating copy to clipboard operation
zlux copied to clipboard

Published 20 hours ago • verified publisher icon zowe

Neither TN3270 nor VT Terminal work on 7554 APIML port

Open Jack-Billings-IBM opened this issue 1 year ago • 11 comments

We have an issue where the TN3270 and VT Terminal in Zowe Desktop v2.9 fail to consistently connect. When clearing cookies the connection will work but on subsequent attempts, the desktop behind APIML (7754) stops working again. Some discussion of the same problem in https://github.com/zowe/api-layer/issues/2603. Opening a new issue in the Zlux repository.

Logs below with both Gateway websocket debugging enabled and terminal logs. There's no indication of issues in the API Gateway. The code 4000 comes from the TN3270 and VT Terminal's code. Also note the different domain, for Gateway it's mvst.host.com and for the terminal this is omvst.host.com.

2023-06-26 13:19:56.240 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-2:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketRoutedSession) sendMessageToServer(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=30, last=true])
2023-06-26 13:19:56.245 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=32, last=true])
2023-06-26 13:19:56.267 <ZWEAGW1:HttpClient@cfe6b335-30:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=48, last=true])
2023-06-26 13:19:56.269 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=32, last=true])
2023-06-26 13:19:56.272 <ZWEAGW1:HttpClient@cfe6b335-30:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=556, last=true])
2023-06-26 13:19:56.294 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-9:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyServerHandler) handleMessage(session=StandardWebSocketSession[id=88765552-f94f-bdc8-3039-21984e1459fd, uri=wss://mvst.host.com:7554/zlux/ws/v1/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=46, last=true])
2023-06-26 13:19:56.294 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-9:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketRoutedSession) sendMessageToServer(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=46, last=true])
2023-06-26 13:19:57.675 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=18
2023-06-26 13:19:57.676 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=52
2023-06-26 13:19:57.407 <ZWEAGW1:RibbonApacheHttpClientConfiguration.connectionManagerTimer:67109295> ZWESVUSR DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Closing expired connections
2023-06-26 13:19:57.677 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=52, last=true])


2023-06-26 13:19:56.242 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:265) ZWED0269I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket client message received. Length=30
2023-06-26 13:19:56.242 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:394) ZWED0275I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Writing to host socket. Length=1
2023-06-26 13:19:56.243 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=2
2023-06-26 13:19:56.244 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=32
2023-06-26 13:19:56.266 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=15
2023-06-26 13:19:56.266 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=48
2023-06-26 13:19:56.268 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=2
2023-06-26 13:19:56.268 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=32
2023-06-26 13:19:56.269 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=395
2023-06-26 13:19:56.269 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=556
2023-06-26 13:19:56.295 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:265) ZWED0269I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket client message received. Length=46
2023-06-26 13:19:56.295 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:394) ZWED0275I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Writing to host socket. Length=15
2023-06-26 13:19:56.240 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-2:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyServerHandler) handleMessage(session=StandardWebSocketSession[id=88765552-f94f-bdc8-3039-21984e1459fd, uri=wss://mvst.host.com:7554/zlux/ws/v1/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=30, last=true])
2023-06-26 13:19:56.240 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-2:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketRoutedSession) sendMessageToServer(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=30, last=true])
2023-06-26 13:19:56.245 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=32, last=true])
2023-06-26 13:19:56.267 <ZWEAGW1:HttpClient@cfe6b335-30:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=48, last=true])
2023-06-26 13:19:56.269 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=32, last=true])
2023-06-26 13:19:56.272 <ZWEAGW1:HttpClient@cfe6b335-30:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=556, last=true])
2023-06-26 13:19:56.294 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-9:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyServerHandler) handleMessage(session=StandardWebSocketSession[id=88765552-f94f-bdc8-3039-21984e1459fd, uri=wss://mvst.host.com:7554/zlux/ws/v1/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=46, last=true])
2023-06-26 13:19:56.294 <ZWEAGW1:https-jsse-nio-0.0.0.0-7554-exec-9:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketRoutedSession) sendMessageToServer(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"VT_I..], byteCount=46, last=true])
2023-06-26 13:19:57.675 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:411) ZWED0277I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Received host data. Length=18
2023-06-26 13:19:57.676 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:400) ZWED0276I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket sending client message. Length=52
2023-06-26 13:19:57.677 <ZWEAGW1:HttpClient@cfe6b335-29:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) handleMessage(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],message=TextMessage payload=[{"t":"TELN..], byteCount=52, last=true])
2023-06-26 13:20:01.392 <ZWED:67109955> ZWESVUSR INFO (org.zowe.terminal.proxy:vtdata,terminalProxy.js:210) ZWED0097I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Websocket closed. Total remaining terminals connected: 0
2023-06-26 13:20:01.392 <ZWED:67109955> ZWESVUSR INFO (org.zowe.terminal.proxy:vtdata,terminalProxy.js:221) ZWED0100I - Total VT terminals connected: 0
2023-06-26 13:20:01.393 <ZWED:67109955> ZWESVUSR DEBUG (org.zowe.terminal.proxy:vtdata,terminalProxy.js:607) ZWED0282I - [Host=omvst.host.com, Port=23, ClientIP=10.120.10.214] Error: Host closed socket
2023-06-26 13:20:01.387 <ZWEAGW1:HttpClient@cfe6b335-30:67109295> ZWESVUSR DEBUG (o.z.a.g.w.WebSocketProxyClientHandler) afterConnectionClosed(session=JettyWebSocketSession[id=07202884-77f4-c982-132f-68152e54c5d2, uri=wss://mvst.host.com:7556/ZLUX/plugins/org.zowe.terminal.vt/services/terminalstream/_current/],status=CloseStatus[code=4000, reason=Closed by user])```

Jack-Billings-IBM avatar Jul 18 '23 14:07 Jack-Billings-IBM

https://github.com/zowe/zlux-server-framework/blob/v2.x/staging/plugins/terminal-proxy/lib/terminalProxy.js#L406 code 4000 occurs in two cases,

  • the host (as in, the TN3270 or SSH server of z/os) closed the connection on us. That can for example happen if you type exit in SSH. It can also happen if there's simply a timeout on the TN3270 or SSH server.
  • the websocket sent a message when its status was not ready. sounds impossible without an upstream bug, i think that one is there for sanity check.

So it's probably the first one: the host closed the connection for some reason. The terminals include a TCP to Websocket proxy. True TN3270 and SSH connections are TCP connections. The websocket carries the data to the browser. When the TCP connection closes, the websocket must also close, and it does so with code 4000.

1000TurquoisePogs avatar Jul 18 '23 15:07 1000TurquoisePogs

Your log confirms that this part of the code is hit https://github.com/zowe/zlux-server-framework/blob/v2.x/staging/plugins/terminal-proxy/lib/terminalProxy.js#L605-L607 So yes, the TCP connection was closed, leading to the websocket being closed. I've seen that happen due to inactivity of sorts. Some servers are set up to close sessions that are inactive for a period of time. When do you experience your disconnections? Is it

  • terminals are slow to connect, and cause error before ever seeing the screen?
  • terminals connect, but then sometime later disconnect?

1000TurquoisePogs avatar Jul 18 '23 16:07 1000TurquoisePogs

Thanks for the feedback @1000TurquoisePogs Some users are able to connect with no problems while others are not able to connect at all. The answer to your question is the first one: The terminals are slow to connect and cause an error before ever seeing the screen.

Jack-Billings-IBM avatar Jul 18 '23 16:07 Jack-Billings-IBM

In our local instances, sometimes we see that after opening the VT Terminal, it will take several seconds of showing blank to show the login prompt. We don't see the connection dropping issue, just takes a while. Testing on the 2.10-RC2 Improvements were made in API ML to have longer inactivity timeouts a couple of versions past.

pablocarle avatar Jul 18 '23 17:07 pablocarle

Regarding the logs, here's what we see:

omvst versus mvst: the terminal proxy connects to what the browser asked for, though there may be dns resolution for hostnames. not sure if either the browser just originally asked for omvst, or if nodejs' query resolved in changing mvst to omvst?

disconnect: we see a disconnect code 4000 on the vt connection in the log. Before that happens, nothing unusual is in the logs. We see network activity going back and forth, and then the host closes the socket so the websocket gets closed to match, with code 4000 to state that's what happened.

With the timestamps, there's a few minute gap in between the last data and the disconnect. It doesn't mean the cause is timeouts, but the logs don't have further hints. Does your telnet server (appears to be telnet, rather than 3270 or ssh) have any timeouts configured?

some terminals have a 'keep alive' feature to keep a session open even in the presence of timeouts, by periodically sending something. Zowe's terminals do not.

1000TurquoisePogs avatar Jul 18 '23 17:07 1000TurquoisePogs

Regarding VT terminal being slow: when using ssh, the DH key exchange is just extremely slow. nodejs has some slow code there, and we looked around for alternative libraries but it didn't make much of a difference. It's just slow to connect unfortunately.

1000TurquoisePogs avatar Jul 18 '23 17:07 1000TurquoisePogs

With the timestamps, there's a few minute gap in between the last data and the disconnect. It doesn't mean the cause is timeouts, but the logs don't have further hints. Does your telnet server (appears to be telnet, rather than 3270 or ssh) have any timeouts configured?

The only TCP/IP timeout has to do with cleaning up stale or dead connections. It will check for a certain number of intervals, up to the timeout interval (around 32 minutes), then delete the connection if still no response.

Jack-Billings-IBM avatar Jul 20 '23 17:07 Jack-Billings-IBM

Hello - this problem is persisting with Zowe v2.13. Any guidance on how to resolve this VT terminal connection issue?

Jack-Billings-IBM avatar Feb 01 '24 16:02 Jack-Billings-IBM

Do you have a network analysis tool that could show where the connection gets dropped? As the logs say "Error: Host closed socket", Zowe has no information on why the other side of the network closed the socket. It could be any cause without more information.

1000TurquoisePogs avatar Feb 09 '24 18:02 1000TurquoisePogs

  • Is this still happening for 3270, or only VT/SSH?

  • If you type an IP instead of a hostname for the value of where to connect, does it prevent the 4000 disconnect? Regardless of that not being a permanent solution, it would be good to know if this "omvst.host.com" versus "mvst.host.com" difference can be avoided by use of IP

  • Do you have terminals outside of Zowe to compare to? I experienced terminal connection issues last week that I narrowed down to cipher negotiation. If you have another terminal that connects and you can inspect which TLS / SSH settings it connected with, it would be good to know if you were using a certain RSA cipher, ChaCha20-Poly1305, or whatever is the latest and greatest. I say this because I learned that when a cipher match can't be found, for SSH, neither the SSH host nor the Zowe client tells you that, they just close the connection mysteriously, so it's lucky I discovered it.

1000TurquoisePogs avatar Feb 20 '24 20:02 1000TurquoisePogs

Hello,

  • This is happening for 3270 and VT. We don't have SSH enabled on the Mainframe at the moment
  • We are getting the same results with an IP address
  • A user that is experiencing an issue connecting using telnet through zowe is able to connect using telnet through putty

gidon-lando avatar Feb 21 '24 15:02 gidon-lando