Timeout when connecting maven daemon

[naosense]

mvnd-0.8.2-darwin-aarch64

❯ mvd8 -Dmaven.test.skip=true -Dmvnd.jvmArgs=-XX:-MaxFDLimit clean package
Exception in thread "main" org.mvndaemon.mvnd.common.DaemonException$ConnectException: Could not connect to the Maven daemon.
Daemon id: cdd5bde8
  log file: /Users/xxx/.m2/mvnd/registry/1.0.0-m1/daemon-cdd5bde8.log
----- Last  200 lines from daemon log file - /Users/xxx/.m2/mvnd/registry/1.0.0-m1/daemon-cdd5bde8.log -----
10:46:42.366 D Initializing daemon with properties:
     mvnd.home=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64
     jdk.java.options=--add-opens java.base/java.io=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/sun.net.www.protocol.jar=ALL-UNNAMED --add-opens java.base/sun.nio.fs=ALL-UNNAMED
     mvnd.noDaemon=false
     mvnd.debug=false
     mvnd.debug.address=8000
     mvnd.idleTimeout=3h
     mvnd.keepAlive=100ms
     mvnd.extClasspath=
     mvnd.coreExtensions=
     mvnd.jvmArgs=-XX:-MaxFDLimit
     mvnd.enableAssertions=false
     mvnd.expirationCheckDelay=10s
     mvnd.duplicateDaemonGracePeriod=10s
     mvnd.socketFamily=inet

10:46:42.371 I Daemon started
10:46:42.371 D daemon is running. Sleeping until state changes.
----- End of the daemon log file -----
  output: /Users/xxx/.m2/mvnd/registry/1.0.0-m1/daemon-cdd5bde8.out.log
----- Last  200 lines from daemon output - /Users/xxx/.m2/mvnd/registry/1.0.0-m1/daemon-cdd5bde8.out.log -----
Starting daemon process: id = cdd5bde8, workingDir = /Users/xxx/project/0work/broadway, daemonArgs: /Users/xxx/Library/Java/JavaVirtualMachines/azul-1.8.0_352/Contents/Home/bin/java -classpath /Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/mvn/lib/ext/mvnd-common-1.0.0-m1.jar:/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/mvn/lib/ext/mvnd-agent-1.0.0-m1.jar -javaagent:/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/mvn/lib/ext/mvnd-agent-1.0.0-m1.jar -XX:-MaxFDLimit -Dmvnd.home=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64 -Dmaven.home=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/mvn -Dmaven.conf=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/mvn/conf -Dmvnd.java.home=/Users/xxx/Library/Java/JavaVirtualMachines/azul-1.8.0_352/Contents/Home -Dlogback.configurationFile=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64/conf/logback.xml -Dmvnd.id=cdd5bde8 -Dmvnd.daemonStorage=/Users/xxx/.m2/mvnd/registry/1.0.0-m1 -Dmvnd.registry=/Users/xxx/.m2/mvnd/registry/1.0.0-m1/registry.bin -Dmvnd.socketFamily=inet -Dmvnd.home=/Users/xxx/bin/mvnd-1.0.0-m1-darwin-aarch64 -Djdk.java.options=--add-opens java.base/java.io=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/sun.net.www.protocol.jar=ALL-UNNAMED --add-opens java.base/sun.nio.fs=ALL-UNNAMED -Dmvnd.noDaemon=false -Dmvnd.debug=false -Dmvnd.debug.address=8000 -Dmvnd.idleTimeout=3h -Dmvnd.keepAlive=100ms -Dmvnd.extClasspath= -Dmvnd.coreExtensions= -Dmvnd.jvmArgs=-XX:-MaxFDLimit -Dmvnd.enableAssertions=false -Dmvnd.expirationCheckDelay=10s -Dmvnd.duplicateDaemonGracePeriod=10s -Dmvnd.socketFamily=inet org.mvndaemon.mvnd.common.MavenDaemon
----- End of the daemon output -----

        at org.mvndaemon.mvnd.client.DaemonConnector.connectToDaemonWithId(DaemonConnector.java:499)
        at org.mvndaemon.mvnd.client.DaemonConnector.startDaemon(DaemonConnector.java:308)
        at org.mvndaemon.mvnd.client.DaemonConnector.connect(DaemonConnector.java:128)
        at org.mvndaemon.mvnd.client.DefaultClient.execute(DefaultClient.java:327)
        at org.mvndaemon.mvnd.client.DefaultClient.main(DefaultClient.java:152)
Caused by: org.mvndaemon.mvnd.common.DaemonException$ConnectException: Could not connect to server /127.0.0.1:49200.
        at org.mvndaemon.mvnd.client.DaemonConnector.connect(DaemonConnector.java:583)
        at org.mvndaemon.mvnd.client.DaemonConnector.connectToDaemon(DaemonConnector.java:510)
        at org.mvndaemon.mvnd.client.DaemonConnector.connectToDaemonWithId(DaemonConnector.java:495)
        ... 4 more
Caused by: java.io.IOException: Timeout
        at org.mvndaemon.mvnd.client.DaemonConnector.connect(DaemonConnector.java:559)
        ... 6 more

[Markus-F-Frisch]

Same here - if I manually increase the timeout in DaemonConnector.CONNECT_TIMEOUT and rebuild mvnd then it seems to work. The problem startet when the company rolled out additional security surveillence agents on the machines, I guess they slow down the connection establishment leading to a timeout. If I interpret wireshark captures correctly, this is what's happening.
Maybe making this timeout configurable would solve the problem?

[gnodet]

I've created #772 to make the timeous configurable.
I've also raised the default socket connect timeout from 10 ms to 1 second. It seems the code messed between units, getting the time using nanoTime, adding microseconds to it...

[adamretter]

@gnodet Thanks for the configurable timeouts, however I think I am still seeing problems in mvnd 0.9.0 that this doesn't seem to help with.

When calling:

mvnd -D'mvnd.connectTimeout=90 seconds' --version

In GitHub Actions on the Windows and macOS runners this seems to still result in a:

Exception in thread "main" org.mvndaemon.mvnd.common.DaemonException$ConnectException: Timeout waiting to connect to the Maven daemon.

Full log is here - https://github.com/eXist-db/exist/actions/runs/4656874086/jobs/8240918019#step:4:204

[adamretter]

@gnodet Sorry to ask again, but any further insight you could provide on this would be very helpful...

[adamretter]

@gnodet Any chance of some feedback on this? It is preventing us from using mvnd.

[ppalaga]

@adamretter could you please try with the latest mvnd release? Do all those installation steps work for you locally on a fresh Windows machine? It would be nice to see in which state is the daemon process when client gives up trying to connect. Is the daemon process alive at all - to check that , you could add some sort of windows counterpart of ps | grep java to your GH actions script. Is it listening on the requested port (I'd do netstat -tulpen | grep java on linux)?

[ppalaga]

Does a mvnd installed via chocolatey work any better?

[adamretter]

I just tried updating to mvnd version 1.0-m6-m40, unfortunately it has made no difference to this issue. The output can be seen here in CI - https://github.com/eXist-db/exist/actions/runs/4956482660/jobs/8866980235
The pertinent parts are:

/tmp/maven-mvnd-1.0-m6-m40-windows-amd64/bin/mvnd -D'mvnd.connectTimeout=90 seconds' --version

May 12, 2023 7:51:16 AM org.jline.utils.Log logr
WARNING: Unable to create a system terminal, creating a dumb terminal (enable debug logging for more information)
[main] WARN org.jline - Unable to create a system terminal, creating a dumb terminal (enable debug logging for more information)
Apache Maven Daemon (mvnd) 1.0-m6 windows-amd64 native client (47d4c6b9c399079d91312bb8ae35d1d76e7fd97a)
Terminal: org.jline.terminal.impl.DumbTerminal
Error: Exception in thread "main" org.mvndaemon.mvnd.common.DaemonException$ConnectException: Timeout waiting to connect to the Maven daemon.
Daemon id: a1c12bd7
  no log file at: C:\Users\runneradmin\.m2\mvnd\registry\1.0-m6\daemon-a1c12bd7.log
  output: C:\Users\runneradmin\.m2\mvnd\registry\1.0-m6\daemon-a1c12bd7.out.log
----- Last  200 lines from daemon output - C:\Users\runneradmin\.m2\mvnd\registry\1.0-m6\daemon-a1c12bd7.out.log -----
Starting daemon process: id = a1c12bd7, workingDir = D:\a\exist\exist, daemonArgs: C:\hostedtoolcache\windows\Java_Temurin-Hotspot_jdk\17.0.7-7\x64\bin\java.exe -classpath C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\mvn\boot\plexus-classworlds-2.6.0.jar -javaagent:C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\mvn\lib\mvnd\mvnd-agent-1.0-m6.jar -Dmvnd.home=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64 -Dmaven.home=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\mvn -Dmaven.conf=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\mvn\conf -Dclassworlds.conf=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\bin\mvnd-daemon.conf -Dmvnd.java.home=C:\hostedtoolcache\windows\Java_Temurin-Hotspot_jdk\17.0.7-7\x64 -Dlogback.configurationFile=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64\mvn\conf\logging\logback-daemon.xml -Dmvnd.id=a1c12bd7 -Dmvnd.daemonStorage=C:\Users\runneradmin\.m2\mvnd\registry\1.0-m6 -Dmvnd.registry=C:\Users\runneradmin\.m2\mvnd\registry\1.0-m6\registry.bin -Dmvnd.socketFamily=inet -Dmvnd.home=C:\Users\RUNNER~1\AppData\Local\Temp\maven-mvnd-1.0-m6-m40-windows-amd64 -Djdk.java.options=--add-opens java.base/java.io=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/sun.net.www.protocol.jar=ALL-UNNAMED --add-opens java.base/sun.nio.fs=ALL-UNNAMED -Dmvnd.noDaemon=false -Dmvnd.debug=false -Dmvnd.debug.address=8000 -Dmvnd.idleTimeout=3h -Dmvnd.keepAlive=100ms -Dmvnd.extClasspath= -Dmvnd.coreExtensions= -Dmvnd.enableAssertions=false -Dmvnd.expirationCheckDelay=10s -Dmvnd.duplicateDaemonGracePeriod=10s -Dmvnd.socketFamily=inet org.codehaus.plexus.classworlds.launcher.LauncherNOTE: Picked up JDK_JAVA_OPTIONS: --add-opens java.base/java.io=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/sun.net.www.protocol.jar=ALL-UNNAMED --add-opens java.base/sun.nio.fs=ALL-UNNAMED
----- End of the daemon output -----

	at org.mvndaemon.mvnd.client.DaemonConnector.startDaemon(DaemonConnector.java:329)
	at org.mvndaemon.mvnd.client.DaemonConnector.connect(DaemonConnector.java:122)
	at org.mvndaemon.mvnd.client.DefaultClient.execute(DefaultClient.java:331)
	at org.mvndaemon.mvnd.client.DefaultClient.main(DefaultClient.java:157)
Error: Process completed with exit code 1.

Do all those installation steps work for you locally on a fresh Windows machine?

I will test that next and come back to you...

It would be nice to see in which state is the daemon process when client gives up trying to connect. Is the daemon process alive at all - to check that , you could add some sort of windows counterpart of ps | grep java to your GH actions script. Is it listening on the requested port (I'd do netstat -tulpen | grep java on linux)?

I am not sure that is something we can test inside GitHub Actions CI as it runs one process after another and is non-interactive.

[ppalaga]

It would be nice to see in which state is the daemon process when client gives up trying to connect. Is the daemon process alive at all - to check that , you could add some sort of windows counterpart of ps | grep java to your GH actions script. Is it listening on the requested port (I'd do netstat -tulpen | grep java on linux)?

I am not sure that is something we can test inside GitHub Actions CI as it runs one process after another and is non-interactive.

You can put those commands right after the mvnd invocation, possibly in an "on failure" block. GH actions has some special syntax for that. I am really curious, whether the daemon process is still up when the client gives up waiting. If it is not up then you need to find out what prevents it from starting, e.g. by trying to invoke that logged java.exe -classpath ... command directly.
If it is up, it would be interesting to see what state is it in, e.g. by inspecting its heapdump. Is it blocked by something? Is it just too slow (because the GHA machine is so underpowered)?