I've only looked at this briefly, but some observations:

• The JVM seems to have spontaneously and uncerimoniously self-destructed:
  • No logged (fatal) exceptions
  • No crash log or heap dump
• None of the usual signs of distress preceding the event
  • StatusLogger frequency
  • Major GCs
  • Load avg, cpu, IO
• High latency immediately preceding the event shared by 2009-b

Conclusion: This is...weird, but probably not worth spending any more time on unless it begins to look like a pattern.

Additionally, before digging too deeply, it would make sense to pursue T200803: Upgrade Cassandra 3.11.2 clusters to 3.11.4 (bugfix release) first.

This instance has gone down again, we should dig deeper.

To: services@wikimedia.org
Subject: ** PROBLEM alert - restbase2017/Check systemd state is CRITICAL **

Notification Type: PROBLEM

Service: Check systemd state
Host: restbase2017
Address: 10.192.48.119
State: CRITICAL

Date/Time: Thu Aug 29 03:20:29 UTC 2019

Notes URLs: https://wikitech.wikimedia.org/wiki/Monitoring/check_systemd_state

Acknowledged by : 

Additional Info:

CRITICAL - degraded: The system is operational but one or more units failed.

The timeline of events goes like this:

• [2019-08-29T03:07:53+00:00] StatusLogger shows ReadStage backing up some (~100 pending tasks). Cause? Effect?
• [2019-08-29T03:17:07+00:00] Exceptions in ReadRepairStage thread (4 total ~4 secs). Cause? Effect?
• [2019-08-29T03:17:12+00:00] Last message logged (StatusLogger.java:101...)
• [2019-08-29T03:17:15+00:00] Syslog/systemd shutdown (see below)
• [2019-08-29T03:20:27+00:00] cassandra-b service is CRITICAL
• [2019-08-29T03:20:59+00:00] cassandra-b CQL 10.192.48.122:9042 is CRITICAL
• [2019-08-29T03:21:37+00:00] cassandra-b SSL 10.192.48.122:7001 is CRITICAL
• [2019-08-29T03:40:33+00:00] First message logged from startup (restarted by Puppet)
• [2019-08-29T03:40:55+00:00] cassandra-b service is OK
• [2019-08-29T03:42:03+00:00] cassandra-b SSL 10.192.48.122:7001 is OK
• [2019-08-29T03:42:55+00:00] cassandra-b CQL 10.192.48.122:9042 is OK

Aug 29 03:17:15 restbase2017 systemd[1]: cassandra-b.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Aug 29 03:17:15 restbase2017 systemd[1]: cassandra-b.service: Unit entered failed state.
Aug 29 03:17:15 restbase2017 systemd[1]: cassandra-b.service: Failed with result 'exit-code'

[ ... ]

Aug 29 03:40:21 restbase2017 puppet-agent[75589]: (/Stage[main]/Cassandra/Cassandra::Instance[b]/Systemd::Service[cassandra-b]/Service[cassandra-b]/ensure) ensure changed stopped' to 'running'

As before, there were no hs_err_pid%p.log" files or heap dumps (cassandra-$(date +%s)-pid$$.hprof). And no fatal exceptions in the logs.

If the systemd syslog output is to believed, the service exited with status code 3 (...status=3/NOTIMPLEMENTED). AFAICT, Java would exit with a status code > 127 if the JVM shutdown as the result of a signal, otherwise this would have to be the result of a java.lang.System.exit(3) call. However, I can find no explanation of this in Cassandra's code.

In T231027#5451242, @Eevans wrote:

This instance has gone down again, we should dig deeper.

[ ... ]

It would appear this also happened on July 30 at ~19:15 UTC (and went un-investigated at the time).

Mentioned in SAL (#wikimedia-operations) [2019-08-30T16:44:22Z] <urandom> restarting restbase2017-b with live hack startup script (adds logging) -- T231027

In T231027#5452798, @Eevans wrote:

If the systemd syslog output is to believed, the service exited with status code 3 (...status=3/NOTIMPLEMENTED). AFAICT, Java would exit with a status code > 127 if the JVM shutdown as the result of a signal, otherwise this would have to be the result of a java.lang.System.exit(3) call. However, I can find no explanation of this in Cassandra's code.

I think we can trust systemd on that. I checked and it correctly identifies java as the mainpid, which was the only doubt I had.

Very dumb question: which version of the cassandra code did you check? Did you include debian patches we apply, if any?

A stopgap if we want the unit to be restarted regularly even when exiting in error would be to use Restart=always and some sane throttling rules, but I'm not sure we want it for cassandra in general.

In T231027#5470702, @Joe wrote:

In T231027#5452798, @Eevans wrote:

If the systemd syslog output is to believed, the service exited with status code 3 (...status=3/NOTIMPLEMENTED). AFAICT, Java would exit with a status code > 127 if the JVM shutdown as the result of a signal, otherwise this would have to be the result of a java.lang.System.exit(3) call. However, I can find no explanation of this in Cassandra's code.

I think we can trust systemd on that. I checked and it correctly identifies java as the mainpid, which was the only doubt I had.

Very dumb question: which version of the cassandra code did you check? Did you include debian patches we apply, if any?

We're running 3.11.2, and using the upstream package.

A stopgap if we want the unit to be restarted regularly even when exiting in error would be to use Restart=always and some sane throttling rules, but I'm not sure we want it for cassandra in general.

The outages themselves haven't caused any issues, and Puppet will start it back up when it next runs; I don't think we need to go this far.

Part of what has made this so odd is that it only ever occurred to this one instance, so good/bad news, this has now been observed on 2009-b as well.

[ ... ]
Sep  9 09:35:12 restbase2009 systemd[1]: cassandra-b.service: main process exited, code=exited, status=3/NOTIMPLEMENTED
Sep  9 09:35:12 restbase2009 systemd[1]: Unit cassandra-b.service entered failed state.
[ .... ]