Tomcatのリッスンが失敗している

Question

###前提・実現したいこと
CentOS7、systemdで、Tomcat8を使用。
JavaプログラムのSystem.exit()メソッドで、Tomcatを終了させてしまいました。
↓以下を修正しました。
tomcatを再起動すると、tomcat自体の起動はできているように見えるものの、リッスンが失敗しているのかブラウザからWebアプリケーションにはアクセスができません。
（※載せていたエラーは、systemdでtomcatが起動されている状態から、コマンドライン上でtomcatの起動コマンドを実行した際のもので、ポート競合が原因とはいえないかもしれません。）
解決法ご存じの方ご教授ください。
###発生している問題・エラーメッセージ
★systemctl restart実行後の、systemctl status結果
（Active: active(runnning)であるべきと思っています）

# systemctl status tomcat8.service -l
● tomcat8.service - Apache Tomcat 8
 Loaded: loaded (/usr/lib/systemd/system/tomcat8.service; enabled; vendor preset: disabled)
 Active: active (exited) since 木 2016-08-25 13:30:32 JST; 45s ago
 Process: 6845 ExecStop=/opt/apache-tomcat/apache-tomcat-8.0.24/bin/shutdown.sh (code=exited, status=0/SUCCESS)
 Process: 6885 ExecStart=/opt/apache-tomcat/apache-tomcat-8.0.24/bin/startup.sh (code=exited, status=0/SUCCESS)
 Main PID: 6885 (code=exited, status=0/SUCCESS)
 CGroup: /system.slice/tomcat8.service
 └─6899 /usr/bin/java -Djava.util.logging.config.file=/opt/apache-tomcat/apache-tomcat-8.0.24/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/opt/apache-tomcat/apache-tomcat-8.0.24/endorsed -classpath .:/opt/apache-tomcat/apache-tomcat-8.0.24/lib/servlet-api.jar:/root/postgresql_jdbc/postgresql-9.4-1202.jdbc42.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/bootstrap.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/tomcat-juli.jar -Dcatalina.base=/opt/apache-tomcat/apache-tomcat-8.0.24 -Dcatalina.home=/opt/apache-tomcat/apache-tomcat-8.0.24 -Djava.io.tmpdir=/opt/apache-tomcat/apache-tomcat-8.0.24/temp org.apache.catalina.startup.Bootstrap start

 8月 25 13:30:32 erp systemd[1]: Starting Apache Tomcat 8...
 8月 25 13:30:32 erp startup.sh[6885]: Using CATALINA_BASE: /opt/apache-tomcat/apache-tomcat-8.0.24
 8月 25 13:30:32 erp startup.sh[6885]: Using CATALINA_HOME: /opt/apache-tomcat/apache-tomcat-8.0.24
 8月 25 13:30:32 erp startup.sh[6885]: Using CATALINA_TMPDIR: /opt/apache-tomcat/apache-tomcat-8.0.24/temp
 8月 25 13:30:32 erp startup.sh[6885]: Using JRE_HOME: /usr
 8月 25 13:30:32 erp startup.sh[6885]: Using CLASSPATH: .:/opt/apache-tomcat/apache-tomcat-8.0.24/lib/servlet-api.jar:/root/postgresql_jdbc/postgresql-9.4-1202.jdbc42.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/bootstrap.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/tomcat-juli.jar
 8月 25 13:30:32 erp startup.sh[6885]: Tomcat started.
 8月 25 13:30:32 erp systemd[1]: Started Apache Tomcat 8.

★tomcatが再起動される際のシステムログ

Aug 24 20:16:11 erp systemd: Stopping Apache Tomcat 8...
Aug 24 20:16:11 erp shutdown.sh: Using CATALINA_BASE:   /opt/apache-tomcat/apache-tomcat-8.0.24
Aug 24 20:16:11 erp shutdown.sh: Using CATALINA_HOME:   /opt/apache-tomcat/apache-tomcat-8.0.24
Aug 24 20:16:11 erp shutdown.sh: Using CATALINA_TMPDIR: /opt/apache-tomcat/apache-tomcat-8.0.24/temp
Aug 24 20:16:11 erp shutdown.sh: Using JRE_HOME:        /usr
Aug 24 20:16:11 erp shutdown.sh: Using CLASSPATH:       .:/opt/apache-tomcat/apache-tomcat-8.0.24/lib/servlet-api.jar:/root/postgresql_jdbc/postgresql-9.4-1202.jdbc42.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/bootstrap.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/tomcat-juli.jar
Aug 24 20:16:11 erp shutdown.sh: 8 24, 2016 8:16:11 午後 org.apache.catalina.startup.Catalina stopServer
Aug 24 20:16:11 erp shutdown.sh: 重大: Could not contact localhost:8005. Tomcat may not be running.
Aug 24 20:16:11 erp shutdown.sh: 8 24, 2016 8:16:11 午後 org.apache.catalina.startup.Catalina stopServer
Aug 24 20:16:11 erp shutdown.sh: 重大: Catalina.stop:
Aug 24 20:16:11 erp shutdown.sh: java.net.ConnectException: 接続を拒否されました
Aug 24 20:16:11 erp shutdown.sh: at java.net.PlainSocketImpl.socketConnect(Native Method)
Aug 24 20:16:11 erp shutdown.sh: at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
Aug 24 20:16:11 erp shutdown.sh: at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
Aug 24 20:16:11 erp shutdown.sh: at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
Aug 24 20:16:11 erp shutdown.sh: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
Aug 24 20:16:11 erp shutdown.sh: at java.net.Socket.connect(Socket.java:589)
Aug 24 20:16:11 erp shutdown.sh: at java.net.Socket.connect(Socket.java:538)
Aug 24 20:16:11 erp shutdown.sh: at java.net.Socket.<init>(Socket.java:434)
Aug 24 20:16:11 erp shutdown.sh: at java.net.Socket.<init>(Socket.java:211)
Aug 24 20:16:11 erp shutdown.sh: at org.apache.catalina.startup.Catalina.stopServer(Catalina.java:450)
Aug 24 20:16:11 erp shutdown.sh: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Aug 24 20:16:11 erp shutdown.sh: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Aug 24 20:16:11 erp shutdown.sh: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Aug 24 20:16:11 erp shutdown.sh: at java.lang.reflect.Method.invoke(Method.java:497)
Aug 24 20:16:11 erp shutdown.sh: at org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:400)
Aug 24 20:16:11 erp shutdown.sh: at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:487)
Aug 24 20:16:11 erp systemd: Stopped Apache Tomcat 8.
Aug 24 20:16:32 erp systemd: Starting Apache Tomcat 8...
Aug 24 20:16:32 erp startup.sh: Using CATALINA_BASE:   /opt/apache-tomcat/apache-tomcat-8.0.24
Aug 24 20:16:32 erp startup.sh: Using CATALINA_HOME:   /opt/apache-tomcat/apache-tomcat-8.0.24
Aug 24 20:16:32 erp startup.sh: Using CATALINA_TMPDIR: /opt/apache-tomcat/apache-tomcat-8.0.24/temp
Aug 24 20:16:32 erp startup.sh: Using JRE_HOME:        /usr
Aug 24 20:16:32 erp startup.sh: Using CLASSPATH:       .:/opt/apache-tomcat/apache-tomcat-8.0.24/lib/servlet-api.jar:/root/postgresql_jdbc/postgresql-9.4-1202.jdbc42.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/bootstrap.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/tomcat-juli.jar
Aug 24 20:16:32 erp startup.sh: Tomcat started.
Aug 24 20:16:32 erp systemd: Started Apache Tomcat 8.

★tomcat8.service起動状態（上記）での、ポート使用状況

# lsof -i:8080
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 6899 root 50u IPv6 300179 0t0 TCP *:webcache (LISTEN)
# lsof -i:8009
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 6899 root 55u IPv6 300183 0t0 TCP *:8009 (LISTEN)
# netstat -anp | grep 8080
tcp6 0 0 :::8080 :::* LISTEN 6899/java 
# netstat -anp | grep 8009
tcp6 0 0 :::8009 :::* LISTEN 6899/java 

★tomcatプロセス

# ps -aux | fgrep -i tomcat
root 6899 101 0.9 11634804 316632 ? Sl 13:30 43:15 /usr/bin/java -Djava.util.logging.config.file=/opt/apache-tomcat/apache-tomcat-8.0.24/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/opt/apache-tomcat/apache-tomcat-8.0.24/endorsed -classpath .:/opt/apache-tomcat/apache-tomcat-8.0.24/lib/servlet-api.jar:/root/postgresql_jdbc/postgresql-9.4-1202.jdbc42.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/bootstrap.jar:/opt/apache-tomcat/apache-tomcat-8.0.24/bin/tomcat-juli.jar -Dcatalina.base=/opt/apache-tomcat/apache-tomcat-8.0.24 -Dcatalina.home=/opt/apache-tomcat/apache-tomcat-8.0.24 -Djava.io.tmpdir=/opt/apache-tomcat/apache-tomcat-8.0.24/temp org.apache.catalina.startup.Bootstrap start

###試したこと
・systemctl restartで、tomcatのサービスを再起動⇒改善せず
・サーバ再起動⇒改善せず
・server.xmlに重複定義はなし
###補足情報(言語/FW/ツール等のバージョンなど)

Comments

[eripong]

エラーの前のログはどうなっていますか？systemctl restartで実行される処理の内容はどうなっていますか？

[hirottsu76]

ありがとうございます。catalina.outのエラーは直接関連なさそうなので、文字数のため削除しました。systemctlの結果載せております。

[Umeeeh]

シスログはstartup.sh が出力したログだと思いますが、今回の場合は catalina.out のほうが関係ありそうに感じます。どんなエラーが書かれてたのでしょうか？

[hirottsu76]

catalina.outには、ポート競合と思われる例外のスタックがあったのですが、これはtomcat起動状態でstartup.shを実行した際に出たもので、リッスンの失敗とは関係が無さそうでした。ありがとうございます。

Answer 1

実際に試したわけではないので、違っていたらすみませんが、

Active: active (exited) since 木 2016-08-25 13:30:32 JST; 45s ago

になっているのは、stattup.shからJavaプロセスが立ち上がるのに、
Systemd入門(4) - serviceタイプUnitの設定ファイル - めもめも

子プロセスをフォークしてバックグラウンドにまわして、最初のコマンド自体は終了するタイプであれば、「Type=forking」とします。

にある様な

Type=forking

が指定されていないからでは無いでしょうか？
英語ですが、
How To Install Apache Tomcat 8 on CentOS 7 | DigitalOcean

# Systemd unit file for tomcat
[Unit]
Description=Apache Tomcat Web Application Container
After=syslog.target network.target

[Service]
Type=forking

Environment=JAVA_HOME=/usr/lib/jvm/jre
Environment=CATALINA_PID=/opt/tomcat/temp/tomcat.pid
Environment=CATALINA_HOME=/opt/tomcat
Environment=CATALINA_BASE=/opt/tomcat
Environment='CATALINA_OPTS=-Xms512M -Xmx1024M -server -XX:+UseParallelGC'
Environment='JAVA_OPTS=-Djava.awt.headless=true -Djava.security.egd=file:/dev/./urandom'

ExecStart=/opt/tomcat/bin/startup.sh
ExecStop=/bin/kill -15 $MAINPID

User=tomcat
Group=tomcat

[Install]
WantedBy=multi-user.target

が参考になるかもしれません。

shutdownがうまく行かない件については、ポート8005にアクセスできないようですが、8005で待ち受けていますか？

また、

tomcatを再起動すると、tomcat自体の起動はできているように見えるものの、リッスンが失敗しているのかブラウザからWebアプリケーションにはアクセスができません。

ということですが、どの様にアクセスしていますか？iptablesなどで止められていたりしないですか？

Comments

[hirottsu76]

ご回答ありがとうございます。
Active: active(exited)は、今回の問題とは別問題なんですね！
こちらの手順は後日試してみようと思います。

[Umeeeh]

8005はTomcatのシャットダウンポートですね。そのポートに接続してシャットダウンコマンドを送信するとプロセスが終了します。

Answer 2

別のプロセスが使っているのではないですか？

以下のコマンドで何が8080ポートを使ってるかわかります。

$ lsof -i:8080

Comments

[hirottsu76]

ご回答ありがとうございます。
lsofコマンドで何も出力されないため、他プロセスが使用しているのではないと考えています...。

[moonphase]

server.xmlの内容はどうなってますか？
同じ定義が重複してるとか。

[hirottsu76]

server.xml確認しましたが、定義の重複はありませんでした。

[moonphase]

System.exit()でTomcatのVMを終了させてしまうと、しばらくは8080を掴んでいる状態となります。
bin/shutdown.sh で終了させましょう。

[hirottsu76]

おそれながら、systemdでのtomcat.serviceのリスタートで、bin/shutdown.shは実行されており、サーバリブートも入れてるため、原因ではなさそうです。
ポートが原因ではないのかもしれません...

[moonphase]

切り分けとして、hirottsu76さんが入れたWEBAPPを外してTomcatを再起動するとうまくいきますか？それでうまくいくならWEBAPPが原因と思われます。

[hirottsu76]

自分の入れたアプリを消しても改善しませんでした。
システムログを乗せたのですが、shutdown.shが正常に終了できていない感じがします。

Answer 3

lsofコマンドかnetstat -anpで8080番ポートを使用しているプロセスを特定してください。

参考リンク：

特定のポート番号をLISTENしているプロセスが知りたい - Qiita
http://qiita.com/cubicdaiya/items/003e36e17519ef32ac8a

あるプロセスが開いているポート番号を調べる方法 - sonots:blog
http://blog.livedoor.jp/sonots/archives/32637678.html

Comments

[hirottsu76]

ご回答ありがとうございます。
# lsof -i:8080
# lsof -i:8009
# netstat -p | grep 8080
# netstat -p | grep 8009
全て何も出力されないため、他プロセスとの競合はしていないと認識しています。
にも関わらず、Tomcat側では競合のエラーが発生しています。

[argius]

netstatは -anpオプションで試していただけますか？
回答も修正しました。

それと、念のため
ps -aux | fgrep -i tomcat
でtomcatプロセスがあるかどうかも確認してみて下さい。

でも再起動してもダメなんですよね。
問題はこの段階では無いかも知れません。

Answer 4

Aug 24 20:16:11 erp shutdown.sh: 重大: Could not contact localhost:8005. Tomcat may not be running.

(略)

Aug 24 20:16:11 erp shutdown.sh: java.net.ConnectException: 接続を拒否されました

状況からの推測ですが、shutdown.sh 実行中に Tomcatのシャットダウンポート(TCP:8005)への接続が失敗してるので、Tomcatを正常に停止できなかった状態だと思います。

Tomcatの停止はシャットダウンポートに接続して SHUTDOWN という文字列を送信することで停止されるようになっています。(ポートや文字列は server.xml で変更可能)

恐らく、System.exit() をした影響で シャットダウンポートをListenしてるプロセスが終了してしまい、shutdown.sh からの終了リクエストを受け取ることが出来なかったのが原因っぽいです。

こうなってしまった場合は、Javaのプロセスをkillするしか無いと思います。

Comments

[eripong]

何らかの原因でJavaプロセスが正常に終了できなかったことによりそうなことは同意見です。ですが、System.exitしてプロセスが終了したなら、Javaプロセスが残ることも無さそうです。同じプロセスですよね？Tomcatって単一プロセスのアプリケーションですよね？

[Umeeeh]

確かに。ご指摘ありがとうございます。System.exit()で終了するはずのプロセスが残ってたと考える方がより合ってそうですね。

Answer 5

結局ハッキリとはわからなかったのですが、
tomcatのshutdown.shで停止しないjavaのプロセスが一つあり、それをkillしてから、
tomcatを再起動したところ、Webアプリケーションにアクセス可能になりました。
System.exit()が実行された際の残骸だったのかと推測していますが、定かではありません。

Comments

[eripong]

> ・サーバ再起動⇒改善せず
なら中途半端なプロセスは残ってないはずなのですが。あるいは再起動の度に同じ状態になっているのでしょうか？そうすると再発しそうです。サーバ再起動というのOS再起動のことと思って良いですか？

[moonphase]

運用の現場ではserviceやsystemctlでrestartは使わず、stopしてからpsで確認し、確実に停止していることを確認してからstartしています。

[eripong]

そうなんですね。確かにその方が確実ですね。