Yoann Rodière ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) *commented* on HSEARCH-4722 ( https://hibernate.atlassian.net/browse/HSEARCH-4722?atlOrigin=eyJpIjoiYWZ... ) Re: Fix postgresql container start timing out on CI ( https://hibernate.atlassian.net/browse/HSEARCH-4722?atlOrigin=eyJpIjoiYWZ... ) The failure occurs randomly, but it happened again today: https://ci.hibernate.org/blue/organizations/jenkins/hibernate-search/deta... ( https://ci.hibernate.org/blue/organizations/jenkins/hibernate-search/deta... ) [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- Picked up JAVA_TOOL_OPTIONS: -Dmaven.ext.class.path=&quot;/var/lib/jenkins/workspace/hibernate-search_PR-3289(a)tmp/withMaven7700036c/pipeline-maven-spy.jar&quot; -Dorg.jenkinsci.plugins.pipeline.maven.reportsFolder="/var/lib/jenkins/workspace/hibernate-search_PR-3289@tmp/withMaven7700036c" [INFO] [INFO] Results: [INFO] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0 [INFO] [INFO] [INFO] --- maven-jar-plugin:3.3.0:jar (default-jar) @ hibernate-search-integrationtest-showcase-library --- [INFO] Building jar: /mnt/jenkins-workdir/workspace/hibernate-search_PR-3289/integrationtest/showcase/library/target/hibernate-search-integrationtest-showcase-library-6.2.0-SNAPSHOT.jar [INFO] [INFO] --- docker-maven-plugin:0.40.2:stop (docker-start) @ hibernate-search-integrationtest-showcase-library --- [INFO] [INFO] --- docker-maven-plugin:0.40.2:start (docker-start) @ hibernate-search-integrationtest-showcase-library --- [INFO] DOCKER> [opensearchproject/opensearch:8.4.3] "opensearch": Skipped running [INFO] DOCKER> [mariadb:10.5.8] "mariadb": Skipped running [INFO] DOCKER> [mysql:8.0.22] "mysql": Skipped running [INFO] DOCKER> [ibmcom/db2:11.5.8.0] "db2": Skipped running [INFO] DOCKER> [gvenzl/oracle-xe:21-slim-faststart] "oracle": Skipped running [INFO] DOCKER> [mcr.microsoft.com/mssql/server:2019-CU8-ubuntu-16.04] "mssql": Skipped running [INFO] DOCKER> [cockroachdb/cockroach:v22.1.4] "cockroachdb": Skipped running [INFO] DOCKER> [elastic/elasticsearch:8.4.3] "elasticsearch": Start container 7adecad9203b [INFO] DOCKER> [postgres:13.1] "postgres": Start container 47af9384c85e [INFO] DOCKER> [elastic/elasticsearch:8.4.3] "elasticsearch": Waiting on url http://localhost:9200 with method GET for status 200. 15:20:23.046 PostgreSQL:The files belonging to this database system will be owned by user "postgres". 15:20:23.047 PostgreSQL:This user must also own the server process. 15:20:23.047 PostgreSQL:The database cluster will be initialized with locale "en_US.utf8". 15:20:23.047 PostgreSQL:The default database encoding has accordingly been set to "UTF8". 15:20:23.047 PostgreSQL:The default text search configuration will be set to "english". 15:20:23.047 PostgreSQL:Data page checksums are disabled. 15:20:23.047 PostgreSQL:fixing permissions on existing directory /var/lib/postgresql/data ... ok 15:20:23.048 PostgreSQL:creating subdirectories ... ok 15:20:23.048 PostgreSQL:selecting dynamic shared memory implementation ... posix 15:20:23.060 PostgreSQL:selecting default max_connections ... 100 15:20:23.080 PostgreSQL:selecting default shared_buffers ... 128MB 15:20:23.092 PostgreSQL:selecting default time zone ... Etc/UTC 15:20:23.097 PostgreSQL:creating configuration files ... ok 15:20:23.230 PostgreSQL:running bootstrap script ... ok 15:20:23.709 PostgreSQL:performing post-bootstrap initialization ... ok 15:20:26.906 Elasticsearch:{"@timestamp":"2022-10-29T15:20:26.899Z", "log.level": "WARN", "message":"Unable to load config file null", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"com.amazonaws.auth.profile.internal.BasicProfileConfigFileLoader","elasticsearch.node.name":"7adecad9203b","elasticsearch.cluster.name":"docker-cluster","error.type":"java.security.AccessControlException","error.message":"access denied (\"java.io.FilePermission\" \"/usr/share/elasticsearch/.aws/config\" \"read\")","error.stack_trace":"java.security.AccessControlException: access denied (\"java.io.FilePermission\" \"/usr/share/elasticsearch/.aws/config\" \"read\")\n\tat java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)\n\tat java.base/java.security.AccessController.checkPermission(AccessController.java:1068)\n\tat java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:411)\n\tat java.base/java.lang.SecurityManager.checkRead(SecurityManager.java:751)\n\tat java.base/java.io.File.exists(File.java:829)\n\tat com.amazonaws.profile.path.config.SharedConfigDefaultLocationProvider.getLocation(SharedConfigDefaultLocationProvider.java:36)\n\tat com.amazonaws.profile.path.AwsProfileFileLocationProviderChain.getLocation(AwsProfileFileLocationProviderChain.java:41)\n\tat com.amazonaws.auth.profile.internal.BasicProfileConfigFileLoader.getProfilesConfigFile(BasicProfileConfigFileLoader.java:69)\n\tat com.amazonaws.auth.profile.internal.BasicProfileConfigFileLoader.getProfile(BasicProfileConfigFileLoader.java:55)\n\tat com.amazonaws.retry.internal.RetryModeResolver.profile(RetryModeResolver.java:92)\n\tat com.amazonaws.retry.internal.RetryModeResolver.resolveRetryMode(RetryModeResolver.java:83)\n\tat com.amazonaws.retry.internal.RetryModeResolver.<init>(RetryModeResolver.java:46)\n\tat com.amazonaws.retry.RetryPolicy.<clinit>(RetryPolicy.java:35)\n\tat com.amazonaws.retry.PredefinedRetryPolicies.<clinit>(PredefinedRetryPolicies.java:30)\n\tat com.amazonaws.ClientConfiguration.<clinit>(ClientConfiguration.java:89)\n\tat java.base/java.lang.Class.forName0(Native Method)\n\tat java.base/java.lang.Class.forName(Class.java:383)\n\tat java.base/java.lang.Class.forName(Class.java:376)\n\tat org.elasticsearch.repositories.s3.S3RepositoryPlugin.lambda$static$0(S3RepositoryPlugin.java:60)\n\tat java.base/java.security.AccessController.doPrivileged(AccessController.java:318)\n\tat org.elasticsearch.repositories.s3.S3RepositoryPlugin.<clinit>(S3RepositoryPlugin.java:54)\n\tat java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method)\n\tat java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1160)\n\tat java.base/jdk.internal.reflect.MethodHandleAccessorFactory.ensureClassInitialized(MethodHandleAccessorFactory.java:300)\n\tat java.base/jdk.internal.reflect.MethodHandleAccessorFactory.newConstructorAccessor(MethodHandleAccessorFactory.java:103)\n\tat java.base/jdk.internal.reflect.ReflectionFactory.newConstructorAccessor(ReflectionFactory.java:236)\n\tat java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:546)\n\tat java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:496)\n\tat java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:483)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.plugins.PluginsService.loadPlugin(PluginsService.java:545)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.plugins.PluginsService.loadBundle(PluginsService.java:463)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.plugins.PluginsService.loadBundles(PluginsService.java:274)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.plugins.PluginsService.<init>(PluginsService.java:150)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.plugins.PluginsService.lambda$getPluginsServiceCtor$14(PluginsService.java:579)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.node.Node.<init>(Node.java:399)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.node.Node.<init>(Node.java:311)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.bootstrap.Elasticsearch$2.<init>(Elasticsearch.java:214)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.bootstrap.Elasticsearch.initPhase3(Elasticsearch.java:214)\n\tat org.elasticsearch.server@8.4.3/org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:67)\n"} 15:20:27.486 PostgreSQL:syncing data to disk ... ok 15:20:27.486 PostgreSQL:Success. You can now start the database server using: 15:20:27.486 PostgreSQL: pg_ctl -D /var/lib/postgresql/data -l logfile start 15:20:27.486 PostgreSQL:initdb: warning: enabling "trust" authentication for local connections 15:20:27.486 PostgreSQL:You can change this by editing pg_hba.conf or using the option -A, or 15:20:27.486 PostgreSQL:--auth-local and --auth-host, the next time you run initdb. 15:20:27.521 PostgreSQL:waiting for server to start....2022-10-29 15:20:27.521 UTC [47] LOG: starting PostgreSQL 13.1 (Debian 13.1-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit 15:20:27.523 PostgreSQL:2022-10-29 15:20:27.523 UTC [47] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" 15:20:27.531 PostgreSQL:2022-10-29 15:20:27.530 UTC [48] LOG: database system was shut down at 2022-10-29 15:20:23 UTC 15:20:27.535 PostgreSQL:2022-10-29 15:20:27.535 UTC [47] LOG: database system is ready to accept connections 15:20:27.600 PostgreSQL: done 15:20:27.600 PostgreSQL:server started 15:20:28.402 PostgreSQL:CREATE DATABASE 15:20:28.403 PostgreSQL:/usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/* 15:20:28.403 PostgreSQL:waiting for server to shut down....2022-10-29 15:20:28.403 UTC [47] LOG: received fast shutdown request 15:20:28.406 PostgreSQL:2022-10-29 15:20:28.405 UTC [47] LOG: aborting any active transactions 15:20:28.407 PostgreSQL:2022-10-29 15:20:28.406 UTC [47] LOG: background worker "logical replication launcher" (PID 54) exited with exit code 1 15:20:28.407 PostgreSQL:2022-10-29 15:20:28.407 UTC [49] LOG: shutting down 15:20:28.426 PostgreSQL:2022-10-29 15:20:28.426 UTC [47] LOG: database system is shut down 15:20:28.502 PostgreSQL: done 15:20:28.502 PostgreSQL:server stopped 15:20:28.503 PostgreSQL:PostgreSQL init process complete; ready for start up. 15:20:28.523 PostgreSQL:2022-10-29 15:20:28.523 UTC [1] LOG: starting PostgreSQL 13.1 (Debian 13.1-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit 15:20:28.524 PostgreSQL:2022-10-29 15:20:28.523 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432 15:20:28.524 PostgreSQL:2022-10-29 15:20:28.523 UTC [1] LOG: listening on IPv6 address "::", port 5432 15:20:28.528 PostgreSQL:2022-10-29 15:20:28.528 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" 15:20:28.533 PostgreSQL:2022-10-29 15:20:28.533 UTC [75] LOG: database system was shut down at 2022-10-29 15:20:28 UTC 15:20:28.539 PostgreSQL:2022-10-29 15:20:28.539 UTC [1] LOG: database system is ready to accept connections [INFO] DOCKER> Pattern '(?s)ready to accept connections.*ready to accept connections' matched for container 47af9384c85e [INFO] DOCKER> [postgres:13.1] "postgres": Waited on log out '(?s)ready to accept connections.*ready to accept connections' 6018 ms 15:20:35.679 Elasticsearch:{"@timestamp":"2022-10-29T15:20:35.678Z", "log.level": "WARN", "message":"max file descriptors [1024] for elasticsearch process is too low, increase to at least [65535]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.bootstrap.BootstrapChecks","elasticsearch.node.name":"7adecad9203b","elasticsearch.cluster.name":"docker-cluster"} 15:20:35.679 Elasticsearch:{"@timestamp":"2022-10-29T15:20:35.679Z", "log.level": "WARN", "message":"max virtual memory areas vm.max_map_count [65530] is too low, increase to at least [262144]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.bootstrap.BootstrapChecks","elasticsearch.node.name":"7adecad9203b","elasticsearch.cluster.name":"docker-cluster"} [INFO] DOCKER> [elastic/elasticsearch:8.4.3] "elasticsearch": Waited on url http://localhost:9200 13719 ms [INFO] [INFO] --- maven-failsafe-plugin:3.0.0-M7:integration-test (it-lucene) @ hibernate-search-integrationtest-showcase-library --- [INFO] Using configured provider org.apache.maven.surefire.junitcore.JUnitCoreProvider [INFO] [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- Picked up JAVA_TOOL_OPTIONS: -Dmaven.ext.class.path=&quot;/var/lib/jenkins/workspace/hibernate-search_PR-3289(a)tmp/withMaven7700036c/pipeline-maven-spy.jar&quot; -Dorg.jenkinsci.plugins.pipeline.maven.reportsFolder="/var/lib/jenkins/workspace/hibernate-search_PR-3289@tmp/withMaven7700036c" [INFO] Running org.hibernate.search.integrationtest.showcase.library.Java17IT [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.826 s - in org.hibernate.search.integrationtest.showcase.library.Java17IT [INFO] Running org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseMassIndexingIT [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.517 s - in org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseMassIndexingIT [INFO] Running org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseSearchIT [INFO] Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.775 s - in org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseSearchIT [INFO] [INFO] Results: [INFO] [INFO] Tests run: 15, Failures: 0, Errors: 0, Skipped: 0 [INFO] [INFO] [INFO] --- maven-failsafe-plugin:3.0.0-M7:integration-test (it-elasticsearch) @ hibernate-search-integrationtest-showcase-library --- [INFO] Using configured provider org.apache.maven.surefire.junitcore.JUnitCoreProvider [INFO] [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- Picked up JAVA_TOOL_OPTIONS: -Dmaven.ext.class.path=&quot;/var/lib/jenkins/workspace/hibernate-search_PR-3289(a)tmp/withMaven7700036c/pipeline-maven-spy.jar&quot; -Dorg.jenkinsci.plugins.pipeline.maven.reportsFolder="/var/lib/jenkins/workspace/hibernate-search_PR-3289@tmp/withMaven7700036c" [INFO] Running org.hibernate.search.integrationtest.showcase.library.Java17IT [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.147 s - in org.hibernate.search.integrationtest.showcase.library.Java17IT [INFO] Running org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseMassIndexingIT [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.379 s - in org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseMassIndexingIT [INFO] Running org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseSearchIT [INFO] Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.082 s - in org.hibernate.search.integrationtest.showcase.library.LibraryShowcaseSearchIT [INFO] [INFO] Results: [INFO] [INFO] Tests run: 15, Failures: 0, Errors: 0, Skipped: 0 [INFO] [INFO] [INFO] --- docker-maven-plugin:0.40.2:stop (docker-stop) @ hibernate-search-integrationtest-showcase-library --- 15:21:07.142 PostgreSQL:2022-10-29 15:21:07.141 UTC [1] LOG: received fast shutdown request 15:21:07.145 PostgreSQL:2022-10-29 15:21:07.144 UTC [1] LOG: aborting any active transactions 15:21:07.145 PostgreSQL:2022-10-29 15:21:07.145 UTC [1] LOG: background worker "logical replication launcher" (PID 81) exited with exit code 1 15:21:07.145 PostgreSQL:2022-10-29 15:21:07.145 UTC [76] LOG: shutting down 15:21:07.351 PostgreSQL:2022-10-29 15:21:07.351 UTC [1] LOG: database system is shut down [INFO] DOCKER> [postgres:13.1] "postgres": Stop and removed container 47af9384c85e after 0 ms [INFO] DOCKER> [elastic/elasticsearch:8.4.3] "elasticsearch": Stop and removed container 7adecad9203b after 0 ms [INFO] [INFO] --- maven-checkstyle-plugin:3.2.0:check (check-style) @ hibernate-search-integrationtest-showcase-library --- [INFO] You have 0 Checkstyle violations. [INFO] [INFO] --- maven-checkstyle-plugin:3.2.0:check (check-style-noparameters) @ hibernate-search-integrationtest-showcase-library --- [INFO] [INFO] --- maven-failsafe-plugin:3.0.0-M7:verify (it-verify) @ hibernate-search-integrationtest-showcase-library --- [INFO] [INFO] --- maven-install-plugin:3.0.1:install (default-install) @ hibernate-search-integrationtest-showcase-library --- [INFO] Installing /mnt/jenkins-workdir/workspace/hibernate-search_PR-3289/integrationtest/showcase/library/pom.xml to /var/lib/jenkins/workspace/hibernate-search_PR-3289@tmp/maven-repository/org/hibernate/search/hibernate-search-integrationtest-showcase-library/6.2.0-SNAPSHOT/hibernate-search-integrationtest-showcase-library-6.2.0-SNAPSHOT.pom [INFO] Installing /mnt/jenkins-workdir/workspace/hibernate-search_PR-3289/integrationtest/showcase/library/target/hibernate-search-integrationtest-showcase-library-6.2.0-SNAPSHOT.jar to /var/lib/jenkins/workspace/hibernate-search_PR-3289@tmp/maven-repository/org/hibernate/search/hibernate-search-integrationtest-showcase-library/6.2.0-SNAPSHOT/hibernate-search-integrationtest-showcase-library-6.2.0-SNAPSHOT.jar [INFO] ------------------------------------------------------------------------ [INFO] Reactor Summary for Hibernate Search ITs - ORM 6.2.0-SNAPSHOT: [INFO] [INFO] Hibernate Search ITs - ORM ......................... FAILURE [ 37.614 s] [INFO] Hibernate Search ITs - ORM - Envers ................ SUCCESS [ 13.521 s] [INFO] Hibernate Search ITs - ORM - Real backend .......... SUCCESS [ 49.375 s] [INFO] Hibernate Search ITs - ORM - Coordination - Outbox Polling SKIPPED [INFO] Hibernate Search ITs - Showcase - Library .......... SUCCESS [ 55.447 s] [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 02:36 min [INFO] Finished at: 2022-10-29T15:21:10Z [INFO] ------------------------------------------------------------------------ [INFO] [jenkins-event-spy] Generated /mnt/jenkins-workdir/workspace/hibernate-search_PR-3289@tmp/withMaven7700036c/maven-spy-20221029-151834-36212173791743644038646.log [ERROR] Failed to execute goal io.fabric8:docker-maven-plugin:0.40.2:start (docker-start) on project hibernate-search-integrationtest-mapper-orm: I/O Error: [postgres:13.1] "postgres": Timeout after 10035 ms while waiting on log out '(?s)ready to accept connections.*ready to accept connections' -> [Help 1] [ERROR] [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch. [ERROR] Re-run Maven using the -X switch to enable full debug logging. [ERROR] [ERROR] For more information about the errors and possible solutions, please read the following articles: [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException script returned exit code 1 ( https://hibernate.atlassian.net/browse/HSEARCH-4722#add-comment?atlOrigin... ) Add Comment ( https://hibernate.atlassian.net/browse/HSEARCH-4722#add-comment?atlOrigin... ) Get Jira notifications on your phone! Download the Jira Cloud app for Android ( https://play.google.com/store/apps/details?id=com.atlassian.android.jira.... ) or iOS ( https://itunes.apple.com/app/apple-store/id1006972087?pt=696495&ct=Em... ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100209- sha1:5956172 )