11:52:50.005 [Test worker] INFO org.testcontainers.images.PullPolicy -- Image pull policy will be performed by: DefaultPullPolicy()
11:52:50.013 [Test worker] INFO org.testcontainers.utility.ImageNameSubstitutor -- Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
11:52:50.023 [Test worker] INFO org.testcontainers.DockerClientFactory -- Testcontainers version: 1.21.4
11:52:50.213 [Test worker] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
11:52:50.427 [Test worker] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
11:52:50.429 [Test worker] INFO org.testcontainers.DockerClientFactory -- Docker host IP address is localhost
11:52:50.452 [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: 7931 MB
11:52:50.490 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Creating container for image: testcontainers/ryuk:0.12.0
11:52:50.631 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Container testcontainers/ryuk:0.12.0 is starting: 6a6e2a17654ba3a58d1127e9846531f44f5244459923d5340e3f42db3893bc65
11:52:50.943 [Test worker] INFO tc.testcontainers/ryuk:0.12.0 -- Container testcontainers/ryuk:0.12.0 started in PT0.45252794S
11:52:50.951 [Test worker] INFO org.testcontainers.utility.RyukResourceReaper -- Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
11:52:50.951 [Test worker] INFO org.testcontainers.DockerClientFactory -- Checking the system...
11:52:50.951 [Test worker] INFO org.testcontainers.DockerClientFactory -- ✔︎ Docker server version should be at least 1.6.0
11:52:50.962 [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.
11:52:51.729 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Starting to pull image
11:52:51.748 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 0 downloaded, 0 extracted, (0 bytes/0 bytes)
11:52:52.140 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 9 pending, 1 downloaded, 0 extracted, (382 KB/? MB)
11:52:52.199 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 8 pending, 2 downloaded, 0 extracted, (814 KB/? MB)
11:52:52.306 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 7 pending, 3 downloaded, 0 extracted, (26 MB/? MB)
11:52:52.313 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 6 pending, 4 downloaded, 0 extracted, (26 MB/? MB)
11:52:52.463 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 5 pending, 5 downloaded, 0 extracted, (31 MB/? MB)
11:52:52.476 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 4 pending, 6 downloaded, 0 extracted, (31 MB/? MB)
11:52:52.498 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 3 pending, 7 downloaded, 0 extracted, (34 MB/? MB)
11:52:52.648 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 2 pending, 8 downloaded, 0 extracted, (39 MB/? MB)
11:52:52.669 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 1 pending, 9 downloaded, 0 extracted, (39 MB/? MB)
11:52:52.732 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 0 extracted, (46 MB/109 MB)
11:52:53.149 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 1 extracted, (55 MB/109 MB)
11:52:54.490 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 2 extracted, (70 MB/109 MB)
11:52:54.660 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 3 extracted, (77 MB/109 MB)
11:52:54.676 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 4 extracted, (77 MB/109 MB)
11:52:55.298 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 5 extracted, (97 MB/109 MB)
11:52:55.310 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 6 extracted, (97 MB/109 MB)
11:52:55.317 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 7 extracted, (97 MB/109 MB)
11:52:55.324 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 8 extracted, (97 MB/109 MB)
11:52:55.331 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 9 extracted, (97 MB/109 MB)
11:52:55.790 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pulling image layers: 0 pending, 10 downloaded, 10 extracted, (109 MB/109 MB)
11:52:55.797 [docker-java-stream--3081363] INFO tc.rabbitmq:3.13-management -- Pull complete. 10 layers, pulled in 4s (downloaded 109 MB at 27 MB/s)
11:52:55.797 [Test worker] INFO tc.rabbitmq:3.13-management -- Image rabbitmq:3.13-management pull took PT4.835497934S
11:52:55.802 [Test worker] INFO tc.rabbitmq:3.13-management -- Creating container for image: rabbitmq:3.13-management
11:52:55.818 [Test worker] INFO tc.rabbitmq:3.13-management -- Container rabbitmq:3.13-management is starting: 4cada58abdb094140de218511dae6e248376ffcd0d98158552bc1bf3c10cc0c0
11:53:01.980 [Test worker] INFO tc.rabbitmq:3.13-management -- Container rabbitmq:3.13-management started in PT6.177809922S
11:53:01.983 [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.
11:53:02.723 [docker-java-stream-764476724] INFO tc.postgres:16 -- Starting to pull image
11:53:02.726 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 0 pending, 0 downloaded, 0 extracted, (0 bytes/0 bytes)
11:53:03.125 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 13 pending, 1 downloaded, 0 extracted, (16 KB/? MB)
11:53:03.143 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 12 pending, 2 downloaded, 0 extracted, (79 KB/? MB)
11:53:03.150 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 12 pending, 2 downloaded, 1 extracted, (79 KB/? MB)
11:53:03.167 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 11 pending, 3 downloaded, 1 extracted, (79 KB/? MB)
11:53:03.324 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 10 pending, 4 downloaded, 1 extracted, (6 MB/? MB)
11:53:03.330 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 10 pending, 4 downloaded, 2 extracted, (6 MB/? MB)
11:53:03.350 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 9 pending, 5 downloaded, 2 extracted, (6 MB/? MB)
11:53:03.365 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 8 pending, 6 downloaded, 2 extracted, (6 MB/? MB)
11:53:03.387 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 8 pending, 6 downloaded, 3 extracted, (7 MB/? MB)
11:53:03.497 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 7 pending, 7 downloaded, 3 extracted, (11 MB/? MB)
11:53:03.540 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 6 pending, 8 downloaded, 3 extracted, (12 MB/? MB)
11:53:03.700 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 5 pending, 9 downloaded, 3 extracted, (41 MB/? MB)
11:53:03.730 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 4 pending, 10 downloaded, 3 extracted, (73 MB/? MB)
11:53:03.887 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 3 pending, 11 downloaded, 3 extracted, (98 MB/? MB)
11:53:03.897 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 2 pending, 12 downloaded, 3 extracted, (98 MB/? MB)
11:53:03.917 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 3 extracted, (98 MB/? MB)
11:53:03.991 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 4 extracted, (98 MB/? MB)
11:53:04.150 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 5 extracted, (100 MB/? MB)
11:53:04.159 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 6 extracted, (100 MB/? MB)
11:53:04.170 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 7 extracted, (100 MB/? MB)
11:53:07.899 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 8 extracted, (124 MB/? MB)
11:53:07.914 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 9 extracted, (124 MB/? MB)
11:53:07.925 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 10 extracted, (124 MB/? MB)
11:53:07.939 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 11 extracted, (124 MB/? MB)
11:53:07.947 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 12 extracted, (124 MB/? MB)
11:53:07.956 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pulling image layers: 1 pending, 13 downloaded, 13 extracted, (124 MB/? MB)
11:53:07.960 [docker-java-stream-764476724] INFO tc.postgres:16 -- Pull complete. 14 layers, pulled in 5s (downloaded 124 MB at 24 MB/s)
11:53:07.960 [Test worker] INFO tc.postgres:16 -- Image postgres:16 pull took PT5.97735562S
11:53:07.963 [Test worker] INFO tc.postgres:16 -- Creating container for image: postgres:16
11:53:07.974 [Test worker] INFO tc.postgres:16 -- Container postgres:16 is starting: 1c343c29ed9107f5158bee7734f9239bc831ed6e7d21f6777050cf9586680710
11:53:08.972 [Test worker] INFO tc.postgres:16 -- Container postgres:16 started in PT1.008033754S
11:53:08.974 [Test worker] INFO tc.postgres:16 -- Container is started (JDBC URL: jdbc:postgresql://localhost:32776/test?loggerLevel=OFF)
11:53:09.121 [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.
11:53:09.272 [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-22T11:53:09.808Z INFO 3120 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : Starting DeliveryProcessingIntegrationTest using Java 17.0.20.1 with PID 3120 (started by runner in /home/runner/work/comp5348-ci-relay/comp5348-ci-relay/repo/delivery)
2026-10-22T11:53:09.812Z INFO 3120 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : No active profile set, falling back to 1 default profile: "default"
2026-10-22T11:53:12.002Z INFO 3120 --- [ Test worker] org.flywaydb.core.FlywayExecutor : Database: jdbc:postgresql://localhost:32776/test (PostgreSQL 16.15)
2026-10-22T11:53:12.037Z INFO 3120 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Schema history table "public"."flyway_schema_history" does not exist yet
2026-10-22T11:53:12.039Z INFO 3120 --- [ Test worker] o.f.core.internal.command.DbValidate : Successfully validated 1 migration (execution time 00:00.014s)
2026-10-22T11:53:12.054Z INFO 3120 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Creating Schema History table "public"."flyway_schema_history" ...
2026-10-22T11:53:12.171Z INFO 3120 --- [ Test worker] o.f.core.internal.command.DbMigrate : Current version of schema "public": << Empty Schema >>
2026-10-22T11:53:12.198Z INFO 3120 --- [ Test worker] o.f.core.internal.command.DbMigrate : Migrating schema "public" to version "1 - create delivery tables"
2026-10-22T11:53:12.236Z INFO 3120 --- [ Test worker] o.f.core.internal.command.DbMigrate : Successfully applied 1 migration to schema "public", now at version v1 (execution time 00:00.018s)
2026-10-22T11:53:13.534Z INFO 3120 --- [ Test worker] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint beneath base path '/actuator'
2026-10-22T11:53:13.640Z INFO 3120 --- [ Test worker] o.s.a.r.c.CachingConnectionFactory : Attempting to connect to: [localhost:32773]
2026-10-22T11:53:13.687Z INFO 3120 --- [ Test worker] o.s.a.r.c.CachingConnectionFactory : Created new connection: rabbitConnectionFactory#3b64f131:0/SimpleConnection@2689b752 [delegate=amqp://guest@127.0.0.1:32773/, localPort=59670]
2026-10-22T11:53:13.770Z INFO 3120 --- [ Test worker] .c.g.d.DeliveryProcessingIntegrationTest : Started DeliveryProcessingIntegrationTest in 4.339 seconds (process running for 24.788)
2026-10-22T11:53:13.798Z INFO 3120 --- [ scheduling-1] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2026-10-22T11:53:14.157Z INFO 3120 --- [ scheduling-1] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@6386234a
2026-10-22T11:53:14.170Z INFO 3120 --- [ scheduling-1] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2026-10-22T11:53:14.933Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-164f4035-a6f3-44c5-a55b-ab40df2a5161 for order 31 as delivery e99aeec2-e6e4-4a1b-9cee-77dc56a0c65a
2026-10-22T11:53:14.949Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Ignoring replayed delivery request request-164f4035-a6f3-44c5-a55b-ab40df2a5161 for order 31
2026-10-22T11:53:15.032Z INFO 3120 --- [ntContainer#0-1] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-d04fb84f-78e0-467a-b79a-ccc93adb1065 for order 34 as delivery a00cff21-6ff4-40d3-9c91-3018c3858265
2026-10-22T11:53:15.125Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery a00cff21-6ff4-40d3-9c91-3018c3858265 for order 34 progressed to PICKED_UP
2026-10-22T11:53:15.128Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery a00cff21-6ff4-40d3-9c91-3018c3858265 for order 34 was lost after PICKED_UP
2026-10-22T11:53:15.134Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 74251233-281f-4bb9-ac78-319ea22281da with broker confirmation
2026-10-22T11:53:15.136Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event c7b2c62a-8162-48cf-889e-10bf7c9e0554 with broker confirmation
2026-10-22T11:53:15.138Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 6adf7edd-f8c9-4d00-a093-309e568914e4 with broker confirmation
2026-10-22T11:53:15.173Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-d6a91893-e269-4c4c-af7c-1feec078b179 for order 35 as delivery be75b794-648b-44af-87a2-af3d9a94e475
2026-10-22T11:53:15.177Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery be75b794-648b-44af-87a2-af3d9a94e475 for order 35 progressed to PICKED_UP
2026-10-22T11:53:15.179Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery be75b794-648b-44af-87a2-af3d9a94e475 for order 35 progressed to IN_TRANSIT
2026-10-22T11:53:15.182Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery be75b794-648b-44af-87a2-af3d9a94e475 for order 35 progressed to DELIVERED
2026-10-22T11:53:15.200Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-80aea69f-3d5a-44ea-b733-76acb7387f76 for order 33 as delivery 1279e8db-2be5-4de4-967d-facb8b5a66dd
2026-10-22T11:53:15.205Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 8a387f8e-1975-47f6-8628-67f5106a8015 with broker confirmation
2026-10-22T11:53:15.227Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Accepted delivery request request-fa058c40-68f2-4295-bdff-1e0436df81ba for order 32 as delivery 7b68fe1c-4700-4304-946d-6de74294579b
2026-10-22T11:53:15.230Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 7b68fe1c-4700-4304-946d-6de74294579b for order 32 progressed to PICKED_UP
2026-10-22T11:53:15.233Z INFO 3120 --- [ Test worker] c.c.g.d.s.DeliveryProcessingService : Delivery 7b68fe1c-4700-4304-946d-6de74294579b for order 32 was lost after PICKED_UP
2026-10-22T11:53:15.240Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 2af21f21-cc74-4986-9aff-c2eb0812eb14 with broker confirmation
2026-10-22T11:53:15.243Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event 3bd150dc-06b7-40b5-8fe6-1d85fbe0ba1c with broker confirmation
2026-10-22T11:53:15.254Z INFO 3120 --- [ Test worker] c.c.g.d.m.DeliveryEventOutboxPublisher : Published delivery status event eac12d23-e4e8-499c-857c-64062a8cb5fb with broker confirmation