Hello Mike, thanks for hinting me to guacd logs.
Actually it was a combination of assumptions that all kind of failed: * all my hosts use letsencrypt certificates for RDP and VMConnect, except that the script failed on the specific host, * I do have property analogous to ignore-cert and it was set to true, but not processed in code, * the exceptions are unrelated, actually they even occur during successful connection establishment, but who cares. Guacd logs spotted the certificate to be untrusted. Once I fixed the setup script on the host, it was back running. Would it be possible to forward some of the error information to guacamole to make this easier? Also because guacd trace does not have any timestamps and thus correlation is difficult. Thanks, Joachim Von: Michael Jumper <[email protected]> Gesendet: Freitag, 23. Dezember 2022 00:12 An: [email protected] Betreff: Re: Race? I don't think you're looking at a race condition. The only error shown is from WebSocket, and that only indicates that the connection was closed. Depending on timing, the socket can be closed just before a message is sent. It doesn't mean that anything is wrong or even that the closure itself is unexpected. Can you describe what specifically isn't working? If it's the connection itself failing to establish, what about your guacd logs? - Mike On Thu, Dec 22, 2022, 3:19 AM Joachim Lindenberg <[email protected] <mailto:[email protected]> > wrote: Hello, I am encountering an issue that I am right now unable to resolve. I am running my own extension that does authentication and connection management and that used to work. It doesn´t any more – neither in the version I used for quite some time nor the version I did to implement a custom field. Thus I assume it is not related to the changes I did recently… With the newer version I have the following output in guacamole trace: guacamole | 10:41:39.448 [http-nio-8080-exec-1] LindenbergBackup:LindenbergBackupConnection.connect():protocol=rdp,.name=Cobra (Running),.enhancedmode=false,.vm=true,.user=null,.id=a563f81a-8a58-4627-abca-a047739d31e7,.state=Running,.group=(Virtual Machines),.backup=null,hostname=***,security=vmconnect,preconnection-blob=a563f81a-8a58-4627-abca-a047739d31e7,.image=null,port=2179,domain=samba,.identifier=Cobra,username=Joachim, guacamole | 10:41:39.448 [http-nio-8080-exec-1] INFO o.a.g.tunnel.TunnelRequestService - User "Joachim" connected to connection "Cobra". guacamole | 10:41:39.448 [http-nio-8080-exec-1] LindenbergBackup:LindenbergBackupConfiguration.connect()-Cobra (Running) guacamole | 10:41:39.522 [http-nio-8080-exec-3] DEBUG o.a.g.rest.RESTExceptionMapper - Client request rejected: No readable active connection for tunnel. guacamole | 10:41:39.524 [http-nio-8080-exec-2] DEBUG o.a.g.rest.RESTExceptionMapper - Client request rejected: Protocol of tunnel is not known/exposed. guacamole | 10:41:40.170 [http-nio-8080-exec-6] LindenbergBackup:LindenbergBackupConfiguration.close()-Cobra (Running) guacamole | 10:41:40.181 [http-nio-8080-exec-6] INFO o.a.g.tunnel.TunnelRequestService - User "Joachim" disconnected from connection "Cobra". Duration: 723 milliseconds in other words, the connection is established or about to be established (10:41:39.448 is the last “location” in my extension before returning) and then two other threads report errors and yet another thread closes the connection. In order to find the cause, I also tried throwing an exception and the stack trace is guacamole | Exception in thread "Thread-6" java.lang.IllegalStateException: Message will not be sent because the WebSocket session has been closed guacamole | at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:441) guacamole | at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:314) guacamole | at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:254) guacamole | at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:195) guacamole | at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37) guacamole | at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint.sendInstruction(GuacamoleWebSocketTunnelEndpoint.java:152) guacamole | at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint.access$200(GuacamoleWebSocketTunnelEndpoint.java:53) guacamole | at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint$2.run(GuacamoleWebSocketTunnelEndpoint.java:253) guacamole | java.io.IOException: who closes this? guacamole | at one.lindenberg.guacamole.LindenbergBackupConfiguration.close(LindenbergBackupConfiguration.java:119) guacamole | at one.lindenberg.guacamole.LindenbergBackupConfiguration.stateChange(LindenbergBackupConfiguration.java:124) guacamole | at one.lindenberg.guacamole.LindenbergBackupAuthenticationProvider.requestChange(LindenbergBackupAuthenticationProvider.java:164) guacamole | at one.lindenberg.guacamole.LindenbergBackupAuthenticationProvider.handleEvent(LindenbergBackupAuthenticationProvider.java:365) guacamole | at org.apache.guacamole.rest.event.ListenerService.handleEvent(ListenerService.java:53) guacamole | at org.apache.guacamole.tunnel.TunnelRequestService.fireTunnelClosedEvent(TunnelRequestService.java:114) guacamole | at org.apache.guacamole.tunnel.TunnelRequestService.access$000(TunnelRequestService.java:51) guacamole | at org.apache.guacamole.tunnel.TunnelRequestService$1.close(TunnelRequestService.java:277) guacamole | at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint.onClose(GuacamoleWebSocketTunnelEndpoint.java:364) guacamole | at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:759) guacamole | at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:740) guacamole | at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:367) guacamole | at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:296) guacamole | at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:133) guacamole | at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:85) guacamole | at org.apache.tomcat.websocket.server.WsFrameServer.doOnDataAvailable(WsFrameServer.java:183) guacamole | at org.apache.tomcat.websocket.server.WsFrameServer.notifyDataAvailable(WsFrameServer.java:162) guacamole | at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:157) guacamole | at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60) guacamole | at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59) guacamole | at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) guacamole | at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673) guacamole | at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) guacamole | at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) guacamole | at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) guacamole | at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) guacamole | at java.lang.Thread.run(Thread.java:748) I also tried to ignore the first close, but that didn´t help either. To me it looks like a race condition, but no idea where and how to resolve it. Any suggestion what to try or look for? Thanks, Joachim
