Skip to content

Improve docker-compose logging#76140

Merged
Felixoid merged 2 commits intomasterfrom
kafka-test
Feb 15, 2025
Merged

Improve docker-compose logging#76140
Felixoid merged 2 commits intomasterfrom
kafka-test

Conversation

@Felixoid
Copy link
Copy Markdown
Member

Changelog category (leave one):

  • Build/Testing/Packaging Improvement

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

Do not collect the docker-compose logs at the end of running since the script is often killed. Instead, collect them in the background.

Documentation entry for user-facing changes

  • Documentation is written (mandatory for new features)

@clickhouse-gh
Copy link
Copy Markdown
Contributor

clickhouse-gh Bot commented Feb 14, 2025

Workflow [PR], commit [e91ec72]

@clickhouse-gh clickhouse-gh Bot added the pr-build Pull request with build/testing/packaging improvement label Feb 14, 2025
@Felixoid Felixoid force-pushed the kafka-test branch 2 times, most recently from 5c4dcaf to 25e9114 Compare February 14, 2025 14:36
@Felixoid Felixoid marked this pull request as draft February 14, 2025 16:31
@Felixoid Felixoid marked this pull request as ready for review February 14, 2025 19:43
@Felixoid Felixoid self-assigned this Feb 14, 2025
@Felixoid
Copy link
Copy Markdown
Member Author

Felixoid commented Feb 14, 2025

Here's the output for pgrep on a runner at the parallel tests launch:

$ pgrep -af docker-compose | tail -4
3588986 docker compose --env-file /ClickHouse/tests/integration/test_backup_restore_new/_instances-0-gw1/.env --project-name roottestbackuprestorenew-gw1 --file /ClickHouse/tests/integration/test_backup_restore_new/_instances-0-gw1/instance/docker-compose.yml logs --follow
3589140 /usr/libexec/docker/cli-plugins/docker-compose compose --env-file /ClickHouse/tests/integration/test_backup_restore_new/_instances-0-gw1/.env --project-name roottestbackuprestorenew-gw1 --file /ClickHouse/tests/integration/test_backup_restore_new/_instances-0-gw1/instance/docker-compose.yml logs --follow
3619643 docker compose --env-file /ClickHouse/tests/integration/test_dictionaries_all_layouts_separate_sources/_instances-mongo_uri-0-gw4/.env --project-name roottestdictionariesalllayoutsseparatesourcesmongouri-gw4 --file /ClickHouse/tests/integration/test_dictionaries_all_layouts_separate_sources/_instances-mongo_uri-0-gw4/uri_node/docker-compose.yml --file /ClickHouse/tests/integration/helpers/../../../tests/integration/compose/docker_compose_mongo.yml logs --follow
3619671 /usr/libexec/docker/cli-plugins/docker-compose compose --env-file /ClickHouse/tests/integration/test_dictionaries_all_layouts_separate_sources/_instances-mongo_uri-0-gw4/.env --project-name roottestdictionariesalllayoutsseparatesourcesmongouri-gw4 --file /ClickHouse/tests/integration/test_dictionaries_all_layouts_separate_sources/_instances-mongo_uri-0-gw4/uri_node/docker-compose.yml --file /ClickHouse/tests/integration/helpers/../../../tests/integration/compose/docker_compose_mongo.yml logs --follow

Now, we'll have all the docker compose logs, regardless of whether the runner process was killed or not.

Copy link
Copy Markdown
Member

@azat azat left a comment

Choose a reason for hiding this comment

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

Killer feature!

P.S. why does it have changes for Kafka here?

os.makedirs(p.dirname(self.docker_logs_path), exist_ok=True)
# Here errors='replace' because docker can sometimes write non-unicode characters to its output.
docker_logs_path = open(self.docker_logs_path, "w+", errors="replace")
subprocess.Popen(
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.

Should we kill this process properly as well?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

No, the docker compose logs --follow dies with exit code 0 when the compose services finish:

> docker compose up -d
[+] Running 5/5
 ✔ Container graphite-clickhouse-tldr-carbon-clickhouse-1    Started                                                                               0.5s
 ✔ Container graphite-clickhouse-tldr-carbonapi-1            Started                                                                               0.4s
 ✔ Container graphite-clickhouse-tldr-clickhouse-1           Started                                                                               0.5s
 ✔ Container graphite-clickhouse-tldr-grafana-1              Started                                                                               0.4s
 ✔ Container graphite-clickhouse-tldr-graphite-clickhouse-1  Started                                                                               0.5s
> docker compose logs -f &> docker.logs &
[1] 2323019
> docker compose stop
[+] Stopping 5/5
 ✔ Container graphite-clickhouse-tldr-grafana-1              Stopped                                                                               0.4s
 ✔ Container graphite-clickhouse-tldr-clickhouse-1           Stopped                                                                               2.5s
 ✔ Container graphite-clickhouse-tldr-carbonapi-1            Stopped                                                                               0.3s
 ✔ Container graphite-clickhouse-tldr-graphite-clickhouse-1  Stopped                                                                               0.4s
 ✔ Container graphite-clickhouse-tldr-carbon-clickhouse-1    Stopped                                                                               0.5s
[1]  + done       docker compose logs -f &> docker.logs
> tail -5 docker.logs
carbonapi-1 exited with code 0
grafana-1 exited with code 0
graphite-clickhouse-1 exited with code 0
carbon-clickhouse-1 exited with code 1
clickhouse-1 exited with code 0

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.

I know, but still looks odd, not to wait the process properly

Copy link
Copy Markdown
Member Author

@Felixoid Felixoid Feb 15, 2025

Choose a reason for hiding this comment

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

We shouldn't wait for it, that's the case.

It's a background process writing the logs in realtime.

And it's killed on it's own, when the tests' docker compose is finished

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.

We shouldn't wait for it, that's the case.

This is minor, in terms of the behavior, but leaving processes without waiting is bad

For instance it could be the case that docker-compose has some buffering for logs and without properly waiting for it we cannot be sure that everything is dumped

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

I see. Yeah, we can wait for it in shutdown

@Felixoid
Copy link
Copy Markdown
Member Author

Felixoid commented Feb 15, 2025

P.S. why does it have changes for Kafka here?

I've prepared something for fixing #69452 and tests in a follow-up. It's just reordering for now to have the logs fixed.

@Felixoid
Copy link
Copy Markdown
Member Author

You know, I'd really move splitting kafka tests into the different PR #76208

@Felixoid Felixoid added this pull request to the merge queue Feb 15, 2025
Merged via the queue into master with commit afdd233 Feb 15, 2025
@Felixoid Felixoid deleted the kafka-test branch February 15, 2025 20:37
@robot-ch-test-poll1 robot-ch-test-poll1 added the pr-synced-to-cloud The PR is synced to the cloud repo label Feb 15, 2025
@azat azat self-assigned this Feb 16, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

pr-build Pull request with build/testing/packaging improvement 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.

3 participants