Thanks.
Based on the thread dumps, it looks like the Compute Engine had one active task that was busy writing logs at the time when the thread dump was performed.
This might indicate that the volume where logs are written is running out of space, or is blocking for another reason.
Could you please check the volume and maybe try creating files in it with the same user that is running SonarQube to see if it’s in a writable state?
I tried connecting to the container, and can without problems write to the logs folder.
access.log in the same folder also gets updated without problems.
Maybe something in the logback configuration causing problems?
Workarounds include reducing logging, and avoiding use of console appender.
The first suggestion is not worth much in practice.
But if the log output is going into a file anyway, maybe allow console log output to be suppressed?
The last logs you sent seem to be from the start process, not from the Compute Engine.
Anyway, good find about the Logback issue. Unfortunately, the bug report and the comments don’t really explain why the thread holding the lock is blocked writing to the file. I actually added a comment to it, since a lot of the comments are misleading.
Looking at the logs of the CE that you sent before (stack4.txt), it appears that you’re experiencing the same problem, except that there are no other threads waiting for the lock to be released.
"Worker 0 (UUID=AXMf7TQqAK9iwH23_ROA) on ce-worker-0" #33 prio=1 os_prio=0 cpu=92818.66ms elapsed=48441.33s tid=0x00007f2654fb0800 nid=0x138 runnable [0x00007f26156f4000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(java.base@11.0.5/Native Method)
at java.io.FileOutputStream.write(java.base@11.0.5/FileOutputStream.java:354)
at java.io.BufferedOutputStream.write(java.base@11.0.5/BufferedOutputStream.java:123)
- locked <0x00000000e07945e0> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(java.base@11.0.5/PrintStream.java:559)
- locked <0x00000000e07945b8> (a java.io.PrintStream)
at java.io.FilterOutputStream.write(java.base@11.0.5/FilterOutputStream.java:108)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
at org.sonar.api.utils.log.LogbackLogger.doInfo(LogbackLogger.java:90)
at org.sonar.api.utils.log.BaseLogger.info(BaseLogger.java:76)
at org.sonar.core.util.logs.DefaultProfiler.logInfo(DefaultProfiler.java:259)
at org.sonar.core.util.logs.DefaultProfiler.log(DefaultProfiler.java:228)
at org.sonar.core.util.logs.DefaultProfiler.doStop(DefaultProfiler.java:197)
at org.sonar.core.util.logs.DefaultProfiler.stopInfo(DefaultProfiler.java:131)
at org.sonar.ce.task.step.ComputationStepExecutor.executeStep(ComputationStepExecutor.java:85)
at org.sonar.ce.task.step.ComputationStepExecutor.executeSteps(ComputationStepExecutor.java:72)
at org.sonar.ce.task.step.ComputationStepExecutor.execute(ComputationStepExecutor.java:59)
at org.sonar.ce.task.projectanalysis.taskprocessor.ReportTaskProcessor.process(ReportTaskProcessor.java:81)
at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.executeTask(CeWorkerImpl.java:209)
at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.run(CeWorkerImpl.java:191)
It’s writing to a file, so I don’t see it being related to console output.
If you’d like to try change the logging configuration, you can do so by modifying the commented out section LOGGING in the file conf/sonar.properties.
In the log I posted, I see:
“Gobbler[ce]” #46 prio=5 os_prio=0 cpu=580.18ms elapsed=1534.72s tid=0x00007f8970004800 nid=0x101 runnable [0x00007f89b84e5000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(java.base@11.0.7/Native Method)
I thought that was what you meant by the Compute Enging hanging.
But is this the root of the problem? Do the two processes write to the same file and cause some kind of lock perhaps?
I will try to tweak the config file to see if it makes a difference.
However, I am taking 3 weeks of vacation starting Friday, so it will take a while before I can look at it again.
yea, that wasn’t much help. We did notice the problem when our cluster got upgraded from ubuntu 16 -> 18. Does that help at all? Nothing about our firewall changed at all, that upgrade was the only thing.
That’s just a thread in the start process waiting for logs to be sent out to the stdout of the Compute Engine process. Nothing abnormal there.
If you see a task in the CE hanging again, get the thread dump of the Compute Engine process.
Please let us know if you have any new information. It’s hard to find the root cause without a reproducer.
We did end up changing the following:
SONAR_JDBC_MAXIDLE=0
and
SONAR_JDBC_MINIDLE=0
Basically to keep it from trying to keep connections idle. But there does appear to be some sensitivity to idle connections getting closed that changes when our nodes upgraded from Ubuntu 16 -> 18.
Thanks. Once again, the logging appender is blocked trying to write logs. It’s not a lock problem, since it’s actually holding the lock.
There are some reports that the receiving end of pipes can stop consuming data causing the writer to block: http://www.jppf.org/tracker/tbg/jppf/issues/JPPF-343https://issues.apache.org/jira/browse/LOG4J2-880
It’s unclear in what conditions that would happen but I’d try to make sure nothing is logged to the console (stdout/stderr). Did you set any property related to logging in sonar.properties? I think by default nothing is logged to stdout/stderr by default, only to files.
Not sure if related. But that bug came up when searching.
Anyway, the curious thing is that the logback hang is reported to trigger when there is large amounts of output.
And I am looking at log-files of a couple of MB. Hardly a lot of data these days.
I will try to increase the log level to see if it triggers the bug in day-to-day operations (instead of just weekends when we build all projects).
Ok, that could be it.
What I suspect is that the reader of the pipe is not picking up the data, the pipe gets full and the logger hangs trying to write to it. The logger could probably do a better job handling that without blocking while holding a lock, but ultimately the problem is caused by a mismanagement of the pipes attached to the process.