<< Back to previous view |
[QB-3212] QuickBuild Agent in a restart loop on macOS due to java.net.BindException: Address already in use
|
|
Status: | Resolved |
Project: | QuickBuild |
Component/s: | None |
Affects Version/s: | 7.0.28 |
Fix Version/s: | None |
Type: | Bug | Priority: | Major |
Reporter: | Sebastian Potasiak | Assigned To: | Robin Shen |
Resolution: | Fixed | Votes: | 0 |
Remaining Estimate: | Unknown | Time Spent: | Unknown |
Original Estimate: | Unknown | ||
Environment: |
Mac mini 7.1 - macOS Sierra
CPU: Intel Core i7 2 cores 3GHz RAM: 16GB uname -a Darwin **** 16.7.0 Darwin Kernel Version 16.7.0: Thu Jun 15 17:36:27 PDT 2017; root:xnu-3789.70.16~2/RELEASE_X86_64 x86_64 sw_vers ProductName: Mac OS X ProductVersion: 10.12.6 BuildVersion: 16G29 |
Description |
We have multiple Mac mini machines with the same configuration, and the issue already happened on three of them in span of 2 days.
These machines are running QB agents for couple days or weeks. Without any obvious reason Java for the agent gets caught in a restart loop (we can see that by watching status of QB agent): QuickBuild Build Agent is not running. QuickBuild Build Agent is running: PID:7918, Wrapper:STARTING, Java:STARTING QuickBuild Build Agent is running: PID:7918, Wrapper:STARTED, Java:STARTED QuickBuild Build Agent is running: PID:7918, Wrapper:STARTED, Java:STOPPING QuickBuild Build Agent is running: PID:7918, Wrapper:STARTED, Java:STOPPED QuickBuild Build Agent is running: PID:7918, Wrapper:STOPPING, Java:DOWN_CLEAN QuickBuild Build Agent is not running. The QB agent is then unusable. In processes we can see that there is a Java process for QB agent running, but every few seconds a second one appears and disappears shortly after. It looks like the agent have hanged for some reason, still has port bind to it, and tries to start another instance. console.log: wrapper | --> Wrapper Started as Daemon wrapper | Java Service Wrapper Standard Edition 64-bit 3.5.26 wrapper | Copyright (C) 1999-2014 Tanuki Software, Ltd. All Rights Reserved. wrapper | http://wrapper.tanukisoftware.com wrapper | Licensed to PMEase Inc. for QuickBuild wrapper | wrapper | Launching a JVM... jvm 1 | WrapperManager: Initializing... jvm 1 | 2018-06-21 15:24:26,212 INFO - Cleaning cached plugin libraries... jvm 1 | 2018-06-21 15:24:26,258 INFO - Cleaning temp directory... jvm 1 | 2018-06-21 15:24:26,261 INFO - Benchmarking... jvm 1 | 2018-06-21 15:24:27,774 INFO - Connecting to server 'https://navkit-quickbuild.tomtomgroup.com'... jvm 1 | 2018-06-21 15:24:28,054 INFO - Updating framework... jvm 1 | 2018-06-21 15:24:28,280 INFO - Updating plugins... jvm 1 | 2018-06-21 15:24:28,321 INFO - Updating plugins/com.pmease.quickbuild.libs... jvm 1 | 2018-06-21 15:24:28,431 INFO - Updating asset... jvm 1 | 2018-06-21 15:24:28,546 INFO - Booting QuickBuild from '/opt/buildagent'... jvm 1 | 2018-06-21 15:24:28,547 INFO - Starting framework... jvm 1 | 2018-06-21 15:24:28,573 INFO - Caching plugin libraries... jvm 1 | 2018-06-21 15:24:30,086 WARN - FAILED ServerConnector@78e2abd8{HTTP/1.1}{0.0.0.0:8811}: java.net.BindException: Address already in use jvm 1 | java.net.BindException: Address already in use jvm 1 | at sun.nio.ch.Net.bind0(Native Method) jvm 1 | at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at com.pmease.quickbuild.Quickbuild.startJettyServer(Quickbuild.java:389) jvm 1 | at com.pmease.quickbuild.Quickbuild.start(Quickbuild.java:252) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.equinoxadapter.EquinoxAdapter.startup(EquinoxAdapter.java:59) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.boot(Bootstrap.java:576) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.main(Bootstrap.java:126) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:316) jvm 1 | at java.lang.Thread.run(Thread.java:745) jvm 1 | 2018-06-21 15:24:30,093 WARN - FAILED ServerConnector@78e2abd8{HTTP/1.1}{0.0.0.0:8811}: java.net.BindException: Address already in use jvm 1 | java.net.BindException: Address already in use jvm 1 | at sun.nio.ch.Net.bind0(Native Method) jvm 1 | at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at com.pmease.quickbuild.Quickbuild.startJettyServer(Quickbuild.java:389) jvm 1 | at com.pmease.quickbuild.Quickbuild.start(Quickbuild.java:252) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.equinoxadapter.EquinoxAdapter.startup(EquinoxAdapter.java:59) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.boot(Bootstrap.java:576) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.main(Bootstrap.java:126) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:316) jvm 1 | at java.lang.Thread.run(Thread.java:745) jvm 1 | 2018-06-21 15:24:30,094 WARN - FAILED org.eclipse.jetty.server.Server@67855b6a: MultiException[java.net.BindException: Address already in use, java.net.BindException: Address already in use] jvm 1 | MultiException[java.net.BindException: Address already in use, java.net.BindException: Address already in use] jvm 1 | at org.eclipse.jetty.server.Server.doStart(Server.java:329) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at com.pmease.quickbuild.Quickbuild.startJettyServer(Quickbuild.java:389) jvm 1 | at com.pmease.quickbuild.Quickbuild.start(Quickbuild.java:252) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.equinoxadapter.EquinoxAdapter.startup(EquinoxAdapter.java:59) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.boot(Bootstrap.java:576) jvm 1 | at com.pmease.quickbuild.bootstrap.Bootstrap.main(Bootstrap.java:126) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:316) jvm 1 | at java.lang.Thread.run(Thread.java:745) jvm 1 | Suppressed: java.net.BindException: Address already in use jvm 1 | at sun.nio.ch.Net.bind0(Native Method) jvm 1 | at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | ... 20 more jvm 1 | Caused by: java.net.BindException: Address already in use jvm 1 | at sun.nio.ch.Net.bind0(Native Method) jvm 1 | at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | ... 20 more jvm 1 | WrapperStartStopApp: jvm 1 | WrapperStartStopApp Error: Encountered an error running start main: java.lang.reflect.InvocationTargetException jvm 1 | WrapperStartStopApp Error: java.lang.reflect.InvocationTargetException jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | WrapperStartStopApp Error: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | WrapperStartStopApp Error: at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.bootstrap.Bootstrap.boot(Bootstrap.java:576) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.bootstrap.Bootstrap.main(Bootstrap.java:126) jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | WrapperStartStopApp Error: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | WrapperStartStopApp Error: at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | WrapperStartStopApp Error: at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:316) jvm 1 | WrapperStartStopApp Error: at java.lang.Thread.run(Thread.java:745) jvm 1 | WrapperStartStopApp Error: Caused by: java.lang.RuntimeException: java.lang.reflect.InvocationTargetException jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.bootstrap.BootstrapUtils.wrapAsUnchecked(BootstrapUtils.java:56) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.equinoxadapter.EquinoxAdapter.startup(EquinoxAdapter.java:61) jvm 1 | WrapperStartStopApp Error: ... 12 more jvm 1 | WrapperStartStopApp Error: Caused by: java.lang.reflect.InvocationTargetException jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jvm 1 | WrapperStartStopApp Error: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jvm 1 | WrapperStartStopApp Error: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jvm 1 | WrapperStartStopApp Error: at java.lang.reflect.Method.invoke(Method.java:498) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.equinoxadapter.EquinoxAdapter.startup(EquinoxAdapter.java:59) jvm 1 | WrapperStartStopApp Error: ... 12 more jvm 1 | WrapperStartStopApp Error: Caused by: java.lang.RuntimeException: MultiException[java.net.BindException: Address already in use, java.net.BindException: Address already in use] jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.bootstrap.BootstrapUtils.wrapAsUnchecked(BootstrapUtils.java:56) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.Quickbuild.startJettyServer(Quickbuild.java:391) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.Quickbuild.start(Quickbuild.java:252) jvm 1 | WrapperStartStopApp Error: ... 17 more jvm 1 | WrapperStartStopApp Error: Caused by: MultiException[java.net.BindException: Address already in use, java.net.BindException: Address already in use] jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:329) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | WrapperStartStopApp Error: at com.pmease.quickbuild.Quickbuild.startJettyServer(Quickbuild.java:389) jvm 1 | WrapperStartStopApp Error: ... 18 more jvm 1 | WrapperStartStopApp Error: Suppressed: java.net.BindException: Address already in use jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind0(Native Method) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | WrapperStartStopApp Error: ... 20 more jvm 1 | WrapperStartStopApp Error: Caused by: java.net.BindException: Address already in use jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind0(Native Method) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind(Net.java:433) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.Net.bind(Net.java:425) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) jvm 1 | WrapperStartStopApp Error: at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:321) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) jvm 1 | WrapperStartStopApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:366) jvm 1 | WrapperStartStopApp Error: ... 20 more jvm 1 | 2018-06-21 15:24:31,152 INFO - Stopping QuickBuild agent... jvm 1 | 2018-06-21 15:24:31,315 INFO - Disconnecting from server... jvm 1 | 2018-06-21 15:24:31,428 INFO - Waiting for finish of existing jobs... jvm 1 | 2018-06-21 15:24:31,429 INFO - Stopping plugins... jvm 1 | 2018-06-21 15:24:31,432 INFO - Stopping task scheduler... jvm 1 | 2018-06-21 15:24:31,462 INFO - QuickBuild agent stopped. wrapper | <-- Wrapper Stopped Unfortunately we do not have logs for what have happened before this restart loop since these restarts filled all log files during the night. I will try to provide it when it happens again though. |
Comments |
Comment by Sebastian Potasiak [ 21/Jun/18 01:51 PM ] |
Forgot to write it down: killing the hanging Java process fixes the issue (probably only temporarily).
The process: /opt/buildagent/bin/./wrapper-macosx-universal-64 /opt/buildagent/bin/../conf/wrapper.conf wrapper.syslog.ident=quickbuild wrapper.pidfile=/opt/buildagent/bin/./quickbuild.pid wrapper.name=quickbuild wrapper.displayname=QuickBuild Build Agent wrapper.daemonize=TRUE wrapper.statusfile=/opt/buildagent/bin/./quickbuild.status wrapper.java.statusfile=/opt/buildagent/bin/./quickbuild.java.status wrapper.script.version=3.5.26 |