Skip to content

Support Startup & Shutdown Log Levels#85967

Merged
kssenii merged 5 commits intoClickHouse:masterfrom
Blokje5:support-startup-and-shutdown-log-levels
Aug 28, 2025
Merged

Support Startup & Shutdown Log Levels#85967
kssenii merged 5 commits intoClickHouse:masterfrom
Blokje5:support-startup-and-shutdown-log-levels

Conversation

@Blokje5
Copy link
Copy Markdown
Contributor

@Blokje5 Blokje5 commented Aug 21, 2025

Alter the log levels on startup & shutdown if the respective values are set. This allows for a higher log level during startup & shutdown of clickhouse.

Fixes: #85958

Changelog category (leave one):

  • New Feature

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

New configuration options: logger.startupLevel & logger.shutdownLevel allow for overriding the log level during the startup & shutdown of Clickhouse respectively.

This can be useful to help investigate startup & shutdown issues.

Documentation entry for user-facing changes

  • Documentation is written (mandatory for new features)

@clickhouse-gh
Copy link
Copy Markdown
Contributor

clickhouse-gh bot commented Aug 21, 2025

Workflow [PR], commit [7e4d800]

Summary:

job_name test_name status info comment
Stateless tests (amd_debug, AsyncInsert, s3 storage, parallel) failure
02443_detach_attach_partition FAIL
Stateless tests (amd_debug, parallel) failure
01825_new_type_json_ghdata_insert_select FAIL

@clickhouse-gh clickhouse-gh bot added the pr-feature Pull request with new product feature label Aug 21, 2025
@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 21, 2025

Example log (from running locally) with:

<logger>
    <level>information</level>
    <startupLevel>trace</startupLevel>
     <shutdownLevel>trace</shutdownLevel>
</logger>
2025.08.21 11:23:30.725777 [ 44796644 ] {} <Information> Application: Starting ClickHouse 25.8.1.1 (revision: 54501, git hash: 1854ff24c2b01aa6e4fbe65eb1d95d38bff9c89d, build id: <unknown>), PID 45091
2025.08.21 11:23:30.725819 [ 44796644 ] {} <Information> Application: starting up
2025.08.21 11:23:30.725843 [ 44796644 ] {} <Information> Application: OS name: Darwin, version: 24.6.0, architecture: arm64
2025.08.21 11:23:30.726071 [ 44796644 ] {} <Information> Jemalloc: Value for background_thread set to true (from false)
2025.08.21 11:23:30.726104 [ 44796644 ] {} <Information> Application: Starting root logger in level trace
2025.08.21 11:23:30.735911 [ 44796644 ] {} <Information> Application: Available RAM: 36.00 GiB; logical cores: 14; used cores: 14.
2025.08.21 11:23:30.735917 [ 44796644 ] {} <Information> Application: Query Profiler and TraceCollector are disabled because they require PHDR cache to be created (otherwise the function 'dl_iterate_phdr' is not lock free and not async-signal safe).
2025.08.21 11:23:30.739488 [ 44796644 ] {} <Information> MemoryWorker: Starting background memory thread with period of 100ms, using Jemalloc as source
2025.08.21 11:23:30.739536 [ 44796644 ] {} <Information> BackgroundSchedulePool/BgSchPool: Create BackgroundSchedulePool with 512 threads
2025.08.21 11:23:30.757399 [ 44796644 ] {} <Debug> Application: Set max number of file descriptors to 4294967295 (was 1048575).
2025.08.21 11:23:30.757407 [ 44796644 ] {} <Debug> Application: Set max number of threads to 9000 (was 6000).
2025.08.21 11:23:30.757428 [ 44796644 ] {} <Warning> Context: Maximum number of threads is lower than 30000. There could be problems with handling a lot of simultaneous queries.
2025.08.21 11:23:30.757523 [ 44796644 ] {} <Debug> Application: Initializing DateLUT.
2025.08.21 11:23:30.757524 [ 44796644 ] {} <Trace> Application: Initialized DateLUT with time zone 'Europe/Madrid'.
2025.08.21 11:23:30.757552 [ 44796644 ] {} <Debug> Application: Initializing interserver credentials.
2025.08.21 11:23:30.757996 [ 44797463 ] {BgSchPool::6eedda99-9735-4960-93a3-13552e61391c} <Trace> CancellationChecker: Started worker function
2025.08.21 11:23:30.758740 [ 44796644 ] {} <Trace> NamedCollectionsMetadataStorage: Using local storage for named collections at path: ./named_collections
2025.08.21 11:23:30.758785 [ 44796644 ] {} <Debug> FileCacheFactory: Will load 0 caches from default cache config
2025.08.21 11:23:30.759619 [ 44796644 ] {} <Debug> ConfigReloader: Loading config 'config.xml'
2025.08.21 11:23:30.759627 [ 44796644 ] {} <Debug> ConfigProcessor: Processing configuration file 'config.xml'.
2025.08.21 11:23:30.760410 [ 44796644 ] {} <Debug> ConfigProcessor: Saved preprocessed configuration to './preprocessed_configs/config.xml'.
2025.08.21 11:23:30.760423 [ 44796644 ] {} <Debug> ConfigReloader: Loaded config 'config.xml', performing update on configuration
2025.08.21 11:23:30.760783 [ 44796644 ] {} <Information> Application: Changed setting 'max_server_memory_usage' to 32.40 GiB (36.00 GiB available memory * 0.90 max_server_memory_usage_to_ram_ratio)
2025.08.21 11:23:30.760799 [ 44796644 ] {} <Information> Application: Setting merges_mutations_memory_usage_soft_limit was set to 18.00 GiB (36.00 GiB available * 0.50 merges_mutations_memory_usage_to_ram_ratio)
2025.08.21 11:23:30.760800 [ 44796644 ] {} <Information> Application: Merges and mutations memory limit is set to 18.00 GiB
2025.08.21 11:23:30.760946 [ 44796644 ] {} <Information> Application: Setting max_remote_read_network_bandwidth_for_server was set to 0
2025.08.21 11:23:30.760947 [ 44796644 ] {} <Information> Application: Setting max_remote_write_network_bandwidth_for_server was set to 0
2025.08.21 11:23:30.760947 [ 44796644 ] {} <Information> Application: Setting max_local_read_bandwidth_for_server was set to 0
2025.08.21 11:23:30.760948 [ 44796644 ] {} <Information> Application: Setting max_local_write_bandwidth_for_server was set to 0
2025.08.21 11:23:30.760960 [ 44796644 ] {} <Information> Application: ConcurrencyControl limit is set to UNLIMITED CPU slots with 'fair_round_robin' scheduler
2025.08.21 11:23:30.760962 [ 44796644 ] {} <Information> BackgroundSchedulePool/BgBufSchPool: Create BackgroundSchedulePool with 16 threads
2025.08.21 11:23:30.761558 [ 44796644 ] {} <Information> BackgroundSchedulePool/BgMBSchPool: Create BackgroundSchedulePool with 16 threads
2025.08.21 11:23:30.761819 [ 44796644 ] {} <Information> BackgroundSchedulePool/BgDistSchPool: Create BackgroundSchedulePool with 16 threads
2025.08.21 11:23:30.765963 [ 44796644 ] {} <Information> Context: Initialized background executor for merges and mutations with num_threads=16, num_tasks=32, scheduling_policy=round_robin
2025.08.21 11:23:30.766134 [ 44796644 ] {} <Information> Context: Initialized background executor for move operations with num_threads=8, num_tasks=8
2025.08.21 11:23:30.766738 [ 44796644 ] {} <Information> Context: Initialized background executor for fetches with num_threads=16, num_tasks=16
2025.08.21 11:23:30.766780 [ 44796644 ] {} <Information> Context: Initialized background executor for common operations (e.g. clearing old parts) with num_threads=8, num_tasks=8
2025.08.21 11:23:30.768011 [ 44796644 ] {} <Information> DNSCacheUpdater: Update period 15 seconds
2025.08.21 11:23:30.768018 [ 44796644 ] {} <Information> Application: Loading metadata from ./
2025.08.21 11:23:30.768078 [ 44796644 ] {} <Information> Context: Database disk name: default
2025.08.21 11:23:30.768079 [ 44796644 ] {} <Information> Context: Database disk name: default, path: ./
2025.08.21 11:23:30.768806 [ 44796644 ] {} <Information> DatabaseAtomic (system): Metadata disk default, path ./
2025.08.21 11:23:30.769482 [ 44796644 ] {} <Information> DatabaseAtomic (system): Metadata processed, database system has 0 tables, 0 dictionaries and 0 materialized views in total.
2025.08.21 11:23:30.769486 [ 44796644 ] {} <Information> TablesLoader: Parsed metadata of 0 tables in 1 databases in 0.000131459 sec
2025.08.21 11:23:30.822566 [ 44796644 ] {} <Information> DatabaseAtomic (default): Metadata disk default, path ./
2025.08.21 11:23:30.822588 [ 44796644 ] {} <Information> DatabaseAtomic (default): Metadata processed, database default has 0 tables, 0 dictionaries and 0 materialized views in total.
2025.08.21 11:23:30.822590 [ 44796644 ] {} <Information> TablesLoader: Parsed metadata of 0 tables in 1 databases in 1.2667e-05 sec
2025.08.21 11:23:30.822610 [ 44796644 ] {} <Information> loadMetadata: Start asynchronous loading of databases
2025.08.21 11:23:30.822734 [ 44796644 ] {} <Information> UserDefinedSQLObjectsLoaderFromDisk: Loading user defined objects from /Users/lennard/git/personal/ClickHouse/user_defined/
2025.08.21 11:23:30.822786 [ 44796644 ] {} <Information> WorkloadEntityDiskStorage: Loading workload entities from /Users/lennard/git/personal/ClickHouse/workload/
2025.08.21 11:23:30.822788 [ 44796644 ] {} <Information> Application: TaskStats is not implemented for this OS. IO accounting will be disabled.
2025.08.21 11:23:30.823266 [ 44796644 ] {} <Warning> Application: Listen [::1]:9000 failed: Poco::Exception. Code: 1000, e.code() = 48, Net Exception: Address already in use: [::1]:9000 (version 25.8.1.1). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2025.08.21 11:23:30.841792 [ 44796978 ] {} <Information> MemoryTracker: Correcting the value of global memory tracker from 62.06 MiB to 371.34 MiB
2025.08.21 11:23:31.015215 [ 44796644 ] {} <Warning> Application: Listen [127.0.0.1]:9000 failed: Poco::Exception. Code: 1000, e.code() = 48, Net Exception: Address already in use: 127.0.0.1:9000 (version 25.8.1.1). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2025.08.21 11:23:31.060756 [ 44796644 ] {} <Information> CertificateReloader: One of paths is empty. Cannot apply new configuration for certificates. Fill all paths and try again.
2025.08.21 11:23:31.060761 [ 44796644 ] {} <Information> CertificateReloader: One of paths is empty. Cannot apply new configuration for certificates. Fill all paths and try again.
2025.08.21 11:23:31.061015 [ 44796644 ] {} <Information> Application: Listening for http://[::1]:8123
2025.08.21 11:23:31.061023 [ 44796644 ] {} <Information> Application: Listening for MySQL compatibility protocol: [::1]:9004
2025.08.21 11:23:31.061029 [ 44796644 ] {} <Information> Application: Listening for PostgreSQL compatibility protocol: [::1]:9005
2025.08.21 11:23:31.061035 [ 44796644 ] {} <Information> Application: Listening for http://127.0.0.1:8123
2025.08.21 11:23:31.061041 [ 44796644 ] {} <Information> Application: Listening for MySQL compatibility protocol: 127.0.0.1:9004
2025.08.21 11:23:31.061047 [ 44796644 ] {} <Information> Application: Listening for PostgreSQL compatibility protocol: 127.0.0.1:9005
2025.08.21 11:23:31.061061 [ 44796644 ] {} <Information> Application: Restored default logger level to information
2025.08.21 11:23:31.061062 [ 44796644 ] {} <Information> Application: Ready for connections.
^C2025.08.21 11:23:35.851250 [ 44796973 ] {} <Information> Application: Received termination signal (Interrupt: 2)
2025.08.21 11:23:35.851360 [ 44796644 ] {} <Information> Application: Set root logger in level trace before shutdown
2025.08.21 11:23:35.851375 [ 44796644 ] {} <Debug> Application: Received termination signal.
2025.08.21 11:23:35.851463 [ 44796644 ] {} <Debug> Application: Waiting for current connections to close.
2025.08.21 11:23:37.079752 [ 44796644 ] {} <Information> Application: Closed all listening sockets.
2025.08.21 11:23:37.080368 [ 44796644 ] {} <Information> Application: Closed connections.
2025.08.21 11:23:37.080397 [ 44796644 ] {} <Information> Application: Stopping AsyncLoader.
2025.08.21 11:23:37.080411 [ 44796644 ] {} <Trace> CancellationChecker: Stopping CancellationChecker
2025.08.21 11:23:37.080736 [ 44797463 ] {} <Trace> CancellationChecker: Execution took 6323 ms.
2025.08.21 11:23:37.081411 [ 44796644 ] {} <Information> Application: Shutting down storages.
2025.08.21 11:23:37.081456 [ 44796644 ] {} <Trace> AsynchronousInsertQueue: Shutting down the asynchronous insertion queue
2025.08.21 11:23:37.082606 [ 44796644 ] {} <Trace> AsynchronousInsertQueue: Asynchronous insertion queue finished
2025.08.21 11:23:37.082619 [ 44796644 ] {} <Debug> Context: Shutting down dictionaries loader
2025.08.21 11:23:37.082625 [ 44796644 ] {} <Debug> ExternalDictionariesLoader: Periodic updates disabled
2025.08.21 11:23:37.082728 [ 44797627 ] {} <Debug> ExternalDictionariesLoader: Stopped periodic updates (enabled: false)
2025.08.21 11:23:37.082768 [ 44796644 ] {} <Debug> Context: Shutting down UDFs loader
2025.08.21 11:23:37.082772 [ 44796644 ] {} <Debug> ExternalUserDefinedExecutableFunctionsLoader: Periodic updates disabled
2025.08.21 11:23:37.082874 [ 44797628 ] {} <Debug> ExternalUserDefinedExecutableFunctionsLoader: Stopped periodic updates (enabled: false)
2025.08.21 11:23:37.082925 [ 44796644 ] {} <Debug> Context: Shutting down another UDFs storage
2025.08.21 11:23:37.082933 [ 44796644 ] {} <Debug> Context: Shutting down workload entity storage
2025.08.21 11:23:37.082935 [ 44796644 ] {} <Trace> Context: Shutting down named sessions
2025.08.21 11:23:37.083052 [ 44796644 ] {} <Trace> Context: Shutting down object storage queue streaming
2025.08.21 11:23:37.083072 [ 44796644 ] {} <Debug> ObjectStorageQueueFactory: There are no queue storages to shutdown
2025.08.21 11:23:37.083073 [ 44796644 ] {} <Trace> Context: Shutting down database catalog
2025.08.21 11:23:37.083092 [ 44796644 ] {} <Trace> DatabaseCatalog: Shutting down database INFORMATION_SCHEMA
2025.08.21 11:23:37.083702 [ 44796644 ] {} <Trace> DatabaseCatalog: Shutting down database default
2025.08.21 11:23:37.083726 [ 44796644 ] {} <Trace> DatabaseCatalog: Shutting down database information_schema
2025.08.21 11:23:37.084360 [ 44796644 ] {} <Trace> DatabaseCatalog: Shutting down system logs
2025.08.21 11:23:37.084373 [ 44796644 ] {} <Debug> Context: Shutting down system logs
2025.08.21 11:23:37.084447 [ 44796644 ] {} <Trace> DatabaseCatalog: Shutting down system databases
2025.08.21 11:23:37.086554 [ 44796644 ] {} <Debug> Context: Shutting down merges executor
2025.08.21 11:23:37.086842 [ 44796644 ] {} <Debug> Context: Shutting down fetches executor
2025.08.21 11:23:37.087082 [ 44796644 ] {} <Debug> Context: Shutting down moves executor
2025.08.21 11:23:37.087163 [ 44796644 ] {} <Debug> Context: Shutting down common executor
2025.08.21 11:23:37.087471 [ 44796644 ] {} <Trace> Context: Shutting down caches
2025.08.21 11:23:37.087486 [ 44796644 ] {} <Information> Context: Shutdown disk default
2025.08.21 11:23:37.087489 [ 44796644 ] {} <Trace> Context: Shutting down AccessControl
2025.08.21 11:23:37.087596 [ 44796644 ] {} <Debug> ExternalDictionariesLoader: Periodic updates disabled
2025.08.21 11:23:37.087602 [ 44796644 ] {} <Debug> ExternalUserDefinedExecutableFunctionsLoader: Periodic updates disabled
2025.08.21 11:23:37.087638 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgBufSchPool: Waiting for threads to finish.
2025.08.21 11:23:37.087724 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgBufSchPool: Threads finished in 0ms.
2025.08.21 11:23:37.088569 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgSchPool: Waiting for threads to finish.
2025.08.21 11:23:37.092464 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgSchPool: Threads finished in 3ms.
2025.08.21 11:23:37.092499 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgDistSchPool: Waiting for threads to finish.
2025.08.21 11:23:37.092794 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgDistSchPool: Threads finished in 0ms.
2025.08.21 11:23:37.092837 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgMBSchPool: Waiting for threads to finish.
2025.08.21 11:23:37.093025 [ 44796644 ] {} <Trace> BackgroundSchedulePool/BgMBSchPool: Threads finished in 0ms.
2025.08.21 11:23:37.093127 [ 44796644 ] {} <Debug> Application: Shut down storages.
2025.08.21 11:23:37.093762 [ 44796644 ] {} <Debug> Application: Destroyed global context.
2025.08.21 11:23:37.093795 [ 44796644 ] {} <Information> Application: Waiting for background threads
2025.08.21 11:23:37.125829 [ 44796644 ] {} <Information> Application: Background threads finished in 32 ms
2025.08.21 11:23:37.126482 [ 44796644 ] {} <Information> Application: shutting down
2025.08.21 11:23:37.126485 [ 44796644 ] {} <Debug> Application: Uninitializing subsystem: Logging Subsystem
2025.08.21 11:23:37.126574 [ 44796973 ] {} <Trace> BaseDaemon: Received signal -2
2025.08.21 11:23:37.126576 [ 44796973 ] {} <Information> BaseDaemon: Stop SignalListener thread

@Blokje5 Blokje5 force-pushed the support-startup-and-shutdown-log-levels branch 2 times, most recently from 717b939 to 2046590 Compare August 21, 2025 10:03
@kssenii kssenii added the can be tested Allows running workflows for external contributors label Aug 21, 2025
@kssenii kssenii self-assigned this Aug 21, 2025
@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 21, 2025

Could you please write an integration test for this feature? See tests/integration. A warning - integration tests only work on linux.

@Blokje5 Blokje5 force-pushed the support-startup-and-shutdown-log-levels branch 3 times, most recently from 880d26b to 4b62bf3 Compare August 21, 2025 14:28
@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 21, 2025

The test seems flaky although I haven't yet figured out why. @kssenii do you have any suggestions for debugging? I can't see the Clickhouse logs from the test results.

It could be shutdown is too fast and the test is unable to get the shutdown logs.

@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 21, 2025

I can't see the Clickhouse logs from the test results.

Logs pop up when you press on FAIL:
image

@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 21, 2025

==================================== ERRORS ====================================
_______________ ERROR at teardown of test_server_no_logging[2-3] _______________
[gw0] linux -- Python 3.10.12 /usr/bin/python3

    @pytest.fixture(scope="module")
    def started_cluster():
        try:
            cluster.start()
            # Validate on startup we increase the log level.
            instance.wait_for_log_line("Starting root logger in level trace")
            yield cluster
        finally:
            # Validate on shutdown we set the log level to trace.
>           instance.wait_for_log_line("Set root logger in level trace before shutdown")

...
>               raise Exception(
                    f"Command [{shell_args}] return non-zero code {res.returncode}: {res.stderr.decode('utf-8')}"
                )
E               Exception: Command [docker exec roottestserverstartupandshutdownlogs-gw0-node-1 bash -c timeout 30 tail -Fn100 "/var/log/clickhouse-server/clickhouse-server.log" | grep -Em 1 'Set root logger in level trace before shutdown'] return non-zero code 1:

@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 22, 2025

@kssenii I meant the logs of the Clickhouse binary itself. Indeed the tests logs are clear on why it failed. I'll take a look at the tests today.

@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 22, 2025

Logs of clickhouse server are also there, inside integration_run_flaky0_0.tar.zst

@Blokje5 Blokje5 force-pushed the support-startup-and-shutdown-log-levels branch 3 times, most recently from 074f289 to 42f8635 Compare August 22, 2025 14:07
@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 22, 2025

Ok the issue was indeed the cluster.shutdown call killing clickhouse. I now trigger a SIGTERM instead so there is time to wait for the shutdown.

Last test failed due to http_query connection issues, hopefully the query call is more stable

[UPDATE]
Turns out it was the fact that I kill Clickhouse in docker & the docker instance is reused across the test invocations. I restart clickhouse now at the end of the test to deal with it.

@Blokje5 Blokje5 force-pushed the support-startup-and-shutdown-log-levels branch from 42f8635 to a4d7019 Compare August 22, 2025 14:54
Alter the log levels on startup & shutdown if the respective values are set. This allows for a higher log level during startup & shutdown of clickhouse.

Fixes: ClickHouse#85958
@Blokje5 Blokje5 force-pushed the support-startup-and-shutdown-log-levels branch from a4d7019 to 315ade5 Compare August 25, 2025 07:40
@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 25, 2025

@kssenii I decided to remove the shutdown check, it caused stability issues with the test. The test still checks startup + revert of log level to configured log level after startup.

Let me know if you want me to add anything else to the PR. Otherwise this PR is ready for review.

@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 25, 2025

it caused stability issues with the test

e.g. the test was flaky?

@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 25, 2025

it caused stability issues with the test

e.g. the test was flaky?

Yeah with the shutdown it became flaky. And I suspect it was more related to the shutdown & restart of CH inside of the container rather then the test case per-se. I got connection errors on the previous PR run.

@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 25, 2025

I got connection errors on the previous PR run.

As it was force-pushed, I cannot see what you tried to use, but I do not see why would it not work. Also I personally do not like to use wait_for_log_line, because it collects logs only from the moment you called this function, so if something you want was logged before - it will not catch it, e.g. it is easy to get a flaky test. So I usually use assert node.contains_in_log with a test unique log line (for example containing a table logger_name for a table which was created in the test - it will have table name as logger name).
Also as far as I see, this change is not supposed to affect system.text_log?

@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 25, 2025

I got connection errors on the previous PR run.

As it was force-pushed, I cannot see what you tried to use, but I do not see why would it not work. Also I personally do not like to use wait_for_log_line, because it collects logs only from the moment you called this function, so if something you want was logged before - it will not catch it, e.g. it is easy to get a flaky test. So I usually use assert node.contains_in_log with a test unique log line (for example containing a table logger_name for a table which was created in the test - it will have table name as logger name).

Ah that is a good point, it would have been better to separate the commits.

I wasn't aware wait_for_log_line would wait for calls after the call is made, that probably explains why the check was flaky in the first place. I have pushed a change with contains_in_log and hopefully that will prevent the test from being flaky.

Also as far as I see, this change is not supposed to affect system.text_log?

No it shouldn't

Comment on lines +35 to +37
instance.exec_in_container(
["bash", "-c", "pkill -{} clickhouse".format(signal)], user="root"
)
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

instance.stop_clickhouse()?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that is probably cleaner.

@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 26, 2025

@kssenii the tests now pass 🎉

I just a fuzzer failure (probably not related to this PR based on what I could see) & a failure in the Finish Workflow:

No autogenerated function categories found in programs/server/Server.cpp
No changes in docs for new feature and no autogenerated function categories found

Do you know where I can add the relevant docs? Or are the comments in config.xml sufficient?

@Blokje5 Blokje5 requested a review from kssenii August 26, 2025 07:22
@kssenii
Copy link
Copy Markdown
Member

kssenii commented Aug 26, 2025

@kssenii kssenii enabled auto-merge August 26, 2025 14:32
{
/// Set the root logger level to the shutdown level.
/// This is useful for debugging shutdown issues.
/// The root logger level will be reset to the default level after the server is fully initialized.
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: this comment doesn't make sense here

auto-merge was automatically disabled August 27, 2025 07:17

Head branch was pushed to by a user without write access

@Blokje5
Copy link
Copy Markdown
Contributor Author

Blokje5 commented Aug 28, 2025

@kssenii I guess the push I did to update the comment disabled the auto-merge?

@kssenii kssenii added this pull request to the merge queue Aug 28, 2025
Merged via the queue into ClickHouse:master with commit 19c8bb4 Aug 28, 2025
121 of 122 checks passed
@robot-ch-test-poll4 robot-ch-test-poll4 added the pr-synced-to-cloud The PR is synced to the cloud repo label Aug 28, 2025
@Blokje5 Blokje5 deleted the support-startup-and-shutdown-log-levels branch August 28, 2025 13:30
<clickhouse>
<logger>
<level>none</level>
<startupLevel>trace</startupLevel>
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Blokje5 , configuration keys should be snake_cased, not camelCased. Please update this

| `async` | When `true` (default) logging will happen asynchronously (one background thread per output channel). Otherwise it will log inside the thread calling LOG |
| `async_queue_max_size` | When using async logging, the max amount of messages that will be kept in the the queue waiting for flushing. Extra messages will be dropped |
| `startupLevel` | Startup level is used to set the root logger level at server startup. After startup log level is reverted to the `level` setting |
| `shutdownLevel` | Shutdown level is used to set the root logger level at server Shutdown. |
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here as well

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

can be tested Allows running workflows for external contributors pr-feature Pull request with new product feature pr-synced-to-cloud The PR is synced to the cloud repo

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Ability to set different startup and shutdown log levels

5 participants