主页 / server / 问题 / 1001236
Accepted
Amos
Asked: 2020-02-01 05:34:12 +0800 CST

Tomcat突然自行关闭

  • 772

我在 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...？我的意思是100s！是公开课吗？是不是应该是这样的？（超载？）

这条线Jan 29 07:18:27 app systemd[875]: Received SIGRTMIN+24 from PID 13436 (kill).也很可疑。我会知道 PID 13436 是什么吗？

ubuntu-18.04 tomcat9 unexpected-shutdown

1 个回答

  1. Best Answer

    正如我在评论中所说，我的第一个想法SHUTDOWN是在 Tomcat 的关闭端口上发送关闭命令 ()（默认情况下侦听接口8005的端口localhost）。Tomcat 的文档中推荐使用此方法。

    但是 Ubuntu（继 Debian）在8.5.32-2 版本中默认禁用了关闭端口。较新版本的 Tomcat 会在 JVM 接收到 时执行干净关闭，SIGTERM因此启用关闭端口只是一个安全风险。

    因此，您意外关闭的主要候选人是：

    • Linux OutOfMemory 杀手，它记录到内核日志 ( journalctl -k)，
    • JVM崩溃。虽然虚拟机本身相当稳定，但我已经看到libtcnative将其关闭。检查 Tomcat9 的主日志（）/var/log/catalina.<date>.log，在您的 Ubuntu 下，systemd -journalctl -u tomcat9 journald （
    • Java 自己的OutOfMemoryError，它也应该在 Tomcat9 的主日志中。

    更新：根据您的系统日志摘录，有人可以访问用户app。为用户app创建的大量用户会话耗尽了系统资源并导致许多服务关闭。

    • 1

相关问题