Added a crash log flush to the disk after the unexpected crash.

[Demilivor]

Closes #51574

Changelog category (leave one):

• Improvement

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Added a crash log flush to the disk after the unexpected crash.

[Demilivor]

Please review the changes add the label can be tested.

[robot-ch-test-poll]

This is an automated comment for commit 7b4e7cd with description of existing statuses. It's updated for the latest CI running
The full report is available here
The overall status of the commit is 🟢 success

Check name	Description	Status
AST fuzzer	Runs randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help	🟢 success
CI running	A meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR	🟢 success
ClickHouse build check	Builds ClickHouse in various configurations for use in further steps. You have to fix the builds that fail. Build logs often has enough information to fix the error, but you might have to reproduce the failure locally. The cmake options can be found in the build log, grepping for cmake. Use these options and follow the general build process	🟢 success
Compatibility check	Checks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help	🟢 success
Docker image for servers	The check to build and optionally push the mentioned image to docker hub	🟢 success
Fast test	Normally this is the first check that is ran for a PR. It builds ClickHouse and runs most of stateless functional tests, omitting some. If it fails, further checks are not started until it is fixed. Look at the report to see which tests fail, then reproduce the failure locally as described here	🟢 success
Flaky tests	Checks if new added or modified tests are flaky by running them repeatedly, in parallel, with more randomization. Functional tests are run 100 times with address sanitizer, and additional randomization of thread scheduling. Integrational tests are run up to 10 times. If at least once a new test has failed, or was too long, this check will be red. We don't allow flaky tests, read the doc	🟢 success
Install packages	Checks that the built packages are installable in a clear environment	🟢 success
Integration tests	The integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests	🟢 success
Mergeable Check	Checks if all other necessary checks are successful	🟢 success
Performance Comparison	Measure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests	🟢 success
Push to Dockerhub	The check for building and pushing the CI related docker images to docker hub	🟢 success
SQLancer	Fuzzing tests that detect logical bugs with SQLancer tool	🟢 success
Sqllogic	Run clickhouse on the sqllogic test set against sqlite and checks that all statements are passed	🟢 success
Stateful tests	Runs stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	🟢 success
Stateless tests	Runs stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	🟢 success
Stress test	Runs stateless functional tests concurrently from several clients to detect concurrency-related errors	🟢 success
Style Check	Runs a set of checks to keep the code style clean. If some of tests failed, see the related log from the report	🟢 success
Unit tests	Runs the unit tests for different release types	🟢 success
Upgrade check	Runs stress tests on server version from last release and then tries to upgrade it to the version from the PR. It checks if the new server can successfully startup without any errors, crashes or sanitizer asserts	🟢 success

[alexey-milovidov]

Not a bug fix.

[alexey-milovidov]

This is not the best option, because a crash can happen in multiple threads in a short time.

[alexey-milovidov]

Missing a comment.

[alexey-milovidov]

I'd better keep it as is, or - as a maximum - lower the flush interval to one second.

[Demilivor]

I'd better keep it as is, or - as a maximum - lower the flush interval to one second.

I will try to test with a flush interval of 1 second.

Although I like the blocking wait more than hoping that the crash log has time to store on disk before the force quit.
Perhaps in the case of multiple crashes, the thread should block the wait for just the first crash, instead of waiting for every crash log flush?

---

Update:
Unfortunately, flush_interval_milliseconds 1000 is not quick enough, but I'm able to reproduce the problem with the missing crash log quite stable.

    <crash_log>
        <database>system</database>
        <table>crash_log</table>
        <flush_interval_milliseconds>1000</flush_interval_milliseconds>
    </crash_log>

[alexey-milovidov]

Let's check - what are the mechanics, and why it reproduces?

I like the idea in general, but for the fatal error handler, it makes sense to keep it loose - it is intended to have "best effort" behavior, and adding extra logic there can have side effects, e.g., subsequent errors.

[Demilivor]

When a signal is received, the signalHandler function from src/Daemon/BaseDaemon.cpp starts execution:

1. It writes a signal into signal_pipe.
2. It starts to wait in this loop (SignalListener thread should receive this).

for (size_t i = 0; i < 300; ++i)
{
/// We will synchronize with the thread printing the messages with an atomic variable to finish earlier.
if (fatal_error_printed.test())
break;

/// signal handler thread wait for 1 second, but it is not enough. (Because flusing logs actually takes more than 1 second (it does file creation, file writing and file closing)
sleepForSeconds(1); 
}

3. It calls call_default_signal_handler. This function stops everything.

SignalListener thread work:

1. It receives a signal from signalHandler
2. It creates a new thread running the SignalListener::onFault method.

SignalListener::onFault thread work: 

1. It adds a crash log entry (SystemLog<LogElement>::savingThreadFunction() periodically check entries)
2. It sets fatal_error_printed (notifies the signalHandler thread).

SystemLog<LogElement>::savingThreadFunction() thread

1. It waits for flush_interval_milliseconds (In this case, let it be 1 second.)
2. It starts to write table files.
3. File opening, file writing, and file closing are quite slow operations, those operations do not finish before signalHandler stops work. (When table files already existed on disk, I was not able to find missing crash log entries.)

I hope this diagram may help to understand the problem:

[alexey-milovidov]

Thank you! Now everything is clear.

Until recently, the logic was simpler - sleep for 10 seconds and call the default signal handler.
As the default flush interval is 7 seconds, it was typically enough for writing into the crash log.

Then it was changed to waiting and calling the default signal handler as soon as the fatal handling thread finished its work.

Let's think about what we can do without flushing too aggressively...

[alexey-milovidov]

The 10-second waiting was initially intended not for the crash_log, but for query_log flushing. It means we have to return it nevertheless.

Let's modify the signal handler, so it will sleep additional 10 seconds after it understood that the fatal handling thread finished its work.

PS. Dealing with it with sleep might sound stupid, but I think it is what is best for this particular code - fatal signal handler...

[Demilivor]

10 Seconds should be enough in most of user cases.

Perhaps It is possible to improve my solution without blocking SignalListener::onFault thread:
We can use similar logic from void SystemLogBase<LogElement>::flush(bool force) but without waiting for flush finish, using this code:

// the code is simplified for readability
template <typename LogElement>
void SystemLogBase<LogElement>::notifyFlush()
{
        std::lock_guard lock(mutex);

        // immediately flush, but do not lock the thread
        requested_flush_up_to = std::max(requested_flush_up_to, this_thread_requested_offset);
        flush_event.notify_all();

    // here we don't wait before flush completes   
}

and in collectCrashLog we will call notifyFlush() instead of flush(true)

[Demilivor]

Update:

1. Added SystemLogBase<LogElement>::notifyFlush(bool force) public method, it will notify savingThreadFunction thread, but it does not block current thread on waiting before flush finish (I'm not sure about usefulness force parameter here).
2. notifyFlush(true) is used instead of flush(true) in collectCrashLog.
3. Added sleepForSeconds(3) in signalHandler as a timeout for storing crash_log.

[alexey-milovidov]

What is happening with the integration tests for PostgreSQL?

[Demilivor]

I tried to read these logs: https://s3.amazonaws.com/clickhouse-test-reports/51720/2b77196a470e3181d9812e4a7f5ffd769ab6663e/integration_tests__asan__[6_6].html

But I don't see anything to latch on to.

The failed test_postgresql_replica_database_engine_1 test does not have published logs at all. This is the only failing test (all test cases fail). Other PostgreSQL tests pass.

[alexey-milovidov]

The PR is good, and we need to merge it, but we have to address the issue with this test regardless (it cannot be merged without investigation).

[alexey-milovidov]

And we still have to figure out what queries in the stress test consume large amount of memory.

[Demilivor]

The tests fails seems unsable:
After last update, failed PostgreSQL integration tests are pass,

Now There another integration tests fail:

>       raise Exception("Can't wait Minio to start")
E       Exception: Can't wait Minio to start

see: https://s3.amazonaws.com/clickhouse-test-reports/51720/2c8564e45e216b63f4fb13d30e5dac65b6741758/integration_tests__release__[3_4]/integration_run_parallel0_0.log

[alexey-milovidov]

We cannot proceed with failed tests. It is most likely our problem, not yours... but we can hold this PR as a hostage until we will fix all the tests.

[Demilivor]

Mergeable check passed: 257 successful and 1 skipped checks