Buck: Buck fails during parsing of test xml files

[kageiit]

Seeing this stacktrace randomly when running tests

java.nio.channels.ClosedByInterruptException
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
    at sun.nio.ch.FileChannelImpl.size(FileChannelImpl.java:315)
    at java.nio.file.Files.readAllBytes(Files.java:3154)
    at com.facebook.buck.test.XmlTestResultParser.parse(XmlTestResultParser.java:125)
    at com.facebook.buck.jvm.java.JavaTest.lambda$0(JavaTest.java:448)
    at com.facebook.buck.cli.TestRunning$4.call(TestRunning.java:537)
    at com.facebook.buck.cli.TestRunning$4.call(TestRunning.java:1)
    at com.facebook.buck.cli.TestRunning.lambda$1(TestRunning.java:811)
    at com.facebook.buck.util.concurrent.WeightedListeningExecutorService.lambda$0(WeightedListeningExecutorService.java:78)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:211)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:200)
    at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:130)
    at com.google.common.util.concurrent.MoreExecutors$5$1.run(MoreExecutors.java:952)
    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:748)

Seems to be happening after we picked up https://github.com/facebook/buck/commit/886fa842cf6589fb5b1942d61fa0343582740da9 recently

[kageiit]

cc @katelyn-weingart @dreiss

[katelyn-weingart]

Hi, I'm looking into this. It could easily be my change but I'm not sure what would have caused the failure because this test is only checking the results of XmlDomParser, not XmlDomParserWithLineNumbers.

The only significant change here related to the failure is that I moved XmlDomParser into the buck.util.xml package from the buck.util package.

[katelyn-weingart]

One potential cause for this failure is that in the BUCK file I added, the XmlDomParser is under java_library rule instead of a java_immutables_library rule. Will change if I get confirmation from @styurin or someone else in buck that this change could cause this failure

[styurin]

I doubt 886fa84 is related to this. Do you have any other exceptions in the log related to interruptions?

[kageiit]

Also seeing

java.lang.InterruptedException
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.UNIXProcess.waitFor(UNIXProcess.java:395)
    at com.facebook.buck.util.DefaultProcessExecutor.execute(DefaultProcessExecutor.java:307)
    at com.facebook.buck.util.DefaultProcessExecutor.launchAndExecute(DefaultProcessExecutor.java:132)
    at com.facebook.buck.util.DefaultProcessExecutor.launchAndExecute(DefaultProcessExecutor.java:120)
    at com.facebook.buck.shell.ShellStep.launchAndInteractWithProcess(ShellStep.java:161)
    at com.facebook.buck.shell.ShellStep.execute(ShellStep.java:105)
    at com.facebook.buck.step.DefaultStepRunner.runStepForBuildTarget(DefaultStepRunner.java:45)
    at com.facebook.buck.cli.TestRunning.lambda$1(TestRunning.java:806)
    at com.facebook.buck.util.concurrent.WeightedListeningExecutorService.lambda$0(WeightedListeningExecutorService.java:78)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:211)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:200)
    at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:130)
    at com.google.common.util.concurrent.MoreExecutors$5$1.run(MoreExecutors.java:952)
    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:748)

====STANDARD OUT====

====STANDARD ERR====

In the logs. Many of them

[kageiit]

Last known buck sha where this was not happening is 62f479585a5e2f6197f5eb08b244afbea03cace3

[bertmaher]

It's interesting to me that we picked up a new release of nailgun in that time window (I don't know of anywhere we generate InterruptedExceptions aside from nailgun), but I don't see anything to make me suspicious of that bump. Will keep investigating.

[kageiit]

@bertmaher It is interesting that you mentioned nailgun.

I looked at the logs in buck-out/log and found this when the exception happened

stderr:


[2017-08-11 06:06:28.963][warn ][command:null][tid:559][com.martiansoftware.nailgun.NGInputStream] Nailgun client read future timed out after 60000 ms
java.util.concurrent.TimeoutException
    at java.util.concurrent.FutureTask.get(FutureTask.java:205)
    at com.martiansoftware.nailgun.NGInputStream$1.run(NGInputStream.java:91)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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:748)

[2017-08-11 06:06:29.078][debug][command:null][tid:559][com.martiansoftware.nailgun.NGInputStream] Nailgun client read shutting down
[2017-08-11 06:06:29.078][info ][command:null][tid:559][com.facebook.buck.cli.Main] BuckIsDyingException: killing background processes on client disconnectionjava.lang.Throwable
    at com.facebook.buck.cli.Main.lambda$3(Main.java:1271)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListener(NGInputStream.java:117)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListener(NGInputStream.java:132)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListeners(NGInputStream.java:150)
    at com.martiansoftware.nailgun.NGInputStream.access$300(NGInputStream.java:35)
    at com.martiansoftware.nailgun.NGInputStream$1.run(NGInputStream.java:101)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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:748)

[2017-08-11 06:06:29.079][info ][command:null][tid:559][com.facebook.buck.cli.Daemon] Client disconnected.
[2017-08-11 06:06:29.088][warn ][command:6a78fd6f-d01c-489c-921e-daf926c0385d][tid:556][com.facebook.buck.util.Threads] Current thread interrupted at this location: java.lang.Throwable
    at com.facebook.buck.util.Threads.interruptCurrentThread(Threads.java:38)
    at com.facebook.buck.cli.TestRunning.runTests(TestRunning.java:390)
    at com.facebook.buck.cli.TestCommand.runTestsInternal(TestCommand.java:296)
    at com.facebook.buck.cli.TestCommand.runWithoutHelp(TestCommand.java:589)
    at com.facebook.buck.cli.AbstractCommand.run(AbstractCommand.java:227)
    at com.facebook.buck.cli.AbstractContainerCommand.run(AbstractContainerCommand.java:67)
    at com.facebook.buck.cli.BuckCommand.run(BuckCommand.java:81)
    at com.facebook.buck.cli.Main.runMainWithExitCode(Main.java:983)
    at com.facebook.buck.cli.Main.runMainThenExit(Main.java:372)
    at com.facebook.buck.cli.Main.nailMain(Main.java:1725)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.martiansoftware.nailgun.NGSession.run(NGSession.java:329)

[2017-08-11 06:06:29.365][warn ][command:6a78fd6f-d01c-489c-921e-daf926c0385d][tid:619][com.facebook.buck.cli.TestRunning] Test command step failed, marking //apps/foo:test_release as failed
java.nio.channels.ClosedByInterruptException
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
    at sun.nio.ch.FileChannelImpl.size(FileChannelImpl.java:315)
    at java.nio.file.Files.readAllBytes(Files.java:3154)
    at com.facebook.buck.test.XmlTestResultParser.parse(XmlTestResultParser.java:125)
    at com.facebook.buck.jvm.java.JavaTest.lambda$0(JavaTest.java:449)
    at com.facebook.buck.cli.TestRunning$4.call(TestRunning.java:537)
    at com.facebook.buck.cli.TestRunning$4.call(TestRunning.java:1)
    at com.facebook.buck.cli.TestRunning.lambda$1(TestRunning.java:811)
    at com.facebook.buck.util.concurrent.WeightedListeningExecutorService.lambda$0(WeightedListeningExecutorService.java:78)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:211)
    at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:200)
    at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:130)
    at com.google.common.util.concurrent.MoreExecutors$5$1.run(MoreExecutors.java:952)
    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:748)

[kageiit]

The timestamps lineup too perfectly when nailgun exited and when the test runner got cancelled for this to be a coincidence

[styurin]

The nailgun update had only fixes related to multithread safety, there were no changes in logic. I'll double check them though

[kageiit]

I also observed several other test running threads abort immediately after the first nailgun issue and take out the entire build within a few seconds

[styurin]

I suspect there is a deadlock somewhere since it's timing out after 1 minute.

[styurin]

https://github.com/martylamb/nailgun/pull/104 created, I'll update out jar as soon as that PR is merged in.

[kageiit]

@styurin We tried the fix in martylamb/nailgun#104 and it is still happening

[kageiit]

Reverting the nailgun update in 9eabab154af3747c1175be18f545dfb11e5a6a76 is still causing the same problem

[kageiit]

Reverting the nailgun update has a different stacktrace

stderr:


[2017-08-11 21:46:48.522][info ][command:null][tid:555][com.facebook.buck.cli.Main] BuckIsDyingException: killing background processes on client disconnectionjava.lang.Throwable
    at com.facebook.buck.cli.Main.lambda$4(Main.java:1272)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListener(NGInputStream.java:117)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListener(NGInputStream.java:132)
    at com.martiansoftware.nailgun.NGInputStream.notifyClientListeners(NGInputStream.java:150)
    at com.martiansoftware.nailgun.NGInputStream.access$300(NGInputStream.java:35)
    at com.martiansoftware.nailgun.NGInputStream$1.run(NGInputStream.java:101)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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:748)

[2017-08-11 21:46:48.523][info ][command:null][tid:555][com.facebook.buck.cli.Daemon] Client disconnected.
[2017-08-11 21:46:48.678][warn ][command:892616de-0fbb-47a6-97db-342586aab04d][tid:551][com.facebook.buck.util.Threads] Current thread interrupted at this location: java.lang.Throwable
    at com.facebook.buck.util.Threads.interruptCurrentThread(Threads.java:38)
    at com.facebook.buck.cli.TestRunning.runTests(TestRunning.java:390)
    at com.facebook.buck.cli.TestCommand.runTestsInternal(TestCommand.java:296)
    at com.facebook.buck.cli.TestCommand.runWithoutHelp(TestCommand.java:589)
    at com.facebook.buck.cli.AbstractCommand.run(AbstractCommand.java:227)
    at com.facebook.buck.cli.AbstractContainerCommand.run(AbstractContainerCommand.java:67)
    at com.facebook.buck.cli.BuckCommand.run(BuckCommand.java:81)
    at com.facebook.buck.cli.Main.runMainWithExitCode(Main.java:984)
    at com.facebook.buck.cli.Main.runMainThenExit(Main.java:373)
    at com.facebook.buck.cli.Main.nailMain(Main.java:1722)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.martiansoftware.nailgun.NGSession.run(NGSession.java:338)

[kageiit]

Any update on this? This still is causing instability on our CI builds. Any idea what else we can do to debug this?

[bertmaher]

We've been running with NO_BUCKD in our CI, because of exactly this problem :-(. If it wasn't the nailgun update, I'm sort of at a loss for what could be causing this. Open to debugging ideas for sure.

[kageiit]

Ok I will try with NO_BUCKD and report back

[kageiit]

Setting NO_BUCKD=1 mitigated the issue on CI. Seems like something we should add to troubleshooting docs as it can bite anyone running tests with buck in CI environments.

[v-jizhang]

@kageiit Is this still happening? Thanks

[kageiit]

Setting no daemon on ci solved the issue so we can close this

[v-jizhang]

Thank you @kageiit