search

zowe / zlux

The top-level superproject for zLUX. zLUX includes the Zowe Desktop framework in addition to several built-in apps and an example server implementation.
Eclipse Public License 2.0
38 stars 42 forks source link

Neither TN3270 nor VT Terminal work on 7554 APIML port #977

Open Jack-Billings-IBM opened 11 months ago

Jack-Billings-IBM commented 11 months ago

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])```
1000TurquoisePogs commented 11 months ago

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

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 commented 11 months ago

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

Jack-Billings-IBM commented 11 months ago

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.

pablocarle commented 11 months ago

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.

1000TurquoisePogs commented 11 months ago

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 commented 11 months ago

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.

Jack-Billings-IBM commented 11 months ago

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 commented 5 months ago

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

1000TurquoisePogs commented 5 months ago

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 commented 4 months ago
gidon-lando commented 4 months ago

Hello,