bitbucket-branch-source-plugin: Notifying pull request build result: ERROR: Could not send notifications | java.net.SocketTimeoutException: Read timed out

Your checklist for this issue

• Jenkins version: 2.176.1

• Plugin version: org.jenkins-ci.plugins:cloudbees-bitbucket-branch-source:2.4.5

• Bitbucket cloud: yes

• Bitbucket server and version

Description

I’m seeing a lot of errors updating build status via com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.postBuildStatus. The majority of these failures are observed at the end of a build, though some are at the start of one. This was originally discussed in issue #213, but that’s focused on retrying idempotent requests (GET branch list).

See also https://issues.jenkins-ci.org/browse/JENKINS-58810

[Bitbucket] Notifying pull request build result
ERROR: Could not send notifications
java.io.IOException: Communication error
	at com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.doRequest(BitbucketCloudApiClient.java:861)
	at com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.postRequest(BitbucketCloudApiClient.java:902)
	at com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.postBuildStatus(BitbucketCloudApiClient.java:607)
	at com.cloudbees.jenkins.plugins.bitbucket.BitbucketChangesetCommentNotifier.buildStatus(BitbucketChangesetCommentNotifier.java:50)
	at com.cloudbees.jenkins.plugins.bitbucket.BitbucketBuildStatusNotifications.createStatus(BitbucketBuildStatusNotifications.java:143)
	at com.cloudbees.jenkins.plugins.bitbucket.BitbucketBuildStatusNotifications.sendNotifications(BitbucketBuildStatusNotifications.java:185)
	at com.cloudbees.jenkins.plugins.bitbucket.BitbucketBuildStatusNotifications.access$000(BitbucketBuildStatusNotifications.java:60)
	at com.cloudbees.jenkins.plugins.bitbucket.BitbucketBuildStatusNotifications$JobCompletedListener.onCompleted(BitbucketBuildStatusNotifications.java:257)
	at hudson.model.listeners.RunListener.fireCompleted(RunListener.java:209)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.finish(WorkflowRun.java:584)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.access$1000(WorkflowRun.java:133)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:996)
	at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1463)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:458)
	at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:37)
	at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:131)
	at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
	at jenkins.security.ImpersonatingExecutorService$1.run(ImpersonatingExecutorService.java:59)
	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:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
	at sun.security.ssl.InputRecord.read(InputRecord.java:503)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
	at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
	at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
	at com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.executeMethod(BitbucketCloudApiClient.java:759)
	at com.cloudbees.jenkins.plugins.bitbucket.client.BitbucketCloudApiClient.doRequest(BitbucketCloudApiClient.java:843)
	... 22 more
Finished: SUCCESS

Any build with the failure at the end remains green and the Bitbucket UI will show “0 of 1”. Any build with the failure at the start doesn’t proceed at all, and no mention of the build will appear in the Bitbucket UI.

The socket timeout above is currently hardcoded to 60 * 1000 milliseconds, aka 1 minute. I see failures like the above logged at ~6 minutes after the last successful “[Bitbucket] Notifying pull request build result” logged.

https://github.com/jenkinsci/bitbucket-branch-source-plugin/blob/7c761939e6b950adbadb08ede737ac3b51470002/src/main/java/com/cloudbees/jenkins/plugins/bitbucket/client/BitbucketCloudApiClient.java#L151

This does not appear to be a symptom of rate limiting. I cranked up the logging level and reproduced a bunch of failures - that LOGGER.fine() about bitbucket API rate limiting isn’t logged. And Bitbucket support has indicated that hitting api rate limits should produce HTTP/429.

https://github.com/jenkinsci/bitbucket-branch-source-plugin/blob/7c761939e6b950adbadb08ede737ac3b51470002/src/main/java/com/cloudbees/jenkins/plugins/bitbucket/client/BitbucketCloudApiClient.java#L747-L774

I have not managed to reproduce in a test case w/ a debugger attached (IntelliJ IDEA on Mac). That’s an entirely different network stack compared to my real Jenkins server, though. The real one is running in an Ubuntu VM on Azure.

Absent a deterministic reproduction outside of production, I would be willing to install a custom-instrumented plugin. I don’t know how to build one yet, or what instrumentation I would add anyway.

Unknowns:

1. Does the plugin make an outbound network connection from the Jenkins master or from the worker where the build is running? They may have different network paths.
2. Exactly how much wall time transpires from the start of sendNotifications() to the exception above? (By starting a bunch of jobs and watching a clock, believe 60 seconds.)
3. How to reproduce deterministically?