10:46:37.058 [Test worker] INFO org.testcontainers.images.PullPolicy -- Image pull policy will be performed by: DefaultPullPolicy()
10:46:37.064 [Test worker] INFO org.testcontainers.utility.ImageNameSubstitutor -- Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
10:46:37.070 [Test worker] INFO org.testcontainers.DockerClientFactory -- Testcontainers version: 1.21.4
10:46:37.217 [Test worker] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
10:46:37.374 [Test worker] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
10:46:37.376 [Test worker] INFO org.testcontainers.DockerClientFactory -- Docker host IP address is localhost
10:46:37.393 [Test worker] INFO org.testcontainers.DockerClientFactory -- Connected to docker:
Server Version: 28.0.4
API Version: 1.48
Operating System: Ubuntu 24.04.5 LTS
Total Memory: 7932 MB
10:46:37.418 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Creating container for image: testcontainers/ryuk:0.12.0
10:46:37.544 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Container testcontainers/ryuk:0.12.0 is starting: d9a87bec89a315e614e19f90bfddd0c61ed357fec40935ffce9e34b42e9aa0b2
10:46:37.751 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Container testcontainers/ryuk:0.12.0 started in PT0.332984521S
10:46:37.755 [Test worker] INFO org.testcontainers.utility.RyukResourceReaper -- Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
10:46:37.756 [Test worker] INFO org.testcontainers.DockerClientFactory -- Checking the system...
10:46:37.756 [Test worker] INFO org.testcontainers.DockerClientFactory -- ✔︎ Docker server version should be at least 1.6.0
10:46:37.762 [Test worker] INFO tc.rabbitmq:3.13-management -- Pulling docker image: rabbitmq:3.13-management. Please be patient; this may take some time but only needs to be done once.
10:46:38.360 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Starting to pull image
10:46:38.371 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 0 downloaded, 0 extracted, (0 bytes/0 bytes)
10:46:38.752 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 9 pending, 1 downloaded, 0 extracted, (814 KB/? MB)
10:46:38.813 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 8 pending, 2 downloaded, 0 extracted, (26 MB/? MB)
10:46:38.879 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 7 pending, 3 downloaded, 0 extracted, (42 MB/? MB)
10:46:38.916 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 6 pending, 4 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.019 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 5 pending, 5 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.077 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 4 pending, 6 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.109 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 3 pending, 7 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.180 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 2 pending, 8 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.231 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 1 pending, 9 downloaded, 0 extracted, (42 MB/? MB)
10:46:39.367 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 0 extracted, (42 MB/109 MB)
10:46:39.612 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 1 extracted, (44 MB/109 MB)
10:46:42.092 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 2 extracted, (70 MB/109 MB)
10:46:42.460 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 3 extracted, (77 MB/109 MB)
10:46:42.479 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 4 extracted, (77 MB/109 MB)
10:46:43.473 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 5 extracted, (97 MB/109 MB)
10:46:43.491 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 6 extracted, (97 MB/109 MB)
10:46:43.508 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 7 extracted, (97 MB/109 MB)
10:46:43.533 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 8 extracted, (97 MB/109 MB)
10:46:43.544 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 9 extracted, (97 MB/109 MB)
10:46:44.379 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 10 extracted, (109 MB/109 MB)
10:46:44.390 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pull complete. 10 layers, pulled in 6s (downloaded 109 MB at 18 MB/s)
10:46:44.390 [Test worker] INFO tc.rabbitmq:3.13-management -- Image rabbitmq:3.13-management pull took PT6.62777111S
10:46:44.397 [Test worker] INFO tc.rabbitmq:3.13-management -- Creating container for image: rabbitmq:3.13-management
10:46:44.416 [Test worker] INFO tc.rabbitmq:3.13-management -- Container rabbitmq:3.13-management is starting: 119ed37969159aaeb5381e9b3fd9eb5dc6e0b3edd64874e55f3845970a4d5e11
10:46:48.631 [Test worker] INFO tc.rabbitmq:3.13-management -- Container rabbitmq:3.13-management started in PT4.233724133S
10:46:48.635 [Test worker] INFO tc.postgres:16 -- Pulling docker image: postgres:16. Please be patient; this may take some time but only needs to be done once.
10:46:49.155 [docker-java-stream-764476724] INFO tc.postgres:16 -- Starting to pull image
10:46:49.156 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 0 pending, 0 downloaded, 0 extracted, (0 bytes/0 bytes)
10:46:49.442 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 13 pending, 1 downloaded, 0 extracted, (1 KB/? MB)
10:46:49.474 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 13 pending, 1 downloaded, 1 extracted, (79 KB/? MB)
10:46:49.506 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 12 pending, 2 downloaded, 1 extracted, (79 KB/? MB)
10:46:49.520 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 11 pending, 3 downloaded, 1 extracted, (79 KB/? MB)
10:46:49.674 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 10 pending, 4 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.677 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 9 pending, 5 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.737 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 8 pending, 6 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.831 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 7 pending, 7 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.880 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 6 pending, 8 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.965 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 5 pending, 9 downloaded, 1 extracted, (6 MB/? MB)
10:46:49.980 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 5 pending, 9 downloaded, 2 extracted, (6 MB/? MB)
10:46:50.050 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 4 pending, 10 downloaded, 2 extracted, (19 MB/? MB)
10:46:50.131 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 3 pending, 11 downloaded, 2 extracted, (55 MB/? MB)
10:46:50.195 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 2 pending, 12 downloaded, 2 extracted, (55 MB/? MB)
10:46:50.273 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 2 extracted, (92 MB/? MB)
10:46:51.226 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 3 extracted, (92 MB/? MB)
10:46:51.682 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 4 extracted, (99 MB/? MB)
10:46:51.904 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 5 extracted, (101 MB/? MB)
10:46:51.921 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 6 extracted, (101 MB/? MB)
10:46:51.933 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 7 extracted, (101 MB/? MB)
10:46:57.187 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 8 extracted, (124 MB/? MB)
10:46:57.202 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 9 extracted, (124 MB/? MB)
10:46:57.216 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 10 extracted, (124 MB/? MB)
10:46:57.231 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 11 extracted, (124 MB/? MB)
10:46:57.237 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 12 extracted, (124 MB/? MB)
10:46:57.244 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 13 extracted, (124 MB/? MB)
10:46:57.249 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pull complete. 14 layers, pulled in 8s (downloaded 124 MB at 15 MB/s)
10:46:57.249 [Test worker] INFO tc.postgres:16 -- Image postgres:16 pull took PT8.61454976S
10:46:57.251 [Test worker] INFO tc.postgres:16 -- Creating container for image: postgres:16
10:46:57.263 [Test worker] INFO tc.postgres:16 -- Container postgres:16 is starting: 02ece9e47577f56a15eabc70a8af02ec6d117ee22bada260f1ab2436e135938f
10:46:58.665 [Test worker] INFO tc.postgres:16 -- Container postgres:16 started in PT1.413994812S
10:46:58.667 [Test worker] INFO tc.postgres:16 -- Container is started (JDBC URL: jdbc:postgresql://localhost:32776/test?loggerLevel=OFF)
10:46:58.772 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils -- Could not detect default configuration classes for test class [com.comp5348.group06.delivery.DeliveryProcessingIntegrationTest]: DeliveryProcessingIntegrationTest does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
10:46:58.866 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper -- Found @SpringBootConfiguration com.comp5348.group06.delivery.DeliveryApplication for test class com.comp5348.group06.delivery.DeliveryProcessingIntegrationTest
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.3.3)
2026-10-22T10:46:59.216Z INFO 3038 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : Starting DeliveryProcessingIntegrationTest using Java 17.0.20.1 with PID 3038 (started by runner in /home/runner/work/comp5348-ci-relay/comp5348-ci-relay/repo/delivery)
2026-10-22T10:46:59.221Z INFO 3038 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : No active profile set, falling back to 1 default profile: "default"
2026-10-22T10:47:00.638Z INFO 3038 --- [ Test worker] org.flywaydb.core.FlywayExecutor : Database: jdbc:postgresql://localhost:32776/test (PostgreSQL 16.15)
2026-10-22T10:47:00.659Z INFO 3038 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Schema history table "public"."flyway_schema_history" does not exist yet
2026-10-22T10:47:00.662Z INFO 3038 --- [ Test worker] o.f.core.internal.command.DbValidate : Successfully validated 1 migration (execution time 00:00.010s)
2026-10-22T10:47:00.673Z INFO 3038 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Creating Schema History table "public"."flyway_schema_history" ...
2026-10-22T10:47:00.738Z INFO 3038 --- [ Test worker] o.f.core.internal.command.DbMigrate : Current version of schema "public": << Empty Schema >>
2026-10-22T10:47:00.755Z INFO 3038 --- [ Test worker] o.f.core.internal.command.DbMigrate : Migrating schema "public" to version "1 - create delivery tables"
2026-10-22T10:47:00.794Z INFO 3038 --- [ Test worker] o.f.core.internal.command.DbMigrate : Successfully applied 1 migration to schema "public", now at version v1 (execution time 00:00.016s)
2026-10-22T10:47:01.573Z INFO 3038 --- [ Test worker] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint beneath base path '/actuator'
2026-10-22T10:47:01.627Z INFO 3038 --- [ Test worker] o.s.a.r.c.CachingConnectionFactory : Attempting to connect to: [localhost:32773]
2026-10-22T10:47:01.655Z INFO 3038 --- [ Test worker] o.s.a.r.c.CachingConnectionFactory : Created new connection: rabbitConnectionFactory#54d35ed5:0/SimpleConnection@1107c465 [delegate=amqp://guest@127.0.0.1:32773/, localPort=56708]
2026-10-22T10:47:01.717Z INFO 3038 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : Started DeliveryProcessingIntegrationTest in 2.751 seconds (process running for 25.346)
2026-10-22T10:47:01.734Z INFO 3038 --- [ scheduling-1] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2026-10-22T10:47:01.788Z INFO 3038 --- [ scheduling-1] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@36b01660
2026-10-22T10:47:01.795Z INFO 3038 --- [ scheduling-1] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2026-10-22T10:47:02.543Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-01a65794-b66c-420c-bae8-e3165ca5069a for order 31 as delivery cdd30197-70df-41e9-bee2-89ea3ec96247
2026-10-22T10:47:02.558Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Ignoring replayed delivery request request-01a65794-b66c-420c-bae8-e3165ca5069a for order 31
2026-10-22T10:47:02.626Z INFO 3038 --- [ntContainer#0-1] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-423842e3-b29a-4957-bb13-5ce95103942f for order 34 as delivery 857cd11e-9e62-4b55-9c4f-f908afe0039f
2026-10-22T10:47:02.729Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 857cd11e-9e62-4b55-9c4f-f908afe0039f for order 34 progressed to PICKED_UP
2026-10-22T10:47:02.735Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 857cd11e-9e62-4b55-9c4f-f908afe0039f for order 34 was lost after PICKED_UP
2026-10-22T10:47:02.742Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 9284bb6c-59f6-481f-8d82-3ceddd6ba815 with broker confirmation
2026-10-22T10:47:02.744Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 51126629-a551-47c7-a36b-7e344dded38b with broker confirmation
2026-10-22T10:47:02.747Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event b8cb1f2f-728e-4846-bfa7-cc33da3ca37a with broker confirmation
2026-10-22T10:47:02.789Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-6393b35c-17ed-4f57-a23d-4802552e7971 for order 35 as delivery a415fc58-cb67-4537-8c0a-089b6e6f32ad
2026-10-22T10:47:02.803Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery a415fc58-cb67-4537-8c0a-089b6e6f32ad for order 35 progressed to PICKED_UP
2026-10-22T10:47:02.813Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery a415fc58-cb67-4537-8c0a-089b6e6f32ad for order 35 progressed to IN_TRANSIT
2026-10-22T10:47:02.821Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery a415fc58-cb67-4537-8c0a-089b6e6f32ad for order 35 progressed to DELIVERED
2026-10-22T10:47:02.840Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-311e8814-2a13-4a84-b9fc-6057421971c0 for order 33 as delivery 75c20fa0-9e98-478f-9274-4c3f38c72820
2026-10-22T10:47:02.844Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 74ade375-5557-45a9-bee0-bc751b82502c with broker confirmation
2026-10-22T10:47:02.869Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-ffacb952-bbc9-44c3-971f-6e77644de986 for order 32 as delivery 78f38cf7-e3fa-4799-9f64-7227c7308c3f
2026-10-22T10:47:02.872Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 78f38cf7-e3fa-4799-9f64-7227c7308c3f for order 32 progressed to PICKED_UP
2026-10-22T10:47:02.877Z INFO 3038 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 78f38cf7-e3fa-4799-9f64-7227c7308c3f for order 32 was lost after PICKED_UP
2026-10-22T10:47:02.883Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event a98ef59b-7c8d-47e8-a6f9-9122da510237 with broker confirmation
2026-10-22T10:47:02.885Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event edaa1489-a720-4563-8470-5a34a24eb07b with broker confirmation
2026-10-22T10:47:02.888Z INFO 3038 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 8d87b030-9053-4f89-a639-9f132f3852c4 with broker confirmation
2026-10-22T10:47:03.641Z INFO 3038 --- [ntContainer#0-1] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@eb1e868: tags=[[amq.ctag-QICb5XIM8YB5w8gwdnNHDA]], channel=Cached Rabbit Channel: PublisherCallbackChannelImpl: AMQChannel(amqp://guest@127.0.0.1:32773/,1), conn: Proxy@1d4531fa Shared Rabbit Connection: SimpleConnection@1107c465 [delegate=amqp://guest@127.0.0.1:32773/, localPort=56708], acknowledgeMode=AUTO local queue size=0