☰

Tomcat突然自行關閉

tag-icon • tag-icon ubuntu-18.04 unexpected-shutdown tomcat9
Tomcat突然自行關閉

我在 Ubuntu 18.04 上運行 tomcat 9.0.26。突然我發現tomcat宕機了。以前從未發生過沒有我將其關閉的情況。我查看了跟踪並看到以下內容（這似乎啟動了關閉過程）：

29-Jan-2020 07:18:27.927 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["https-jsse-nio2-8443"]
29-Jan-2020 07:18:27.936 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8009"]
29-Jan-2020 07:18:27.946 INFO [Thread-4] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]

從這裡開始，它是關閉過程本身的一部分，而不是原因，儘管可能相關：

29-Jan-2020 07:18:28.145 WARNING [Thread-4] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [app] appears to have started a thread named [grpc-default-worker-ELG-1-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:

上面的這部分appears to have started a thread named [grpc-default-worker-ELG-1-1]在例外之間發生變化：grpc-default-worker-ELG-1-2 Gax-2 Gax-3等等......

之後我看到如下幾行：

29-Jan-2020 07:18:28.154 SEVERE [Thread-4] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [app] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@117138f9]) and a value of type [io.grpc.netty.shaded.io.netty.util.internal.InternalThreadLocalMap] (value [io.grpc.netty.shaded.io.netty.util.internal.InternalThreadLocalMap@2b40bbea]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

最後：

29-Jan-2020 07:18:28.262 INFO [Thread-4] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["https-jsse-nio2-8443"]
29-Jan-2020 07:18:28.305 INFO [Thread-4] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8009"]
29-Jan-2020 07:18:28.316 INFO [Thread-4] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["https-jsse-nio2-8443"]
29-Jan-2020 07:18:28.323 INFO [Thread-4] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8009"]
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED

如果有任何關於在哪裡或尋找什麼的提示，我將不勝感激。在沒有事先通知的情況下關閉讓我想知道那裡發生了什麼。謝謝

更新： 我在關閉的同時在 /var/log/apache2 日誌中找到了這個：

[Wed Jan 29 07:18:29.141852 2020] [mpm_prefork:notice] [pid 568] AH00169: caught SIGTERM, shutting down
[Wed Jan 29 07:38:12.843389 2020] [suexec:notice] [pid 513] AH01232: suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Wed Jan 29 07:38:13.060250 2020] [mpm_prefork:notice] [pid 539] AH00163: Apache/2.4.29 (Ubuntu) mod_fcgid/2.3.9 OpenSSL/1.1.1 configured -- resuming normal operations
[Wed Jan 29 07:38:13.060350 2020] [core:notice] [pid 539] AH00094: Command line: '/usr/sbin/apache2'

在 mail.log 中，我看到以下內容（最後一行的日期時間可疑），postfix 故意關閉）：

Jan 29 07:38:08 app postgrey[271]: Process Backgrounded
Jan 29 07:38:08 app postgrey[271]: 2020/01/29-07:38:08 postgrey (type Net::Server::Multiplex) starting! pid(271)
Jan 29 07:38:08 app postgrey[271]: Resolved [localhost]:10023 to [::1]:10023, IPv6
Jan 29 07:38:08 app postgrey[271]: Resolved [localhost]:10023 to [127.0.0.1]:10023, IPv4
Jan 29 07:38:08 app postgrey[271]: Binding to TCP port 10023 on host ::1 with IPv6
Jan 29 07:38:08 app postgrey[271]: Binding to TCP port 10023 on host 127.0.0.1 with IPv4
Jan 29 07:38:08 app postgrey[271]: Setting gid to "122 122"
Jan 29 07:38:09 app postgrey[271]: Setting uid to "118"
Jan 29 07:38:11 app dovecot: master: Dovecot v2.2.33.2 (d6601f4ec) starting up for imap, pop3 (core dumps disabled)
Jan 29 07:38:12 app opendkim[502]: OpenDKIM Filter v2.11.0 starting (args: -P /var/run/opendkim/opendkim.pid -p inet:[email protected])

這是我唯一一次看到提及 postgrey 的時間和地點，但我不知道它是什麼。

更新2：這就是事情開始崩潰的地方：

Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#37793 (wWW.MUARaPeNimBunGiLiR.DeSA.Id): query (cache) 'wWW.MUARaPeNimBunGiLiR.DeSA.Id/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#43632 (WWW.mUarapEnImbunGIlIr.dEsA.iD): query (cache) 'WWW.mUarapEnImbunGIlIr.dEsA.iD/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#50618 (www.MuarAPEnImBUNgIliR.DEsA.id): query (cache) 'www.MuarAPEnImBUNgIliR.DEsA.id/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#40648 (WWW.muAraPeniMbungiLir.desA.iD): query (cache) 'WWW.muAraPeniMbungiLir.desA.iD/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#59108 (Www.mUARaPeniMbuNGiLIR.deSA.iD): query (cache) 'Www.mUARaPeniMbuNGiLIR.deSA.iD/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#42231 (wWW.mUARapenIMBUNgIlIr.DESA.ID): query (cache) 'wWW.mUARapenIMBUNgIlIr.DESA.ID/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#43692 (www.MUarAPeNimbUNGIliR.DeSA.ID): query (cache) 'www.MUarAPeNimbUNGIliR.DeSA.ID/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#47881 (Www.mUAraPeNIMBungiLiR.dESA.id): query (cache) 'Www.mUAraPeNIMBungiLiR.dESA.id/A/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#36046 (www.mUaraPeNimBungIliR.Desa.id): query (cache) 'www.mUaraPeNimBungIliR.Desa.id/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#49623 (wWw.MuArapenimbUNgILIR.dESA.iD): query (cache) 'wWw.MuArapenimbUNgILIR.dESA.iD/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#42436 (Www.muARaPeniMBuNGIliR.DeSa.id): query (cache) 'Www.muARaPeniMBuNGIliR.DeSa.id/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#41600 (WWw.mUARAPeNiMbunGiLIr.DEsA.iD): query (cache) 'WWw.mUARAPeNiMbunGiLIr.DEsA.iD/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#40947 (WWW.mUAraPeNIMbUNgiLir.DeSA.iD): query (cache) 'WWW.mUAraPeNIMbUNgiLir.DeSA.iD/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#47416 (WWW.MUARApENiMBunGilIR.dESA.Id): query (cache) 'WWW.MUARApENiMBunGilIR.dESA.Id/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#50269 (Www.mUarAPENImBuNgilir.dESA.id): query (cache) 'Www.mUarAPENImBuNgilir.dESA.id/AAAA/IN' denied
Jan 29 07:13:56 app named[461]: client @0x7f6cec025fa0 35.172.217.55#34727 (WWw.MUArApEniMBUngIliR.DesA.id): query (cache) 'WWw.MUArApEniMBUngIliR.DesA.id/AAAA/IN' denied
then a lot of logs similar to this: Jan 29 07:17:14 app systemd[1]: Started Session c5470 of user app.
Jan 29 07:18:26 app systemd[1]: Removed slice system-serial\x2dgetty.slice.
then a lot of logs similar to this: Jan 29 07:18:26 app systemd[1]: Stopped Session c2888 of user app.
Jan 29 07:18:27 app systemd[875]: Closed GnuPG cryptographic agent and passphrase cache.
Jan 29 07:18:27 app systemd[875]: Reached target Shutdown.
Jan 29 07:18:27 app systemd[875]: Starting Exit the Session...
Jan 29 07:18:27 app systemd[1]: Stopped Session c3432 of user app.
Jan 29 07:18:27 app systemd[875]: Received SIGRTMIN+24 from PID 13436 (kill).
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '1' to 'kernel/kptr_restrict', ignoring: Permission denied
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '1' to 'fs/protected_hardlinks', ignoring: Permission denied
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '1' to 'fs/protected_symlinks', ignoring: Permission denied
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '176' to 'kernel/sysrq', ignoring: Permission denied
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '1' to 'net/ipv4/tcp_syncookies', ignoring: No such file or directory
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '1' to 'kernel/yama/ptrace_scope', ignoring: Permission denied
Jan 29 07:38:06 app keyboard-setup.sh[67]: Couldn't get a file descriptor referring to the console
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write '65536' to 'vm/mmap_min_addr', ignoring: Operation not permitted
Jan 29 07:38:06 app keyboard-setup.sh[67]: Couldn't get a file descriptor referring to the console
Jan 29 07:38:06 app systemd-sysctl[85]: Couldn't write 'fq_codel' to 'net/core/default_qdisc', ignoring: No such file or directory
Jan 29 07:38:06 app keyboard-setup.sh[67]: Couldn't get a file descriptor referring to the console
Jan 29 07:38:06 app keyboard-setup.sh[67]: message repeated 4 times: [ Couldn't get a file descriptor referring to the console]
Jan 29 07:38:06 app keyboard-setup.sh[67]: setupcon: We are not on the console, the console is left unconfigured.

為什麼我會看到 100 多個Stopped Session <session> of user...？我的意思是 100 秒！是公開會議嗎？應該是這樣嗎？ （超載？）

這條線也Jan 29 07:18:27 app systemd[875]: Received SIGRTMIN+24 from PID 13436 (kill).非常可疑。我知道 PID 13436 是什麼嗎？

答案1

正如我在評論中所說，我的第一個想法是SHUTDOWN在 Tomcat 的關閉連接埠上發送關閉命令 ( ) （預設會偵聽8005介面的連接埠localhost）。推薦使用此方法Tomcat 的文檔。

然而，Ubuntu（繼 Debian）預設禁用關閉端口版本8.5.32-2。當 JVM 收到 時SIGTERM，較新版本的 Tomcat 會執行乾淨關閉，因此啟用關閉連接埠只是一個安全風險。

因此，意外關機的主要可能性是：

  • Linux記憶體不足殺手，記錄到內核日誌 ( journalctl -k)，
  • 的崩潰虛擬機。雖然虛擬機器本身相當穩定，但我見過自由語拿下來。檢查 Tomcat9 的主日誌（/var/log/catalina.<date>.log），在你的 Ubuntu 下也很好地收集了系統日誌( journalctl -u tomcat9) 並發送至系統日誌。
  • Java自己的記憶體不足錯誤，它也應該在 Tomcat9 的主日誌中。

更新：根據您的系統日誌摘錄，有人造訪了該使用者app。創建的大量用戶會話app耗盡了系統資源並導致許多服務關閉。

相關內容