SAP Hybris si spegne da solo

Sono nuovo in un progetto sap hybris e da qualche settimana abbiamo il problema che la nostra hybris si spegne da sola in produzione.

In produzione abbiamo un server backend per backoffice, cronjobs, imports ecc. e abbiamo un server frontend per ... bene il frontend. Entrambi sono applicazioni complete hybris. Anche il nostro solr è su una maschine dedicata.

Il server frontend funziona bene per tutto il tempo. Solo il nostro server backened si spegne senza nulla di buono motivo.

Il server backend ha il seguente aspetto:

  • Java 8
  • Hybris 6.7
  • 36 GB DI RAM
  • java.mem è 28GB
  • Ubuntu 16.04.2

Questo è ciò che dice l'output della console:

INFO   | jvm 1    | main    | 2020/08/27 09:04:50.411 | INFO  [cluster-ClusterId{value='5f462504979dc05c35c5afff', description='null'}-111.22.12.16:27017] [connection] Opened connection [connectionId{localValue:33, serverValue:8662}] to 111.22.12.16:27017
INFO   | jvm 1    | main    | 2020/08/27 09:04:50.513 | INFO  [cluster-ClusterId{value='5f462504979dc05c35c5afff', description='null'}-111.22.12.16:27017] [cluster] Monitor thread successfully connected to server with description ServerDescription{address=111.22.12.16:27017, type=STANDALONE, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 4, 10]}, minWireVersion=0, maxWireVersion=5, maxDocumentSize=16777216, roundTripTimeNanos=115245710}
INFO   | jvm 1    | main    | 2020/08/27 09:04:51.014 |
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.224 | INFO  [RemoveFavouriteListEntryWithProductEmptyCronJob::de.hybris.platform.servicelayer.internal.jalo.ScriptingJob] (RemoveFavouriteListEntryWithProductEmptyCronJob) [ScriptingJobPerformable] ### Starting executing script : model://removeFavouriteListEntryWithProductEmptyScript ###
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.224 | INFO  [update-shopOrderIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopOrderIndex-cronJob) [SolrIndexerJob] Started indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.324 | INFO  [RemoveFavouriteListEntryWithProductEmptyCronJob::de.hybris.platform.servicelayer.internal.jalo.ScriptingJob] (RemoveFavouriteListEntryWithProductEmptyCronJob) [ScriptingJobPerformable] de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService$$EnhancerBySpringCGLIB$$d7ee97a3@7ca8259bFavoritesListEntry removed []done
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.324 | INFO  [RemoveFavouriteListEntryWithProductEmptyCronJob::de.hybris.platform.servicelayer.internal.jalo.ScriptingJob] (RemoveFavouriteListEntryWithProductEmptyCronJob) [ScriptingJobPerformable] ### Finished executing script, returned script result = null ###
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.324 | INFO  [update-shopStockItemIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopStockItemIndex-cronJob) [SolrIndexerJob] Started indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.425 | INFO  [update-shopQuoteIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopQuoteIndex-cronJob) [SolrIndexerJob] Started indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:01.826 | INFO  [update-shopQuoteIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopQuoteIndex-cronJob) [SolrIndexerJob] Finished indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:02.127 | INFO  [update-shopStockItemIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopStockItemIndex-cronJob) [SolrIndexerJob] Finished indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:02.429 | INFO  [update-shopOrderIndex-cronJob::de.hybris.platform.servicelayer.internal.jalo.ServicelayerJob] (update-shopOrderIndex-cronJob) [SolrIndexerJob] Finished indexer cronjob.
INFO   | jvm 1    | main    | 2020/08/27 09:05:02.931 |
INFO   | jvm 1    | main    | 2020/08/27 09:05:27.177 | WARN  [jgroups-11,shoplive-broadcast,hybrisnode-1] [NAKACK2] JGRP000011: hybrisnode-1: dropped message batch from non-member hybrisnode-2 (view=[hybrisnode-1|2] (1) [hybrisnode-1])
INFO   | jvm 1    | main    | 2020/08/27 09:05:27.677 |
INFO   | jvm 1    | main    | 2020/08/27 09:05:49.412 | INFO  [solrclient-cleanup-master] [DefaultSolrClientPool] Checking pooled Solr client [config=shopSolrServerConfig]
INFO   | jvm 1    | main    | 2020/08/27 09:05:49.912 |
INFO   | jvm 1    | main    | 2020/08/27 09:06:19.376 | INFO  [cluster-ClusterId{value='5f462504979dc05c35c5afff', description='null'}-111.22.12.16:27017] [connection] Opened connection [connectionId{localValue:34, serverValue:8664}] to 111.22.12.16:27017
INFO   | jvm 1    | main    | 2020/08/27 09:06:19.877 |
INFO   | jvm 1    | main    | 2020/08/27 09:06:29.399 | WARN  [jgroups-11,shoplive-broadcast,hybrisnode-1] [NAKACK2] JGRP000011: hybrisnode-1: dropped message batch from non-member hybrisnode-2 (view=[hybrisnode-1|2] (1) [hybrisnode-1]) (received 3 identical messages from hybrisnode-2 in the last 62247 ms)
INFO   | jvm 1    | main    | 2020/08/27 09:06:29.900 |
INFO   | jvm 1    | main    | 2020/08/27 09:06:49.436 | INFO  [solrclient-cleanup-master] [DefaultSolrClientPool] Checking pooled Solr client [config=shopSolrServerConfig]
INFO   | jvm 1    | main    | 2020/08/27 09:06:49.937 |
INFO   | jvm 1    | main    | 2020/08/27 09:07:49.358 | INFO  [solrclient-cleanup-master] [DefaultSolrClientPool] Checking pooled Solr client [config=shopSolrServerConfig]
INFO   | jvm 1    | main    | 2020/08/27 09:07:49.860 |
INFO   | jvm 1    | main    | 2020/08/27 09:07:51.064 | WARN  [jgroups-25,shoplive-broadcast,hybrisnode-1] [NAKACK2] JGRP000011: hybrisnode-1: dropped message batch from non-member hybrisnode-2 (view=[hybrisnode-1|2] (1) [hybrisnode-1]) (received 2 identical messages from hybrisnode-2 in the last 81647 ms)
INFO   | jvm 1    | main    | 2020/08/27 09:07:51.565 |
INFO   | jvm 1    | main    | 2020/08/27 09:08:20.737 | INFO  [cluster-ClusterId{value='5f462504979dc05c35c5afff', description='null'}-111.22.12.16:27017] [connection] Opened connection [connectionId{localValue:35, serverValue:8665}] to 111.22.12.16:27017
INFO   | jvm 1    | main    | 2020/08/27 09:08:21.238 |
STATUS | wrapper  | main    | 2020/08/27 09:08:35.081 | Pinging the JVM took 2 seconds to respond.
INFO   | jvm 1    | main    | 2020/08/27 09:08:49.617 | INFO  [solrclient-cleanup-master] [DefaultSolrClientPool] Checking pooled Solr client [config=shopSolrServerConfig]
INFO   | jvm 1    | main    | 2020/08/27 09:08:50.118 |
INFO   | jvm 1    | main    | 2020/08/27 09:09:16.324 | INFO  [cluster-ClusterId{value='5f462504979dc05c35c5afff', description='null'}-111.22.12.16:27017] [connection] Opened connection [connectionId{localValue:36, serverValue:8688}] to 111.22.12.16:27017
INFO   | jvm 1    | main    | 2020/08/27 09:09:16.825 |
STATUS | wrapper  | main    | 2020/08/27 09:09:46.483 | Pinging the JVM took 1 seconds to respond.
STATUS | wrapper  | main    | 2020/08/27 09:09:52.562 | JVM received a signal SIGKILL (9).
STATUS | wrapper  | main    | 2020/08/27 09:09:52.563 | JVM process is gone.
ERROR  | wrapper  | main    | 2020/08/27 09:09:52.563 | JVM exited unexpectedly.
STATUS | wrapper  | main    | 2020/08/27 09:09:52.984 | Reloading Wrapper configuration...
STATUS | wrapper  | main    | 2020/08/27 09:09:53.209 | Launching a JVM...
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.415 | Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e9990000, 29366878208, 0) failed; error='Cannot allocate memory' (errno=12)
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.416 | #
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.416 | # There is insufficient memory for the Java Runtime Environment to continue.
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.416 | # Native memory allocation (mmap) failed to map 29366878208 bytes for committing reserved memory.
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.416 | # An error report file with more information is saved as:
INFO   | jvm 2    | main    | 2020/08/27 09:09:53.416 | # /home/user/hybris/bin/platform/tomcat/bin/hs_err_pid31526.log
ERROR  | wrapper  | main    | 2020/08/27 09:09:53.459 | JVM exited while loading the application.
STATUS | wrapper  | main    | 2020/08/27 09:09:53.862 | Reloading Wrapper configuration...
STATUS | wrapper  | main    | 2020/08/27 09:09:54.076 | Launching a JVM...
ERROR  | wrapper  | main    | 2020/08/27 09:09:54.117 | JVM exited while loading the application.
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e9990000, 29366878208, 0) failed; error='Cannot allocate memory' (errno=12)
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | #
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | # There is insufficient memory for the Java Runtime Environment to continue.
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | # Native memory allocation (mmap) failed to map 29366878208 bytes for committing reserved memory.
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | # An error report file with more information is saved as:
INFO   | jvm 3    | main    | 2020/08/27 09:09:54.118 | # /home/user/hybris/bin/platform/tomcat/bin/hs_err_pid31536.log
STATUS | wrapper  | main    | 2020/08/27 09:09:54.521 | Reloading Wrapper configuration...
STATUS | wrapper  | main    | 2020/08/27 09:09:54.737 | Launching a JVM...
ERROR  | wrapper  | main    | 2020/08/27 09:09:54.773 | JVM exited while loading the application.
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e9990000, 29366878208, 0) failed; error='Cannot allocate memory' (errno=12)
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | #
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | # There is insufficient memory for the Java Runtime Environment to continue.
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | # Native memory allocation (mmap) failed to map 29366878208 bytes for committing reserved memory.
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | # An error report file with more information is saved as:
INFO   | jvm 4    | main    | 2020/08/27 09:09:54.773 | # /home/user/hybris/bin/platform/tomcat/bin/hs_err_pid31546.log
STATUS | wrapper  | main    | 2020/08/27 09:09:55.176 | Reloading Wrapper configuration...
STATUS | wrapper  | main    | 2020/08/27 09:09:55.385 | Launching a JVM...
ERROR  | wrapper  | main    | 2020/08/27 09:09:55.425 | JVM exited while loading the application.
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e9990000, 29366878208, 0) failed; error='Cannot allocate memory' (errno=12)
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | #
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | # There is insufficient memory for the Java Runtime Environment to continue.
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | # Native memory allocation (mmap) failed to map 29366878208 bytes for committing reserved memory.
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | # An error report file with more information is saved as:
INFO   | jvm 5    | main    | 2020/08/27 09:09:55.425 | # /home/user/hybris/bin/platform/tomcat/bin/hs_err_pid31556.log
STATUS | wrapper  | main    | 2020/08/27 09:09:55.827 | Reloading Wrapper configuration...
STATUS | wrapper  | main    | 2020/08/27 09:09:56.039 | Launching a JVM...
ERROR  | wrapper  | main    | 2020/08/27 09:09:56.076 | JVM exited while loading the application.
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e9990000, 29366878208, 0) failed; error='Cannot allocate memory' (errno=12)
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | #
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | # There is insufficient memory for the Java Runtime Environment to continue.
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | # Native memory allocation (mmap) failed to map 29366878208 bytes for committing reserved memory.
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | # An error report file with more information is saved as:
INFO   | jvm 6    | main    | 2020/08/27 09:09:56.077 | # /home/user/hybris/bin/platform/tomcat/bin/hs_err_pid31566.log
FATAL  | wrapper  | main    | 2020/08/27 09:09:56.378 | There were 5 failed launches in a row, each lasting less than 300 seconds.  Giving up.
FATAL  | wrapper  | main    | 2020/08/27 09:09:56.379 |   There may be a configuration problem: please check the logs.
STATUS | wrapper  | main    | 2020/08/27 09:09:56.580 | <-- Wrapper Stopped

Per me sembra che il server si spenga, senza motivo, ma non completamente e mantiene la RAM corrente e quindi tenta di ricominciare, ma non ha abbastanza RAM.

Inoltre il primo progetto dove vedo che una hybris si chiude giù da solo. Ho già lavorato in altri 4 grandi progetti, non ho mai avuto questo tipo di problema.

Author: Mr.Tr33, 2020-08-27
Source

1 answers

Questa mi sembra una terminazione non standard. Nel registro puoi vedere

JVM ha ricevuto un segnale SIGKILL (9)

Questo è qualcosa di esterno che invia un kill -9. Se il wrapper lo fa, dovresti vedere i messaggi sulla richiesta di spegnimento e quindi il timing out dell'operazione di spegnimento, prima che il wrapper alla fine uccida -9. Questo registro mostra qualcosa che va dritto con kill -9.

Immagino che dovrai guardare i sistemi esterni e / o l'O / S-I'm detto che l'O / S può farlo da solo se il sistema è sotto forte pressione della memoria. So che dici che il sistema ha molta memoria, ma potrebbe succedere qualcos'altro per consumare quella memoria altrove ... o potrebbe essere una VM in cui l'hardware effettivo è sovra-sottoscritto in modo che la VM non abbia tanta memoria come appare?

 0
Author: Neil Hubert-Price, 2020-08-27 09:06:38