History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QB-3212
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Major Major
Assignee: Robin Shen
Reporter: Sebastian Potasiak
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
QuickBuild

QuickBuild Agent in a restart loop on macOS due to java.net.BindException: Address already in use

Created: 21/Jun/18 01:49 PM   Updated: 28/Feb/19 03:10 PM
Component/s: None
Affects Version/s: 7.0.28
Fix Version/s: None

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: 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  « Hide
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.

 All   Comments   Work Log   Change History      Sort Order:
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