tomcat 8 will not startup on free port

2019-03-05 06:01发布

站内文章 / 移动开发
31 0 0

问题:

PROBLEM

Stop->Start of tomcat 8 via windows services fails as tomcat shutdown somehow keeps listening on port 8080 in an "invisible" state and tomcat fails to startup as it cannot bind to port 8080

BACKGROUND

One of our build scripts, which restarts tomcat windows service, started to fail a few weeks back. Coming back from holidays I am now trying to resolve the issue. As far as I can see no changes has been done to the tomcat configuration.

REPRODUCING THE PROBLEM

Tomcat shuts down clean (via windows service stop) without errors:

10-Aug-2018 19:30:56.860 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-apr-8080"]
10-Aug-2018 19:30:56.860 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["ajp-apr-8009"]
10-Aug-2018 19:30:56.923 INFO [Thread-4] org.apache.catalina.core.StandardService.stopInternal Stopping service Catalina
10-Aug-2018 19:30:56.985 INFO [Thread-4] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-apr-8009"]

All tomcat ports are free:

C:\Windows\system32>netstat -abno | find "80"
TCP    0.0.0.0:49160          0.0.0.0:0              LISTENING       1180
TCP    [::]:49160             [::]:0                 LISTENING       1180
UDP    0.0.0.0:123            *:*                                    980
UDP    [::]:123               *:*                                    980

As we can see the default tomcat port 8080 is free (not present in list)

windows report the "apache tomcat" service to be stopped.

Task manager has no process for "tomcat8w.exe"

I start the tomcat by starting the windows service and get the following in catalina log:

10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.0.32
10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Feb 2 2016 19:34:53 UTC
10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.0.32.0
10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Windows Server 2012 R2
10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            6.3
10-Aug-2018 19:36:50.018 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             d:\ng\jre
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_73-b02
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         D:\ng\tomcat
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         D:\ng\tomcat
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=D:\ng\tomcat
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=D:\ng\tomcat
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=D:\ng\tomcat\endorsed
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=D:\ng\tomcat\temp
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManage
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=D:\ng\tomcat\conf\logging.proper
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: exit
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms1024m
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx6144m
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR based Apache Tomcat Native library 1.2.4 using APR version 1.5.1.
10-Aug-2018 19:36:50.033 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [
10-Aug-2018 19:36:50.549 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized (OpenSSL 1.0.2e 3 Dec 2015)
10-Aug-2018 19:36:50.674 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-apr-8080"]
10-Aug-2018 19:36:50.674 SEVERE [main] org.apache.coyote.AbstractProtocol.init Failed to initialize end point associated with ProtocolHandler ["http-apr-8080"]
 java.lang.Exception: Socket bind failed: [730048] Only one usage of each socket address (protocol/network address/port) is normally permitted.
        at org.apache.tomcat.util.net.AprEndpoint.bind(AprEndpoint.java:471)
        at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:742)
        at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:458)
        at org.apache.catalina.connector.Connector.initInternal(Connector.java:960)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        at org.apache.catalina.core.StandardService.initInternal(StandardService.java:568)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:851)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        at org.apache.catalina.startup.Catalina.load(Catalina.java:580)
        at org.apache.catalina.startup.Catalina.load(Catalina.java:603)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484)

10-Aug-2018 19:36:50.689 SEVERE [main] org.apache.catalina.core.StandardService.initInternal Failed to initialize connector [Connector[HTTP/1.1-8080]]
 org.apache.catalina.LifecycleException: Failed to initialize component [Connector[HTTP/1.1-8080]]
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:106)
        at org.apache.catalina.core.StandardService.initInternal(StandardService.java:568)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:851)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        at org.apache.catalina.startup.Catalina.load(Catalina.java:580)
        at org.apache.catalina.startup.Catalina.load(Catalina.java:603)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484)
Caused by: org.apache.catalina.LifecycleException: Protocol handler initialization failed
        at org.apache.catalina.connector.Connector.initInternal(Connector.java:962)
        at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
        ... 12 more
Caused by: java.lang.Exception: Socket bind failed: [730048] Only one usage of each socket address (protocol/network address/port) is normally permitted.
        at org.apache.tomcat.util.net.AprEndpoint.bind(AprEndpoint.java:471)
        at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:742)
        at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:458)
        at org.apache.catalina.connector.Connector.initInternal(Connector.java:960)
        ... 13 more

10-Aug-2018 19:36:50.689 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-apr-8009"]
10-Aug-2018 19:36:50.689 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 971 ms

after which it starts to deploy the applications. After startup I run:

C:\Windows\system32>netstat -abno | find "80"
TCP    0.0.0.0:8009           0.0.0.0:0              LISTENING       5040
TCP    0.0.0.0:49160          0.0.0.0:0              LISTENING       1180
TCP    127.0.0.1:8005         0.0.0.0:0              LISTENING       5040
TCP    127.0.0.1:55979        127.0.0.1:55980        ESTABLISHED     5040
TCP    127.0.0.1:55980        127.0.0.1:55979        ESTABLISHED     5040
TCP    172.17.104.53:56029    172.17.10.154:8014     CLOSE_WAIT      1488
TCP    [::]:49160             [::]:0                 LISTENING       1180
UDP    0.0.0.0:123            *:*                                    980
UDP    [::]:123               *:*                                    980

I can see port 8009 is bound to PID 5040 which in taskmanager is "tomcat8.exe" but as you can see the port 8080 was free, but is not bound due to error:

10-Aug-2018 19:36:50.674 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-apr-8080"]
10-Aug-2018 19:36:50.674 SEVERE [main] org.apache.coyote.AbstractProtocol.init Failed to initialize end point associated with ProtocolHandler ["http-apr-8080"]
 java.lang.Exception: Socket bind failed: [730048] Only one usage of each socket address (protocol/network address/port) is normally permitted.

So at this point the build script has executed successfully, windows is reporting the apache tomcat service to be running, but tomcat has not been bound to port 8080 and thus is not receiving any new requests.

WORKAROUND

If I restart Windows (the server), then tomcat service will startup without problems and tomcat will listen on port 8080.

NEXT STEP

What is the reason that tomcat cannot bind to a free port 8080 ?

Or what could stop windows displaying who/what is blocking port 8080 ?

How can a previous tomcat instance block port 8080, but windows does not show any running tomcat instances?

标签： windows tomcat startup
举报

收藏的人(0)

Ta的文章 更多文章
登录 后发表评论
0条评论
还没有人评论过~