Problem with SonarQube start on Ubuntu 1604. Process exited with exit value [es]: 143

Pavel_Puker · June 19, 2018, 2:40pm

Hello! Could you please help me with my problem. I tried to find solution in Google, but, i was not able to find it.

My sonar.log file.

Spawning intermediate process...
Spawning daemon process...
--> Wrapper Started as Daemon
Using tick timer.
server listening on port 32000.
Command[0] : /usr/lib/jvm/java-8-oracle/bin/java
Command[1] : -Dsonar.wrapped=true
Command[2] : -Djava.awt.headless=true
Command[3] : -Xms8m
Command[4] : -Xmx32m
Command[5] : -Djava.library.path=./lib
Command[6] : -classpath
Command[7] : ../../lib/jsw/log4j-core-2.11.0.jar:../../lib/jsw/log4j-api-2.11.0.jar:../../lib/jsw/wrapper-3.2.3.jar:../../lib/common/commons-dbutils-1.5.jar:../../lib/common/alm-vss-client-1.0.2.jar:../../lib/common/commons-io-2.6.jar:../../lib/common/github-api-1.93.0.71.jar:../../lib/common/lucene-misc-6.6.1.jar:../../lib/common/lucene-core-6.6.1.jar:../../lib/common/logback-access-1.2.3.jar:../../lib/common/jackson-jaxrs-base-2.4.1.jar:../../lib/common/netty-handler-4.1.13.Final.jar:../../lib/common/picocontainer-2.15.jar:../../lib/common/activation-1.1.jar:../../lib/common/jackson-databind-2.9.5.jar:../../lib/common/lucene-queries-6.6.1.jar:../../lib/common/sonar-db-core-7.2.jar:../../lib/common/commons-pool-1.5.4.jar:../../lib/common/aopalliance-repackaged-2.5.0-b42.jar:../../lib/common/bcprov-jdk15on-1.59.jar:../../lib/common/diffutils-1.2.jar:../../lib/common/sonar-process-7.2.jar:../../lib/common/log4j-api-2.11.0.jar:../../lib/common/sonar-update-center-common-1.18.0.487.jar:../../lib/common/lucene-join-6.6.1.jar:../../lib/common/netty-transport-4.1.13.Final.jar:../../lib/common/guava-18.0.jar:../../lib/common/lucene-spatial-6.6.1.jar:../../lib/common/log4j-to-slf4j-2.8.2.jar:../../lib/common/lucene-sandbox-6.6.1.jar:../../lib/common/jaxb-api-2.3.0.jar:../../lib/common/jackson-module-jaxb-annotations-2.4.1.jar:../../lib/common/jackson-jaxrs-json-provider-2.4.1.jar:../../lib/common/sonar-ws-7.2.jar:../../lib/common/securesm-1.1.jar:../../lib/common/tomcat-annotations-api-8.5.23.jar:../../lib/common/alm-releasemanagement-client-1.0.2.jar:../../lib/common/parent-join-client-5.6.3.jar:../../lib/common/jackson-dataformat-cbor-2.8.6.jar:../../lib/common/hppc-0.7.1.jar:../../lib/common/jna-4.4.0-1.jar:../../lib/common/lucene-queryparser-6.6.1.jar:../../lib/common/osgi-resource-locator-1.0.1.jar:../../lib/common/sonar-scanner-protocol-7.2.jar:../../lib/common/javax.mail-1.5.6.jar:../../lib/common/sonar-server-common-7.2.jar:../../lib/common/netty-resolver-4.1.13.Final.jar:../../lib/common/javassist-3.22.0-CR2.jar:../../lib/common/javax.inject-1.jar:../../lib/common/sonar-server-7.2.jar:../../lib/common/lz4-1.3.0.jar:../../lib/common/hazelcast-3.8.6.jar:../../lib/common/httpcore-4.4.4.jar:../../lib/common/commons-codec-1.8.jar:../../lib/common/lucene-highlighter-6.6.1.jar:../../lib/common/jersey-common-2.26.jar:../../lib/common/commons-dbcp-1.4.jar:../../lib/common/lucene-spatial3d-6.6.1.jar:../../lib/common/netty-codec-http-4.1.13.Final.jar:../../lib/common/lucene-grouping-6.6.1.jar:../../lib/common/edition-developer-7.2.jar:../../lib/common/alm-tfs-client-1.0.2.jar:../../lib/common/hk2-locator-2.5.0-b42.jar:../../lib/common/httpclient-4.5.2.jar:../../lib/common/staxmate-2.0.1.jar:../../lib/common/nanohttpd-2.3.0.jar:../../lib/common/javax.inject-2.5.0-b42.jar:../../lib/common/sonar-markdown-7.2.jar:../../lib/common/jopt-simple-5.0.2.jar:../../lib/common/okhttp-3.7.0.jar:../../lib/common/netty-buffer-4.1.13.Final.jar:../../lib/common/sonar-plugin-bridge-7.2.jar:../../lib/common/jul-to-slf4j-1.7.25.jar:../../lib/common/log4j-core-2.11.0.jar:../../lib/common/jjwt-0.9.0.jar:../../lib/common/netty-codec-4.1.13.Final.jar:../../lib/common/bcpkix-jdk15on-1.59.jar:../../lib/common/sonar-classloader-1.0.jar:../../lib/common/javax.ws.rs-api-2.1.jar:../../lib/common/lucene-backward-codecs-6.6.1.jar:../../lib/common/percolator-client-5.6.3.jar:../../lib/common/logback-classic-1.2.3.jar:../../lib/common/lucene-suggest-6.6.1.jar:../../lib/common/javax.annotation-api-1.2.jar:../../lib/common/logback-core-1.2.3.jar:../../lib/common/okio-1.12.0.jar:../../lib/common/slf4j-api-1.7.25.jar:../../lib/common/sonar-core-7.2.jar:../../lib/common/jersey-hk2-2.26.jar:../../lib/common/hk2-api-2.5.0-b42.jar:../../lib/common/hazelcast-client-3.8.6.jar:../../lib/common/jackson-core-2.9.5.jar:../../lib/common/commons-lang-2.6.jar:../../lib/common/commons-csv-1.4.jar:../../lib/common/transport-netty4-client-5.6.3.jar:../../lib/common/netty-common-4.1.13.Final.jar:../../lib/common/lucene-memory-6.6.1.jar:../../lib/common/jackson-dataformat-yaml-2.8.6.jar:../../lib/common/sonar-db-dao-7.2.jar:../../lib/common/stax2-api-3.1.4.jar:../../lib/common/alm-distributedtask-client-1.0.2.jar:../../lib/common/hk2-utils-2.5.0-b42.jar:../../lib/common/alm-gallery-client-1.0.2.jar:../../lib/common/woodstox-core-lgpl-4.4.0.jar:../../lib/common/sonar-ce-7.2.jar:../../lib/common/lucene-analyzers-common-6.6.1.jar:../../lib/common/elasticsearch-5.6.3.jar:../../lib/common/jersey-client-2.26.jar:../../lib/common/tomcat-embed-core-8.5.23.jar:../../lib/common/jbcrypt-0.4.jar:../../lib/common/lucene-spatial-extras-6.6.1.jar:../../lib/common/sonar-db-migration-7.2.jar:../../lib/common/java-jwt-3.3.0.jar:../../lib/common/HdrHistogram-2.1.9.jar:../../lib/common/commons-email-1.5.jar:../../lib/common/jersey-apache-connector-2.26.jar:../../lib/common/snakeyaml-1.15.jar:../../lib/common/gson-2.8.4.jar:../../lib/common/jackson-annotations-2.9.5.jar:../../lib/common/protobuf-java-3.5.1.jar:../../lib/common/sonar-plugin-api-7.2-all.jar:../../lib/common/sonar-main-7.2.jar:../../lib/common/t-digest-3.0.jar:../../lib/common/transport-5.6.3.jar:../../lib/common/joda-time-2.9.5.jar:../../lib/common/alm-extensionmanagement-client-1.0.2.jar:../../lib/common/mybatis-3.4.6.jar:../../lib/common/jackson-dataformat-smile-2.8.6.jar:../../lib/log4j-core-2.11.0.jar:../../lib/sonar-application-7.2.jar:../../lib/log4j-api-2.11.0.jar
Command[8] : -Dwrapper.key=zYw7b5DVhTOzKwnw
Command[9] : -Dwrapper.port=32000
Command[10] : -Dwrapper.jvm.port.min=31000
Command[11] : -Dwrapper.jvm.port.max=31999
Command[12] : -Dwrapper.debug=TRUE
Command[13] : -Dwrapper.pid=9407
Command[14] : -Dwrapper.version=3.2.3
Command[15] : -Dwrapper.native_library=wrapper
Command[16] : -Dwrapper.service=TRUE
Command[17] : -Dwrapper.cpu.timeout=10
Command[18] : -Dwrapper.jvmid=1
Command[19] : org.tanukisoftware.wrapper.WrapperSimpleApp
Command[20] : org.sonar.application.App
Launching a JVM...
WrapperManager class initialized by thread: main  Using classloader: sun.misc.Launcher$AppClassLoader@42a57993
Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
  Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.

Wrapper Manager: JVM #1
Running a 64-bit JVM.
Wrapper Manager: Registering shutdown hook
Wrapper Manager: Using wrapper
Load native library.  One or more attempts may fail if platform specific libraries do not exist.
Loading native library failed: libwrapper-linux-x86-64.so  Cause: java.lang.UnsatisfiedLinkError: no wrapper-linux-x86-64 in java.library.path
Loaded native library: libwrapper.so
Calling native initialization method.
Inside native WrapperManager initialization method
Java Version   : 1.8.0_171-b11 Java HotSpot(TM) 64-Bit Server VM
Java VM Vendor : Oracle Corporation

Control event monitor thread started.
Startup runner thread started.
WrapperManager.start(org.tanukisoftware.wrapper.WrapperSimpleApp@73c6c3b2, args[]) called by thread: main
Communications runner thread started.
Open socket to wrapper...Wrapper-Connection
Opened Socket from 31000 to 32000
Send a packet KEY : zYw7b5DVhTOzKwnw
handleSocket(Socket[addr=/127.0.0.1,port=32000,localport=31000])
accepted a socket from 127.0.0.1 on port 31000
read a packet KEY : zYw7b5DVhTOzKwnw
Got key from JVM: zYw7b5DVhTOzKwnw
send a packet LOW_LOG_LEVEL : 1
send a packet PING_TIMEOUT : 300
send a packet PROPERTIES : (Property Values)
Start Application.
send a packet START : start
Received a packet LOW_LOG_LEVEL : 1
Wrapper Manager: LowLogLevel from Wrapper is 1
Received a packet PING_TIMEOUT : 300
PingTimeout from Wrapper is 300000
Received a packet PROPERTIES : (Property Values)
Received a packet START : start
calling WrapperListener.start()
Waiting for WrapperListener.start runner thread to complete.
WrapperListener.start runner thread started.
WrapperSimpleApp: start(args) Will wait up to 2 seconds for the main method to complete.
WrapperSimpleApp: invoking main method
Signal trapped.  Details:
  signal number=15 (SIGTERM), source="kill, sigsend or raise"
  signal generated by PID: 9484 (Session PID: 9482), UID: 1001 (sonar)
TERM trapped.  Shutting down.
wrapperStopProcess(0) called.
Sending stop signal to JVM
send a packet STOP : NULL
2018.06.19 17:33:56 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /opt/sonarqube/temp
2018.06.19 17:33:57 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on /127.0.0.1:9001
2018.06.19 17:33:57 INFO  app[][o.s.a.p.ProcessLauncherImpl] Launch process[[key='es', ipcIndex=1, logFilenamePrefix=es]] from [/opt/sonarqube/elasticsearch]: /opt/sonarqube/elasticsearch/bin/elasticsearch -Epath.conf=/opt/sonarqube/temp/conf/es
2018.06.19 17:33:57 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
Send a packet START_PENDING : 5000
read a packet START_PENDING : 5000
JVM signalled a start pending with waitHint of 5000 millis.
2018.06.19 17:33:57 INFO  app[][o.e.p.PluginsService] no modules loaded
2018.06.19 17:33:57 INFO  app[][o.e.p.PluginsService] loaded plugin [org.elasticsearch.transport.Netty4Plugin]
Send a packet START_PENDING : 5000
WrapperSimpleApp: start(args) end.  Main Completed=false, exitCode=null
WrapperListener.start runner thread stopped.
returned from WrapperListener.start()
Send a packet STARTED :
Received a packet STOP :
Thread, Wrapper-Connection, handling the shutdown process.
calling listener.stop()
Waiting for WrapperListener.stop runner thread to complete.
WrapperListener.stop runner thread started.
WrapperSimpleApp: stop(0)
WrapperListener.stop runner thread stopped.
returned from listener.stop() -> 0
shutdownJVM(0) Thread:Wrapper-Connection
Send a packet STOPPED : 0
read a packet START_PENDING : 5000
JVM signalled a start pending with waitHint of 5000 millis.
read a packet STARTED :
JVM signalled that it was started.
send a packet STOP : NULL
read a packet STOPPED : 0
JVM signalled that it was stopped.
Startup runner thread stopped.
Closing socket.
socket read no code (closed?).
server listening on port 32001.
calling System.exit(0)
2018.06.19 17:33:59 INFO  app[][o.s.a.SchedulerImpl] Stopping SonarQube
JVM exited normally.
Signal trapped.  Details:
  signal number=17 (SIGCHLD), source="unknown"
Received SIGCHLD, checking JVM process status.
JVM process exited with a code of 0, leaving the wrapper exit code set to 0.
2018.06.19 17:33:59 WARN  app[][o.s.a.p.AbstractProcessMonitor] Process exited with exit value [es]: 143
2018.06.19 17:33:59 INFO  app[][o.s.a.SchedulerImpl] Process [es] is stopped
2018.06.19 17:33:59 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped
WrapperSimpleApp: main method completed
<-- Wrapper Stopped

I will really appreciate for help.

ganncamp · June 20, 2018, 11:31am

Hi,

You appear to have included sonar.log. Typically the error message is found in one of the other logs. Before you look, though I’m going to venture a guess that you tried to run SonarQube as root. That’s no longer possible; you’ll need to run it as another user.

Ann

Pavel_Puker · June 20, 2018, 12:01pm

Hello G Ann! Thank you so much for your response!
Unfortunately I think that problem not in this.(
I had another problem and I fix it with start sonarqube with sonar user, not root.

I can share my /bin/linux-x86-64/sonar.sh file.

#! /bin/sh

#
# Copyright (c) 1999, 2006 Tanuki Software Inc.
#
# Java Service Wrapper sh script.  Suitable for starting and stopping
#  wrapped Java applications on UNIX platforms.
#
#-----------------------------------------------------------------------------
# These settings can be modified to fit the needs of your application
# Default values for the Application variables, below.
#
# NOTE: The build for specific applications may override this during the resource-copying
# phase, to fill in a concrete name and avoid the use of the defaults specified here.
DEF_APP_NAME="SonarQube"
DEF_APP_LONG_NAME="SonarQube"

# Application
APP_NAME="${DEF_APP_NAME}"
APP_LONG_NAME="${DEF_APP_LONG_NAME}"

# Wrapper
WRAPPER_CMD="./wrapper"
WRAPPER_CONF="../../conf/wrapper.conf"

# Priority at which to run the wrapper.  See "man nice" for valid priorities.
#  nice is only used if a priority is specified.
PRIORITY=

# Location of the pid file.
PIDDIR="."

# If uncommented, causes the Wrapper to be shutdown using an anchor file.
#  When launched with the 'start' command, it will also ignore all INT and
#  TERM signals.
#IGNORE_SIGNALS=true

# If specified, the Wrapper will be run as the specified user.
# IMPORTANT - Make sure that the user has the required privileges to write
#  the PID file and wrapper.log files.  Failure to be able to write the log
#  file will cause the Wrapper to exit without any way to write out an error
#  message.
# NOTE - This will set the user which is used to run the Wrapper as well as
#  the JVM and is not useful in situations where a privileged resource or
#  port needs to be allocated prior to the user being changed.
RUN_AS_USER=sonar

# The following two lines are used by the chkconfig command. Change as is
#  appropriate for your application.  They should remain commented.
# chkconfig: 2345 20 80
# description: Test Wrapper Sample Application
# Do not modify anything beyond this point

You can find here “RUN_AS_USER=sonar” line.

And this user have permissions for files in this folder.

drwxr-xr-x 11 sonar sonar 4096 Jun 18 09:35 .
drwxr-xr-x  3 root  root  4096 Jun 19 17:17 ..
-rw-r--r--  1 sonar sonar 7651 Jun 18 09:31 COPYING
drwxr-xr-x  8 sonar sonar 4096 Jun 18 09:31 bin
drwxr-xr-x  2 sonar sonar 4096 Jun 20 14:56 conf
drwxr-xr-x  3 sonar sonar 4096 Jun 19 06:25 data
drwxr-xr-x  7 sonar sonar 4096 Jun 18 09:31 elasticsearch
drwxr-xr-x  4 sonar sonar 4096 Jun 18 09:31 extensions
drwxr-xr-x  7 sonar sonar 4096 Jun 19 10:39 lib
drwxr-xr-x  2 sonar sonar 4096 Jun 19 06:25 logs
drwxr-xr-x  3 sonar sonar 4096 Jun 20 14:56 temp
drwxr-xr-x  7 sonar sonar 4096 Jun 18 09:35 web

I really hope that you can help me. Thanks for your time.

ganncamp · June 20, 2018, 1:21pm

Hi,

When you look in $SONARQUBE_HOME/logs, you see multiple files there. Please check each one for error messages.

More details: https://docs.sonarqube.org/display/SONAR/Troubleshooting

Ann

Pavel_Puker · June 20, 2018, 1:52pm

)))) I know where to find the log files, and how read it.)

But in my “logs” folder i see two files only.

And I sent you log from “sonar.log” file in first message, in DEBUG mode.)

I used a lot of ways to solve the problem before I wrote to you.

NicoB · June 20, 2018, 2:04pm

What does es.log say ? It’s possible that other logs are not yet printed because ElasticSearch process failed, before other processes got a chance to even start (see SonarQube Architecture). Looking at the error in es.log specifically should help you narrow-down the precise issue here.

Pavel_Puker · June 20, 2018, 2:44pm

Hello Nicolas! Thanks for you response!

My es.log file:

2018.06.19 06:25:11 INFO  es[][o.e.n.Node] initializing ...
2018.06.19 06:25:11 INFO  es[][o.e.e.NodeEnvironment] using [1] data paths, mounts [[/ (/dev/xvda1)]], net usable_space [44.1gb], net total_space [49gb], spins? [no], types [ext4]
2018.06.19 06:25:11 INFO  es[][o.e.e.NodeEnvironment] heap size [495.3mb], compressed ordinary object pointers [true]
2018.06.19 06:25:11 INFO  es[][o.e.n.Node] node name [sonarqube], node ID [CVMME_FdRCK6HG3g6MH5HA]
2018.06.19 06:25:11 INFO  es[][o.e.n.Node] version[5.6.3], pid[21570], build[1a2f265/2017-10-06T20:33:39.012Z], OS[Linux/4.4.0-127-generic/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_171/25.171-b11]
2018.06.19 06:25:11 INFO  es[][o.e.n.Node] JVM arguments [-XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -Djdk$
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [aggs-matrix-stats]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [ingest-common]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [parent-join]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [percolator]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [reindex]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] loaded module [transport-netty4]
2018.06.19 06:25:12 INFO  es[][o.e.p.PluginsService] no plugins loaded
2018.06.19 06:25:17 INFO  es[][o.e.d.DiscoveryModule] using discovery type [zen]
2018.06.19 06:25:17 INFO  es[][o.e.n.Node] initialized
2018.06.19 06:25:17 INFO  es[][o.e.n.Node] starting ...
2018.06.19 06:25:18 INFO  es[][o.e.t.TransportService] publish_address {127.0.0.1:9001}, bound_addresses {127.0.0.1:9001}
2018.06.19 06:25:18 WARN  es[][o.e.b.BootstrapChecks] max virtual memory areas vm.max_map_count [65530] is too low, increase to at least [262144]
2018.06.19 06:25:21 INFO  es[][o.e.c.s.ClusterService] new_master {sonarqube}{CVMME_FdRCK6HG3g6MH5HA}{v1S7iO_KTHWD7JavMuRh6w}{127.0.0.1}{127.0.0.1:9001}{rack_id=sonarqube}, reason: zen-disco-elected-as-master ([0] nodes joined)
2018.06.19 06:25:21 INFO  es[][o.e.n.Node] started
2018.06.19 06:25:21 INFO  es[][o.e.g.GatewayService] recovered [0] indices into cluster_state

I see here problem with this:

2018.06.19 06:25:18 WARN  es[][o.e.b.BootstrapChecks] max virtual memory areas vm.max_map_count [65530] is too low, increase to at least [262144]

But, my vm.count is:

ganncamp · June 21, 2018, 12:26pm

Hi,

You’re using sysctl to see the value. Did you use sysctl to set the value? If so, are you sure that value is available to the session/user running SonarQube? The docs give you advice on setting the value permanently and across all users/sessions.

Ann

NicoB · June 21, 2018, 2:21pm

Hi Pavel,

Actually this is only a warning, so it’s not fatal. And in fact you do get a successful startup log afterwards:

2018.06.19 06:25:21 INFO  es[][o.e.n.Node] started

All in all I would suggest you focus on this external signal SonarQube seems to be receiving (from your original post):

2018.06.19 17:33:59 INFO  app[][o.s.a.SchedulerImpl] Stopping SonarQube
JVM exited normally.
Signal trapped.  Details:
  signal number=17 (SIGCHLD), source="unknown"
Received SIGCHLD, checking JVM process status.
JVM process exited with a code of 0, leaving the wrapper exit code set to 0.
2018.06.19 17:33:59 WARN  app[][o.s.a.p.AbstractProcessMonitor] Process exited with exit value [es]: 143

If you didn’t kill the process on purpose, then the OS might have, for reasons you need to discover. One starting point could be to look at the CPU/RAM state of your machine as SonarQube starts-up, and see if anything stands out (or if there’s any resource starvation anywhere). You should also double-check/correlate with the actual JVM settings you’ve defined in sonar.properties.

Pavel_Puker · June 22, 2018, 8:35am

Thanks for your help.

Run Sonar with command ““ES_JAVA_OPTS=”-Xms2g -Xmx2g” ./bin/linux-x86-64/sonar.sh start" solve my problem.

NicoB · June 22, 2018, 8:56am

Thanks for the follow-up Pavel. At this stage I suggest you review ticket SONAR-10294 though, as we rather recommend to set JVM settings via the appropriate parameters in sonar.properties.