[4.6] OCI - Keycloak bootup fails

[ddevadat]

hi,
We are not able to start keycloak service. It keeps getting killed

06:25:26,582 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 63) WFLYCLINF0002: Started loginFailures cache from keycloak container
06:25:26,603 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 73) WFLYCLINF0002: Started work cache from keycloak container
06:25:26,612 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 66) WFLYCLINF0002: Started clientSessions cache from keycloak container
06:25:26,636 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 74) WFLYCLINF0002: Started client-mappings cache from ejb container
06:25:26,911 WARN [org.jboss.as.server.deployment] (MSC service thread 1-8) WFLYSRV0273: Excluded subsystem webservices via jboss-deployment-structure.xml does not exist.
06:25:28,297 INFO [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0001: Loading config from standalone.xml or domain.xml
06:25:28,751 WARN [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0047: get-required-action-link (org.sunbird.keycloak.rest.RequiredActionLinkProviderFactory) is implementing the internal SPI realm-restapi-extension. This SPI is internal and may change without notice
06:25:28,786 WARN [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0047: smsCode (org.sunbird.keycloak.resetcredential.sms.KeycloakSmsAuthenticatorCredentialProviderFactory) is implementing the internal SPI credential. This SPI is internal and may change without notice
06:25:28,857 WARN [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0047: sms-authentication (org.sunbird.keycloak.resetcredential.sms.KeycloakSmsAuthenticatorFactory) is implementing the internal SPI authenticator. This SPI is internal and may change without notice
06:25:28,858 WARN [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0047: auth-phone-password-form (org.sunbird.keycloak.login.phone.PhonePasswordFormFactory) is implementing the internal SPI authenticator. This SPI is internal and may change without notice
06:25:28,858 WARN [org.keycloak.services] (ServerService Thread Pool -- 66) KC-SERVICES0047: spi-reset-credentials-choose-user (org.sunbird.keycloak.resetcredential.chooseuser.ResetCredentialChooseUserAuthenticatorFactory) is implementing the internal SPI authenticator. This SPI is internal and may change without notice
06:25:28,958 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 66) WFLYCLINF0002: Started realmRevisions cache from keycloak container
06:25:28,962 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 66) WFLYCLINF0002: Started userRevisions cache from keycloak container
06:25:28,971 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 66) WFLYCLINF0002: Started authorizationRevisions cache from keycloak container
06:25:28,973 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (ServerService Thread Pool -- 66) Node name: dp, Site name: null
Killed

Tried the below command but still the same result
keycloakuser=keycloak
keycloakpath=/opt/keycloak/bin
LOGOUT=/var/log/keycloak.out.log
LOGERR=/var/log/keycloak.err.log
su - $keycloakuser -c "cd $keycloakpath && (nohup sh ./standalone.sh -b=10.0.1.76 -bprivate=10.0.1.76 --server-config standalone-ha.xml 0<&- 1>>$LOGOUT 2>>$LOGERR &)"

[beepdot]

Your system must be out of memory and kernel might be killing the process. Check syslogs for more details. Please adjust the java heap memory for keycloak accordingly.

[ddevadat]

memory on the dp vm was at 100%.
i stopped logstash process for the moment and started keycloak manually.

how to triage the memory issue, is there any potential memory leak

[ddevadat]

top memory consuming process are as below..

ubuntu@dp:~$ ps -eo pid,ppid,%mem,%cpu,cmd --sort=-%mem | head
  PID  PPID %MEM %CPU CMD
21538     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
 6430     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
27602     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
21172     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
 7137     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
24382     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
23276     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
11793     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}
 2505     1  1.0  0.0 java -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms250m -Xmx5120m -XX:+UseStringDeduplication -cp /mount/data/analytics/spark-2.4.4-bin-hadoop2.7/jars/*:/mount/data/analytics/models-2.0/*:/mount/data/analytics/models-2.0/data-products-1.0/lib/* -Dconfig.file=/mount/data/analytics/models-2.0/dev.conf org.ekstep.analytics.job.JobManager --config {"jobsCount":3,"topic":"dev.analytics.job_queue","bootStrapServer":"10.0.1.83:9092","zookeeperConnect":"10.0.1.83:2181","consumerGroup":"jobmanager","slackChannel":"#test_channel","slackUserName":"JobManager","tempBucket":"telemetry-data-store","tempFolder":"transient-data"}

[beepdot]

The output is not readable. Please use formatting using back ticks or triple back ticks. You can kill all the processes having jobmanager in the ps output. That should solve the memory issues. You can also set a lower Xmx for these jobs if you see them using too much memory frequently. Please also read on vm overcommit memory which might save a few crashes.

[ddevadat]

updated the format.
what are these process...what will be the impact of stopping them.
Also there are cronjobs set related to job manager

#Ansible: dev-submit-all-jobs
35 2 * * * /bin/bash -lc "ruby /mount/data/analytics/scripts/submit-all-jobs.rb"
#Ansible: dev-job-manager
30 2 * * * /mount/data/analytics/scripts/start-jobmanager.sh
#Ansible: dev-course-batch-status-updater
*/60 * * * * /mount/data/analytics/scripts/run-job.sh course-batch-status-updater
#Ansible: dev-admin-user-reports-3AMIST
30 21 * * * /mount/data/analytics/scripts/run-job.sh admin-user-reports
#Ansible: dev-admin-user-reports-2PMIST
30 8 * * * /mount/data/analytics/scripts/run-job.sh admin-user-reports
#Ansible: dev-admin-geo-reports-4AMIST
30 22 * * * /mount/data/analytics/scripts/run-job.sh admin-geo-reports
#Ansible: dev-admin-geo-reports-3PMIST
30 9 * * * /mount/data/analytics/scripts/run-job.sh admin-geo-reports
#Ansible: dev-assessment-aggregator-report
35 18 * * * /bin/bash /mount/data/analytics/adhoc-scripts/run_exporter.sh > /home/analytics/output.log
#Ansible: dev-etb-metrics-weekly
30 23 * * 1 /mount/data/analytics/scripts/run-job.sh etb-metrics
#Ansible: dev-progress-exhaust
0 08 * * * /mount/data/analytics/scripts/run-job.sh progress-exhaust
#Ansible: dev-response-exhaust
0 09 * * * /mount/data/analytics/scripts/run-job.sh response-exhaust
#Ansible: dev-cassandra-migration
15 19 * * * /mount/data/analytics/scripts/run-job.sh cassandra-migration
#Ansible: dev-userinfo-exhaust
0 10 * * * /mount/data/analytics/scripts/run-job.sh userinfo-exhaust
#Ansible: dev-collection-summary

Do we need to disable the crons too

[beepdot]

No need to disable the cronjobs. These jobs are used for reporting functionality. Usually the jobs don't continue to run after the task is complete. These look like orphan processes. Sometimes we have seen this happen. Maybe if it occurs again, there might be some information in the job logs.

[ddevadat]

killed all the job manager process..now the memory util has come down