[JIRA] (HSEARCH-4910) Investigate slow startup of Elasticsearch container in integration tests
by Yoann Rodière (JIRA)
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(a)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(a)8.9.0/org.elasticsearch.node.Node.<init>(Node.java:427)\n\tat org.elasticsearch.server(a)8.9.0/org.elasticsearch.node.Node.<init>(Node.java:334)\n\tat org.elasticsearch.server(a)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=EmailN... ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100233- sha1:06f5c37 )
11 months, 1 week