Yoann Rodière ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) *created* an issue Hibernate Search ( https://hibernate.atlassian.net/browse/HSEARCH?atlOrigin=eyJpIjoiYWU1YmJj... ) / Task ( https://hibernate.atlassian.net/browse/HSEARCH-4910?atlOrigin=eyJpIjoiYWU... ) HSEARCH-4910 ( https://hibernate.atlassian.net/browse/HSEARCH-4910?atlOrigin=eyJpIjoiYWU... ) Investigate slow startup of Elasticsearch container in integration tests ( https://hibernate.atlassian.net/browse/HSEARCH-4910?atlOrigin=eyJpIjoiYWU... ) Issue Type: Task Assignee: Unassigned Components: build Created: 04/Aug/2023 05:54 AM Fix Versions: 7.0-backlog Priority: Major Reporter: Yoann Rodière ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) I just stumbled upon this build ( https://ci.hibernate.org/blue/organizations/jenkins/hibernate-search/deta... ) , where CI failed to start an Elasticsearch containers. See below for the logs. It’s apparently a timeout, and it doesn’t happen often. I think Elasticsearch is just slow to start on CI. A quick google search didn’t turn anything useful, so we’ll need to investigate a bit more. I can just say that the bit about Unable to load config file null doesn’t seem to be critical (even if it doesn’t seem normal), as the boot continues afterwards. Also, if I try to start the container locally, there’s a lot of templates being loaded on startup over 1-2s, so I suppose it could be 5-10s on a slower machine. We might want to disable a few things to get back to a decently fast startup. [INFO] --- docker-maven-plugin:0.40.2:start (docker-start) @ hibernate-search-integrationtest-showcase-library --- [INFO] DOCKER> [opensearchproject/opensearch:8.9.0] "opensearch": Skipped running [INFO] DOCKER> [postgres:15.1] "postgres": Skipped running [INFO] DOCKER> [mariadb:10.10.2] "mariadb": Skipped running [INFO] DOCKER> [mysql:8.0.31] "mysql": Skipped running [INFO] DOCKER> [ibmcom/db2:11.5.8.0] "db2": Skipped running [INFO] DOCKER> [mcr.microsoft.com/mssql/server:2019-CU18-ubuntu-20.04] "mssql": Skipped running [INFO] DOCKER> [cockroachdb/cockroach:v23.1.4] "cockroachdb": Skipped running [INFO] DOCKER> [elastic/elasticsearch:8.9.0] "elasticsearch": Start container 2680352bf619 [INFO] DOCKER> [gvenzl/oracle-xe:21.3.0-slim-faststart] "oracle": Start container ad775fd27dee [INFO] DOCKER> [elastic/elasticsearch:8.9.0] "elasticsearch": Waiting on url http://localhost:9200 with method GET for status 200. 08:52:48.461 Oracle Database:CONTAINER: starting up... 08:52:48.539 Oracle Database:CONTAINER: first database startup, initializing... 08:52:48.563 Oracle Database:CONTAINER: starting up Oracle Database... 08:52:48.570 Oracle Database:LSNRCTL for Linux: Version 21.0.0.0.0 - Production on 04-AUG-2023 08:52:48 08:52:48.570 Oracle Database:Copyright (c) 1991, 2021, Oracle. All rights reserved. 08:52:48.572 Oracle Database:Starting /opt/oracle/product/21c/dbhomeXE/bin/tnslsnr: please wait... 08:52:48.949 Oracle Database:TNSLSNR for Linux: Version 21.0.0.0.0 - Production 08:52:48.949 Oracle Database:System parameter file is /opt/oracle/homes/OraDBHome21cXE/network/admin/listener.ora 08:52:48.949 Oracle Database:Log messages written to /opt/oracle/diag/tnslsnr/ad775fd27dee/listener/alert/log.xml 08:52:48.949 Oracle Database:Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_XE))) 08:52:48.949 Oracle Database:Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521))) 08:52:48.949 Oracle Database:Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC_FOR_XE))) 08:52:48.950 Oracle Database:STATUS of the LISTENER 08:52:48.950 Oracle Database:------------------------ 08:52:48.950 Oracle Database:Alias LISTENER 08:52:48.950 Oracle Database:Version TNSLSNR for Linux: Version 21.0.0.0.0 - Production 08:52:48.950 Oracle Database:Start Date 04-AUG-2023 08:52:48 08:52:48.950 Oracle Database:Uptime 0 days 0 hr. 0 min. 0 sec 08:52:48.950 Oracle Database:Trace Level off 08:52:48.950 Oracle Database:Security ON: Local OS Authentication 08:52:48.950 Oracle Database:SNMP OFF 08:52:48.950 Oracle Database:Default Service XE 08:52:48.950 Oracle Database:Listener Parameter File /opt/oracle/homes/OraDBHome21cXE/network/admin/listener.ora 08:52:48.950 Oracle Database:Listener Log File /opt/oracle/diag/tnslsnr/ad775fd27dee/listener/alert/log.xml 08:52:48.950 Oracle Database:Listening Endpoints Summary... 08:52:48.950 Oracle Database: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_XE))) 08:52:48.950 Oracle Database: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521))) 08:52:48.950 Oracle Database:The listener supports no services 08:52:48.950 Oracle Database:The command completed successfully 08:52:54.002 Elasticsearch:{"@timestamp":"2023-08-04T08:52:53.993Z", "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":"2680352bf619","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:488)\n\tat java.base/java.security.AccessController.checkPermission(AccessController.java:1071)\n\tat java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:411)\n\tat java.base/java.lang.SecurityManager.checkRead(SecurityManager.java:742)\n\tat java.base/java.io.File.exists(File.java:831)\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:103)\n\tat com.amazonaws.retry.internal.RetryModeResolver.resolveRetryMode(RetryModeResolver.java:89)\n\tat com.amazonaws.retry.internal.RetryModeResolver.<init>(RetryModeResolver.java:55)\n\tat com.amazonaws.retry.internal.RetryModeResolver.<init>(RetryModeResolver.java:48)\n\tat com.amazonaws.retry.RetryPolicy.<clinit>(RetryPolicy.java:35)\n\tat com.amazonaws.retry.PredefinedRetryPolicies.<clinit>(PredefinedRetryPolicies.java:32)\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:391)\n\tat java.base/java.lang.Class.forName(Class.java:382)\n\tat org.elasticsearch.repositories.s3.S3RepositoryPlugin.lambda$static$0(S3RepositoryPlugin.java:61)\n\tat java.base/java.security.AccessController.doPrivileged(AccessController.java:319)\n\tat org.elasticsearch.repositories.s3.S3RepositoryPlugin.<clinit>(S3RepositoryPlugin.java:55)\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:200)\n\tat java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:547)\n\tat java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:497)\n\tat java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:484)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.plugins.PluginsService.loadPlugin(PluginsService.java:668)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.plugins.PluginsService.loadBundle(PluginsService.java:518)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.plugins.PluginsService.loadBundles(PluginsService.java:303)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.plugins.PluginsService.<init>(PluginsService.java:173)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.plugins.PluginsService.lambda$getPluginsServiceCtor$16(PluginsService.java:702)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.node.Node.<init>(Node.java:427)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.node.Node.<init>(Node.java:334)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.bootstrap.Elasticsearch$2.<init>(Elasticsearch.java:234)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.bootstrap.Elasticsearch.initPhase3(Elasticsearch.java:234)\n\tat org.elasticsearch.server@8.9.0/org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:72)\n"} 08:52:59.207 Oracle Database:ORACLE instance started. 08:52:59.226 Oracle Database:Total System Global Area 1241512312 bytes 08:52:59.226 Oracle Database:Fixed Size 9685368 bytes 08:52:59.226 Oracle Database:Variable Size 603979776 bytes 08:52:59.226 Oracle Database:Database Buffers 620756992 bytes 08:52:59.226 Oracle Database:Redo Buffers 7090176 bytes 08:52:59.658 Oracle Database:Database mounted. 08:53:05.971 Oracle Database:Database opened. 08:53:06.358 Oracle Database:CONTAINER: Resetting SYS and SYSTEM passwords. 08:53:06.709 Oracle Database:User altered. 08:53:06.813 Oracle Database:User altered. 08:53:06.841 Oracle Database:######################### 08:53:06.841 Oracle Database:DATABASE IS READY TO USE! 08:53:06.841 Oracle Database:######################### 08:53:06.841 Oracle Database:################################################################## 08:53:06.841 Oracle Database:CONTAINER: The following output is now from the alert_XE.log file: 08:53:06.842 Oracle Database:################################################################## 08:53:06.846 Oracle Database:XEPDB1(3):SUPLOG: Set PDB SUPLOG SGA at PDB OPEN, old 0x18, new 0x0 (no suplog) 08:53:06.846 Oracle Database:XEPDB1(3):Opening pdb with Resource Manager plan: DEFAULT_PLAN 08:53:06.846 Oracle Database:2023-08-04T08:53:05.265441+00:00 08:53:06.846 Oracle Database:Resize operation completed for file# 201, fname /opt/oracle/oradata/XE/temp01.dbf, old size 2048K, new size 12288K 08:53:06.846 Oracle Database:2023-08-04T08:53:05.549762+00:00 08:53:06.846 Oracle Database:Pluggable database XEPDB1 opened read write 08:53:06.846 Oracle Database:Starting background process CJQ0 08:53:06.846 Oracle Database:2023-08-04T08:53:05.969054+00:00 08:53:06.847 Oracle Database:CJQ0 started with pid=61, OS id=207 08:53:06.847 Oracle Database:Completed: ALTER DATABASE OPEN [INFO] DOCKER> Pattern 'DATABASE IS READY TO USE!' matched for container ad775fd27dee [INFO] DOCKER> [gvenzl/oracle-xe:21.3.0-slim-faststart] "oracle": Waited on log out 'DATABASE IS READY TO USE!' 19076 ms [ERROR] DOCKER> [elastic/elasticsearch:8.9.0] "elasticsearch": Timeout after 20139 ms while waiting on url http://localhost:9200 [ERROR] DOCKER> Error occurred during container startup, shutting down... 08:53:08.499 Oracle Database:CONTAINER: shutdown request received. 08:53:08.735 Elasticsearch:{"@timestamp":"2023-08-04T08:53:08.735Z", "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":"2680352bf619","elasticsearch.cluster.name":"docker-cluster"} 08:53:08.499 Oracle Database:CONTAINER: shutting down database! 08:53:08.735 Elasticsearch:{"@timestamp":"2023-08-04T08:53:08.735Z", "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":"2680352bf619","elasticsearch.cluster.name":"docker-cluster"} 08:53:08.506 Oracle Database:LSNRCTL for Linux: Version 21.0.0.0.0 - Production on 04-AUG-2023 08:53:08 08:53:08.506 Oracle Database:Copyright (c) 1991, 2021, Oracle. All rights reserved. 08:53:08.506 Oracle Database:Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC_FOR_XE))) 08:53:08.510 Oracle Database:The command completed successfully 08:53:08.549 Oracle Database:2023-08-04T08:53:08.549166+00:00 08:53:08.549 Oracle Database:Shutting down ORACLE instance (immediate) (OS id: 230) 08:53:08.549 Oracle Database:Shutdown is initiated by sqlplus@ad775fd27dee (TNS V1-V3). 08:53:08.560 Oracle Database:Stopping background process SMCO 08:53:08.623 Oracle Database:Shutting down instance: further logons disabled 08:53:09.306 Oracle Database:Stopping background process MMNL 08:53:09.357 Oracle Database:Stopping background process MMON 08:53:09.407 Oracle Database:alter pluggable database all close immediate 08:53:09.409 Oracle Database:2023-08-04T08:53:09.409534+00:00 08:53:09.409 Oracle Database:XEPDB1(3):Pluggable database XEPDB1 closing 08:53:09.414 Oracle Database:XEPDB1(3):JIT: pid 230 requesting stop 08:53:09.419 Oracle Database:2023-08-04T08:53:09.418890+00:00 08:53:09.419 Oracle Database:XEPDB1(3):Stopped service xepdb1 08:53:09.477 Oracle Database:XEPDB1(3):Closing sequence subsystem (4259409943). 08:53:09.491 Oracle Database:XEPDB1(3):Buffer Cache flush deferred for PDB 3 08:53:09.792 Oracle Database:2023-08-04T08:53:09.792656+00:00 08:53:09.793 Oracle Database:Pluggable database XEPDB1 closed 08:53:09.793 Oracle Database:Completed: alter pluggable database all close immediate 08:53:09.793 Oracle Database:PDB$SEED(2):Pluggable database PDB$SEED closing 08:53:09.794 Oracle Database:PDB$SEED(2):JIT: pid 230 requesting stop 08:53:09.797 Oracle Database:PDB$SEED(2):Buffer Cache flush deferred for PDB 2 08:53:09.801 Oracle Database:License high water mark = 2 08:53:09.804 Oracle Database:Dispatchers and shared servers shutdown 08:53:09.804 Oracle Database:Data Pump shutdown in progress 08:53:09.815 Oracle Database:2023-08-04T08:53:09.812049+00:00 08:53:09.815 Oracle Database:Process termination requested for pid 222 [source = rdbms], [info = 2] [request issued by pid: 230, uid: 54321] 08:53:09.827 Oracle Database:ALTER DATABASE CLOSE NORMAL 08:53:09.858 Oracle Database:2023-08-04T08:53:09.857774+00:00 08:53:09.858 Oracle Database:Stopping Emon pool 08:53:09.858 Oracle Database:Stopping background process AQPC 08:53:09.909 Oracle Database:alter pluggable database all close immediate 08:53:09.909 Oracle Database:Completed: alter pluggable database all close immediate 08:53:09.909 Oracle Database:alter pluggable database all close immediate 08:53:09.909 Oracle Database:Completed: alter pluggable database all close immediate 08:53:09.912 Oracle Database:IM on ADG: Start of Empty Journal 08:53:09.913 Oracle Database:IM on ADG: End of Empty Journal 08:53:09.913 Oracle Database:Stopping background process RCBG 08:53:09.964 Oracle Database:Stopping Emon pool 08:53:09.964 Oracle Database:Shutting down blockchain Apply - must do a restart blockchain after this. 08:53:09.964 Oracle Database:Closing sequence subsystem (4259896644). 08:53:10.974 Oracle Database:2023-08-04T08:53:10.973845+00:00 08:53:10.974 Oracle Database:Stopping change tracking 08:53:11.306 Oracle Database:2023-08-04T08:53:11.306242+00:00 08:53:11.306 Oracle Database:Thread 1 closed at log sequence 19 08:53:11.306 Oracle Database:Successful close of redo thread 1 08:53:11.312 Oracle Database:2023-08-04T08:53:11.312008+00:00 08:53:11.312 Oracle Database:Entire Buffer Cache invalidation started 08:53:11.317 Oracle Database:Entire Buffer Cache invalidation completed 08:53:11.350 Oracle Database:Completed: ALTER DATABASE CLOSE NORMAL 08:53:11.350 Oracle Database:Database closed. 08:53:11.351 Oracle Database:ALTER DATABASE DISMOUNT 08:53:11.393 Oracle Database:Completed: ALTER DATABASE DISMOUNT 08:53:11.393 Oracle Database:Database dismounted. 08:53:11.891 Oracle Database:JIT: pid 230 requesting stop 08:53:11.949 Oracle Database:JIT: pid 230 requesting stop 08:53:11.953 Oracle Database:2023-08-04T08:53:11.949563+00:00 08:53:11.953 Oracle Database:Stopping background process VKTM 08:53:12.415 Oracle Database:2023-08-04T08:53:12.415224+00:00 08:53:12.415 Oracle Database:Instance shutdown complete (OS id: 230) 08:53:12.415 Oracle Database:ORACLE instance shut down. 08:53:12.479 Oracle Database:CONTAINER: stopping container. [INFO] DOCKER> [gvenzl/oracle-xe:21.3.0-slim-faststart] "oracle": Stop and removed container ad775fd27dee after 0 ms [INFO] DOCKER> [elastic/elasticsearch:8.9.0] "elasticsearch": Stop and removed container 2680352bf619 after 0 ms [ERROR] DOCKER> I/O Error [[elastic/elasticsearch:8.9.0] "elasticsearch": Timeout after 20139 ms while waiting on url http://localhost:9200] ( https://hibernate.atlassian.net/browse/HSEARCH-4910#add-comment?atlOrigin... ) Add Comment ( https://hibernate.atlassian.net/browse/HSEARCH-4910#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#100233- sha1:06f5c37 )