Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

State cache validity check is flaky #431

Open
onukristo opened this issue Dec 13, 2023 · 2 comments
Open

State cache validity check is flaky #431

onukristo opened this issue Dec 13, 2023 · 2 comments

Comments

@onukristo
Copy link

onukristo commented Dec 13, 2023

I noticed, that composeUp sometimes takes 4-5 seconds, even when the containers are running from previous execution.
At other times, it is very fast, less than half a second.

On slow runs, the following is logged: "Current and cached states are different, cannot use the cached service infos.", after which some slow steps, including slow tcp checks, are done.

I realised, that the check here is a bit naive, not considering, that the arrays can have a different order.

For example, first cache state:

[Command:"docker-entrypoint.s…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:48485d159557, Image:mariadb:10.4.27, LocalVolumes:1, Mounts:9d32a44f2b12f4…, Name:wise-kafka-processor-mariadb-1, Names:wise-kafka-processor-mariadb-1, Networks:wise-kafka-processor_default, Ports:0.0.0.0:44359->3306/tcp, Publishers:[[URL:0.0.0.0, TargetPort:3306, PublishedPort:44359, Protocol:tcp]], Service:mariadb, Size:0B, State:running, Status:Up]     [Command:"docker-entrypoint.s…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:fd2671a506dd, Image:postgres:14, LocalVolumes:1, Mounts:d4bed348d71737…, Name:wise-kafka-processor-postgres-1, Names:wise-kafka-processor-postgres-1, Networks:wise-kafka-processor_default, Ports:0.0.0.0:62682->5432/tcp, Publishers:[[URL:0.0.0.0, TargetPort:5432, PublishedPort:62682, Protocol:tcp]], Service:postgres, Size:0B, State:running, Status:Up]      [Command:"/docker-entrypoint.…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:a8eca8e46ecf, Image:zookeeper:3.7.1, LocalVolumes:3, Mounts:ac8a97f7ce79f3…,7111d5ab0ca1f2…,1fd0fecccf9c54…, Name:wise-kafka-processor-zookeeper-1, Names:wise-kafka-processor-zookeeper-1, Networks:wise-kafka-processor_default, Ports:2888/tcp, 3888/tcp, 8080/tcp, 0.0.0.0:59782->2181/tcp, Publishers:[[URL:0.0.0.0, TargetPort:2181, PublishedPort:59782, Protocol:tcp], [URL:, TargetPort:2888, PublishedPort:0, Protocol:tcp], [URL:, TargetPort:3888, PublishedPort:0, Protocol:tcp], [URL:, TargetPort:8080, PublishedPort:0, Protocol:tcp]], Service:zookeeper, Size:0B, State:running, Status:Up] [Command:"start-kafka.sh", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:eea0468a40d5, Image:wurstmeister/kafka:2.12-2.4.1, LocalVolumes:1, Mounts:15320d4b7b223e…,/run/host-serv…, Name:wise_kafka_processor_kafka, Names:wise_kafka_processor_kafka, Networks:wise-kafka-processor_default, Ports:0.0.0.0:49178->9092/tcp, Publishers:[[URL:0.0.0.0, TargetPort:9092, PublishedPort:49178, Protocol:tcp]], Service:kafka, Size:0B, State:running, Status:Up]name: wise-kafka-processor

and second cache state:

[Command:"docker-entrypoint.s…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:48485d159557, Image:mariadb:10.4.27, LocalVolumes:1, Mounts:9d32a44f2b12f4…, Name:wise-kafka-processor-mariadb-1, Names:wise-kafka-processor-mariadb-1, Networks:wise-kafka-processor_default, Ports:0.0.0.0:44359->3306/tcp, Publishers:[[URL:0.0.0.0, TargetPort:3306, PublishedPort:44359, Protocol:tcp]], Service:mariadb, Size:0B, State:running, Status:Up]     [Command:"docker-entrypoint.s…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:fd2671a506dd, Image:postgres:14, LocalVolumes:1, Mounts:d4bed348d71737…, Name:wise-kafka-processor-postgres-1, Names:wise-kafka-processor-postgres-1, Networks:wise-kafka-processor_default, Ports:0.0.0.0:62682->5432/tcp, Publishers:[[URL:0.0.0.0, TargetPort:5432, PublishedPort:62682, Protocol:tcp]], Service:postgres, Size:0B, State:running, Status:Up]      [Command:"/docker-entrypoint.…", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:a8eca8e46ecf, Image:zookeeper:3.7.1, LocalVolumes:3, Mounts:1fd0fecccf9c54…,ac8a97f7ce79f3…,7111d5ab0ca1f2…, Name:wise-kafka-processor-zookeeper-1, Names:wise-kafka-processor-zookeeper-1, Networks:wise-kafka-processor_default, Ports:2888/tcp, 3888/tcp, 8080/tcp, 0.0.0.0:59782->2181/tcp, Publishers:[[URL:0.0.0.0, TargetPort:2181, PublishedPort:59782, Protocol:tcp], [URL:, TargetPort:2888, PublishedPort:0, Protocol:tcp], [URL:, TargetPort:3888, PublishedPort:0, Protocol:tcp], [URL:, TargetPort:8080, PublishedPort:0, Protocol:tcp]], Service:zookeeper, Size:0B, State:running, Status:Up] [Command:"start-kafka.sh", CreatedAt:2023-12-13 10:08:48 +0200 EET, ExitCode:0, Health:, ID:eea0468a40d5, Image:wurstmeister/kafka:2.12-2.4.1, LocalVolumes:1, Mounts:15320d4b7b223e…,/run/host-serv…, Name:wise_kafka_processor_kafka, Names:wise_kafka_processor_kafka, Networks:wise-kafka-processor_default, Ports:0.0.0.0:49178->9092/tcp, Publishers:[[URL:0.0.0.0, TargetPort:9092, PublishedPort:49178, Protocol:tcp]], Service:kafka, Size:0B, State:running, Status:Up]name: wise-kafka-processor

are semantically the same, however have a order difference of "Mounts:ac8a97f7ce79f3…,7111d5ab0ca1f2…,1fd0fecccf9c54…" vs "Mounts:1fd0fecccf9c54…,ac8a97f7ce79f3…,7111d5ab0ca1f2...".

Expected behaviours:

  1. Use cached state, when semantically nothing changes between the runs.
  2. When order of mounts is different, still consider the cached state equal to current state.

In any case, this is a minor thing. Thanks for the great library.

Appendix #1: fast run logs:

Dec 13 10:30:54 
Dec 13 10:30:54 > Task :composeUp
Dec 13 10:30:54 Cached services infos loaded while 'stopContainers' is set to 'false'.
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 | Name                       | Container Port | Mapping         |
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 | wise_kafka_processor_kafka | 9092           | localhost:49178 |
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 | mariadb-1                  | 3306           | localhost:44359 |
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 | postgres-1                 | 5432           | localhost:62682 |
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 | zookeeper-1                | 2181           | localhost:59782 |
Dec 13 10:30:54 +----------------------------+----------------+-----------------+
Dec 13 10:30:54 
Dec 13 10:30:54 > Task :composeDownForcedOnFailure SKIPPED
Dec 13 10:30:54 
Dec 13 10:30:54 Deprecated Gradle features were used in this build, making it incompatible with Gradle 9.0.
Dec 13 10:30:54 
Dec 13 10:30:54 You can use '--warning-mode all' to show the individual deprecation warnings and determine if they come from your own scripts or plugins.
Dec 13 10:30:54 
Dec 13 10:30:54 For more on this, please refer to https://docs.gradle.org/8.5/userguide/command_line_interface.html#sec:command_line_warnings in the Gradle documentation.
Dec 13 10:30:54 
Dec 13 10:30:54 BUILD SUCCESSFUL in 662ms
Dec 13 10:30:54 1 actionable task: 1 executed

Appendix #2: slow run logs:

Dec 13 10:31:55 
Dec 13 10:31:55 > Task :composeUp
Dec 13 10:31:55 Current and cached states are different, cannot use the cached service infos.
Dec 13 10:31:55 Will use localhost as host of kafka
Dec 13 10:31:55 Will use localhost as host of mariadb
Dec 13 10:31:55 Will use localhost as host of postgres
Dec 13 10:31:55 Will use localhost as host of zookeeper
Dec 13 10:31:55 Probing TCP socket on localhost:49178 of 'wise_kafka_processor_kafka'
Dec 13 10:31:55 TCP socket on localhost:49178 of 'wise_kafka_processor_kafka' is ready
Dec 13 10:31:55 Probing TCP socket on localhost:44359 of 'mariadb-1'
Dec 13 10:31:55 TCP socket on localhost:44359 of 'mariadb-1' is ready
Dec 13 10:31:55 Probing TCP socket on localhost:62682 of 'postgres-1'
Dec 13 10:31:56 TCP socket on localhost:62682 of 'postgres-1' is ready
Dec 13 10:31:56 Probing TCP socket on localhost:59782 of 'zookeeper-1'
Dec 13 10:31:57 TCP socket on localhost:59782 of 'zookeeper-1' is ready
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 | Name                       | Container Port | Mapping         |
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 | wise_kafka_processor_kafka | 9092           | localhost:49178 |
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 | mariadb-1                  | 3306           | localhost:44359 |
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 | postgres-1                 | 5432           | localhost:62682 |
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 | zookeeper-1                | 2181           | localhost:59782 |
Dec 13 10:31:57 +----------------------------+----------------+-----------------+
Dec 13 10:31:57 
Dec 13 10:31:57 > Task :composeDownForcedOnFailure SKIPPED
Dec 13 10:31:57 
Dec 13 10:31:57 Deprecated Gradle features were used in this build, making it incompatible with Gradle 9.0.
Dec 13 10:31:57 
Dec 13 10:31:57 You can use '--warning-mode all' to show the individual deprecation warnings and determine if they come from your own scripts or plugins.
Dec 13 10:31:57 
Dec 13 10:31:57 For more on this, please refer to https://docs.gradle.org/8.5/userguide/command_line_interface.html#sec:command_line_warnings in the Gradle documentation.
Dec 13 10:31:57 
Dec 13 10:31:57 BUILD SUCCESSFUL in 4s
Dec 13 10:31:57 1 actionable task: 1 executed
@augi
Copy link
Member

augi commented Dec 13, 2023

Hello, thank you very much for reporting this! 👍 Agree that the current implementation is naïve, just please refer to getStateforCache method - this is where the state is computed, and there is already some kind of normalization.

So feel free to prepare a PR that would improve this behavior 🙏

Also, please note that there is already removal of the Labels field, but it is not so important for the container. I would prefer a more sophisticates solution for the Mounts field, for example just order the array.

@tom-wozniakowski-tw
Copy link
Contributor

I have raised a PR to fix this bug: #468

Would appreciate a review and a merge if you're happy @augi !

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

No branches or pull requests

3 participants