Elastic Search Indexing fails with Error : "Unrecoverable indexation failures" while migrating SonarQube from 5.6 to 6.7.1

[Nikhil Jain]

Hello,

We are trying to migrate SonarQube from 5.6 to 6.7. DB migration is successful but we get this error during Elastic Search Indexing :

web.log

-----------------------------------------------------------------------------------------

2018.02.26 10:50:08 DEBUG web[][sun.rmi.loader] RMI TCP Connection(26)-172.22.234.27: name = "[Ljava.lang.String;", codebase = ""

2018.02.26 10:50:08 ERROR web[][o.s.s.p.Platform] Background initialization failed. Stopping SonarQube

java.lang.IllegalStateException: Unrecoverable indexation failures

        at org.sonar.server.es.IndexingListener$1.onFinish(IndexingListener.java:39)

        at org.sonar.server.es.BulkIndexer.stop(BulkIndexer.java:117)

        at org.sonar.server.component.index.ComponentIndexer.doIndexByProjectUuid(ComponentIndexer.java:149)

        at org.sonar.server.component.index.ComponentIndexer.indexOnStartup(ComponentIndexer.java:71)

        at org.sonar.server.es.IndexerStartupTask.indexUninitializedTypes(IndexerStartupTask.java:68)

        at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)

        at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580)

        at org.sonar.server.es.IndexerStartupTask.execute(IndexerStartupTask.java:55)

        at java.util.Optional.ifPresent(Optional.java:159)

        at org.sonar.server.platform.platformlevel.PlatformLevelStartup$1.doPrivileged(PlatformLevelStartup.java:84)

        at org.sonar.server.user.DoPrivileged.execute(DoPrivileged.java:45)

        at org.sonar.server.platform.platformlevel.PlatformLevelStartup.start(PlatformLevelStartup.java:80)

        at org.sonar.server.platform.Platform.executeStartupTasks(Platform.java:196)

        at org.sonar.server.platform.Platform.access$400(Platform.java:46)

        at org.sonar.server.platform.Platform$1.lambda$doRun$1(Platform.java:121)

        at org.sonar.server.platform.Platform$AutoStarterRunnable.runIfNotAborted(Platform.java:371)

        at org.sonar.server.platform.Platform$1.doRun(Platform.java:121)

        at org.sonar.server.platform.Platform$AutoStarterRunnable.run(Platform.java:355)

        at java.lang.Thread.run(Thread.java:745)

2018.02.26 10:50:08 DEBUG web[][o.s.s.p.Platform] Background initialization of SonarQube done

----------------------------------------------------------------------

Sonar.log

----------------------------------------------------------------------

2018.02.26 10:07:12 DEBUG app[][i.n.util.Recycler] -Dio.netty.recycler.ratio: 8

2018.02.26 10:07:12 DEBUG app[][o.e.t.n.Netty4Transport] connected to node [{sonarqube}{ozaGoa39SA6jvZpRp_O70w}{rxG-jE6RTvClBjvAA43KSQ}{127.0.0.1}{127.0.0.1:9001}{rack_id=sonarqube}]

2018.02.26 10:07:13 INFO  app[][o.s.a.SchedulerImpl] Process[es] is up

2018.02.26 10:07:13 INFO  app[][o.s.a.p.ProcessLauncherImpl] Launch process[[key='web', ipcIndex=2, logFilenamePrefix=web]] from [/data/sonarqube/sonarqube-6.7.1]: /data/java/jdk1.8.0_101/jre/bin/java -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Djava.io.tmpdir=/data/sonarqube/sonarqube-6.7.1/temp -Xmx24G -Xms24G -XX:+HeapDumpOnOutOfMemoryError -Djava.net.preferIPv4Stack=true -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/tmp/GC.log -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=true -Dcom.sun.management.jmxremote.port=10443 -Dcom.sun.management.jmxremote.rmi.port=10444 -Dcom.sun.management.jmxremote.password.file=/data/sonarsource/sonar/conf/jmxremote.password -Dcom.sun.management.jmxremote.access.file=/data/sonarsource/sonar/conf/jmxremote.access -Djava.rmi.server.hostname=10.64.101.63 -cp ./lib/common/*:./lib/server/*:/data/sonarqube/sonarqube-6.7.1/lib/jdbc/mysql/mysql-connector-java-5.1.42.jar org.sonar.server.app.WebServer /data/sonarqube/sonarqube-6.7.1/temp/sq-process9027008388417072243properties

2018.02.26 10:50:11 DEBUG app[][o.s.a.p.AbstractProcessMonitor] Process exited with exit value [web]: 0

2018.02.26 10:50:11 INFO  app[][o.s.a.SchedulerImpl] Process [web] is stopped

2018.02.26 10:50:11 DEBUG app[][o.e.c.t.TransportClientNodesService] failed to connect to node [{#transport#-1}{pcixfhGsQs-QA0VbKhmX0Q}{127.0.0.1}{127.0.0.1:9001}], ignoring...

org.elasticsearch.transport.ConnectTransportException: [][127.0.0.1:9001] connect_timeout[30s]

        at org.elasticsearch.transport.netty4.Netty4Transport.connectToChannels(Netty4Transport.java:362)

        at org.elasticsearch.transport.TcpTransport.openConnection(TcpTransport.java:570)

        at org.elasticsearch.transport.TcpTransport.openConnection(TcpTransport.java:117)

        at org.elasticsearch.transport.TransportService.openConnection(TransportService.java:351)

        at org.elasticsearch.client.transport.TransportClientNodesService$SimpleNodeSampler.doSample(TransportClientNodesService.java:407)

        at org.elasticsearch.client.transport.TransportClientNodesService$NodeSampler.sample(TransportClientNodesService.java:357)

        at org.elasticsearch.client.transport.TransportClientNodesService$ScheduledNodeSampler.run(TransportClientNodesService.java:390)

        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:569)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

        at java.lang.Thread.run(Thread.java:745)

Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /127.0.0.1:9001

        at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

        at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)

        at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:352)

        at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340)

        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:632)

        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579)

        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496)

        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)

        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)

        ... 1 common frames omitted

Caused by: java.net.ConnectException: Connection refused

        ... 10 common frames omitted

2018.02.26 10:50:12 INFO  app[][o.s.a.SchedulerImpl] Process [es] is stopped

2018.02.26 10:50:12 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

2018.02.26 10:50:12 WARN  app[][o.s.a.p.AbstractProcessMonitor] Process exited with exit value [es]: 143

----------------------------------------------------------------------

We are running elastic search and web server both with 24 GB RAM.

Has anyone encountered such issue before?

P.S: I have tried deleting the data folder and keeping the upgraded plugin in extension/plugins but it fails with same error.

Thanks

Nikhil

[nicolas...@sonarsource.com]

Hi Nikhil,

I suggest you share a larger chunk of web.log (ideally the full log file), that will allow to understand the sequence/state at which SonarQube failed with this error. And at the same time I recommend you share your current settings sonar.[search/web/ce].javaOpts in sonar.properties .

Best regards,

Nicolas

[Colin Mueller]

Nikhil,

Can you double check that all processes related to the previous version of SonarQube are stopped? Your errors remind me of some errors I faced trying to upgrade SonarQube in the past, where some processes did not stop all the way. Running jps on the command line (on either Windows or Linux) helped me suss out the processes that need to be kliled.

If that doesn't work, can you also try starting your server without JMX enabled? 

Colin

[Nikhil Jain]

Hi Nicolas,

Below are the current settings :

sonar.search.javaOpts=-Xmx24G -Xms24G -Djava.net.preferIPv4Stack=true \

  -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 \

  -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError

sonar.ce.javaOpts=-Xmx8G -Xms8G -XX:+HeapDumpOnOutOfMemoryError -Djava.net.preferIPv4Stack=true

sonar.web.javaOpts=-Xmx24G -Xms24G -XX:+HeapDumpOnOutOfMemoryError -Djava.net.preferIPv4Stack=true -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/tmp/GC.log

Also here is the link to see complete web.log = https://drive.google.com/open?id=16jFdpRKEvhJ4lzuZGxdhTCKrphadvtTf .

Thanks in advance for having a look.

Regards,

Nikhil

[vism...@gmail.com]

Hi Colin,

Removing the JMX parameters seems to have helped us as the ES indexing has been running for much longer than before. Could you please explain why this has helped fixed the issue?

- Vismay

[vism...@gmail.com]

I spoke too soon :)  

We faced the same error after ~2 hours of ES indexing. So, while the indexing did run for longer after disabling JMX, it did not fix the issue.