Response code -1 and response message null when making github API calls

[anirudh2290]

Stacktrace below:

java.net.SocketException: Socket closed

	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.readV3Record(InputRecord.java:593)

	at sun.security.ssl.InputRecord.read(InputRecord.java:532)

	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 okio.Okio$2.read(Okio.java:139)

	at okio.AsyncTimeout$2.read(AsyncTimeout.java:211)

Caused: java.net.SocketTimeoutException: timeout

	at okio.Okio$3.newTimeoutException(Okio.java:207)

	at okio.AsyncTimeout.exit(AsyncTimeout.java:261)

	at okio.AsyncTimeout$2.read(AsyncTimeout.java:215)

	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:306)

	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:300)

	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:196)

	at com.squareup.okhttp.internal.http.Http1xStream.readResponse(Http1xStream.java:186)

	at com.squareup.okhttp.internal.http.Http1xStream.readResponseHeaders(Http1xStream.java:127)

	at com.squareup.okhttp.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:737)

	at com.squareup.okhttp.internal.http.HttpEngine.readResponse(HttpEngine.java:609)

	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:460)

	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:399)

	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:527)

	at com.squareup.okhttp.internal.huc.DelegatingHttpsURLConnection.getResponseCode(DelegatingHttpsURLConnection.java:105)

	at com.squareup.okhttp.internal.huc.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:25)

	at org.kohsuke.github.Requester.parse(Requester.java:615)

Caused: org.kohsuke.github.HttpException: Server returned HTTP response code: -1, message: 'null' for URL: https://api.github.com/repos/apache/incubator-mxnet

	at org.kohsuke.github.Requester.parse(Requester.java:646)

	at org.kohsuke.github.Requester.parse(Requester.java:644)

	at org.kohsuke.github.Requester.parse(Requester.java:644)

	at org.kohsuke.github.Requester.parse(Requester.java:607)

	at org.kohsuke.github.Requester._to(Requester.java:285)

	at org.kohsuke.github.Requester.to(Requester.java:247)

	at org.kohsuke.github.GitHub.getRepository(GitHub.java:475)

	at org.jenkinsci.plugins.github_branch_source.GitHubSCMSource.retrieve(GitHubSCMSource.java:1506)

	at jenkins.scm.api.SCMSource.fetch(SCMSource.java:582)

	at org.jenkinsci.plugins.workflow.multibranch.SCMBinder.create(SCMBinder.java:98)

	at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:293)

	at hudson.model.ResourceController.execute(ResourceController.java:97)

	at hudson.model.Executor.run(Executor.java:429)

Finished: FAILURE

@kohsuke Any ideas ?

[timja]

We get this as well, I think some retry functionality should be added

[bitwiseman]

@timja In what context are you seeing this? Significantly more information needed.

[timja]

Using the github-branch-source-plugin in jenkins is where we see this the most, while checking out shared libraries,

This is the stacktrace:

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 okio.Okio$2.read(Okio.java:139)
	at okio.AsyncTimeout$2.read(AsyncTimeout.java:211)
Caused: java.net.SocketTimeoutException: timeout
	at okio.Okio$3.newTimeoutException(Okio.java:207)
	at okio.AsyncTimeout.exit(AsyncTimeout.java:261)
	at okio.AsyncTimeout$2.read(AsyncTimeout.java:215)
	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:306)
	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:300)
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:196)
	at com.squareup.okhttp.internal.http.Http1xStream.readResponse(Http1xStream.java:186)
	at com.squareup.okhttp.internal.http.Http1xStream.readResponseHeaders(Http1xStream.java:127)
	at com.squareup.okhttp.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:737)
	at com.squareup.okhttp.internal.http.HttpEngine.readResponse(HttpEngine.java:609)
	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:460)
	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:399)
	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:527)
	at com.squareup.okhttp.internal.huc.DelegatingHttpsURLConnection.getResponseCode(DelegatingHttpsURLConnection.java:105)
	at com.squareup.okhttp.internal.huc.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:25)
	at org.kohsuke.github.Requester.parse(Requester.java:615)
Caused: org.kohsuke.github.HttpException: Server returned HTTP response code: -1, message: 'null' for URL: https://api.github.com/repos/timja-org/jenkins-scripted-test/pulls/2
	at org.kohsuke.github.Requester.parse(Requester.java:646)
	at org.kohsuke.github.Requester.parse(Requester.java:644)
	at org.kohsuke.github.Requester.parse(Requester.java:644)
	at org.kohsuke.github.Requester.parse(Requester.java:607)
	at org.kohsuke.github.Requester._to(Requester.java:285)
	at org.kohsuke.github.Requester.to(Requester.java:247)
	at org.kohsuke.github.GHRepository.getPullRequest(GHRepository.java:715)
	at org.jenkinsci.plugins.github_branch_source.GitHubSCMSource.retrieve(GitHubSCMSource.java:1583)
	at jenkins.scm.api.SCMSource.fetch(SCMSource.java:582)
	at org.jenkinsci.plugins.workflow.multibranch.SCMBinder.create(SCMBinder.java:95)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:299)
	at hudson.model.ResourceController.execute(ResourceController.java:97)
	at hudson.model.Executor.run(Executor.java:429)

[timja]

Note that is just on a pull request, but shared library is the most common one we see

[bitwiseman]

@timja
So far, this library has left retries to callers of this library. Do you feel that SocketTimeoutException specifically should retry (or have an option for it), or do you want a general retry functionality?

[timja]

At least timeouts, possibly server errors.
I think it would nicer for the user of Getty was handled transparently.

I could send a PR to GitHub branch source and wrap all calls to this plugin, but I think it would be better to just handle it here for everyone. Exposing some configuration if needed

[timja]

Hmm seems like there's already does it:
https://github.com/github-api/github-api/blob/github-api-1.95/src/main/java/org/kohsuke/github/Requester.java#L642-L646

I don't have the system logs left from when this has happened but I'll keep an eye on it.

(found this when I wrote a wiremock test to show time and this code got invoked)

[bitwiseman]

Have your tried this on a newer version of OkHttp?

[v1v]

I've just faced this issue today:

Expand to view the stacktrace

17:33:15  Started by upstream project "apm-agent-ruby/apm-agent-ruby-mbp/master" build number 182
17:33:15  originally caused by:
17:33:15   Started by user Victor Martinez
17:33:15  [Elastic] Plugin version: 1.4-SNAPSHOT
17:33:15  [Elastic] Generated the Elastic Build ID: 20200120163315-434968F0
17:33:15  [Elastic] Generating Filebeat configuration.
17:33:15  [Elastic] Plugin disabled, not recording the build log.
16:33:15 [2020-01-20T16:33:15.157Z] Connecting to https://api.github.com using apmmachine/****** (GitHub user @apmmachine User + Personal Access Token)
17:33:25  [Elastic] Updating the environment.
17:33:25  [Elastic] Generating the build data for indexing.
17:33:25  [Elastic] Looking for Elastic build metadata in 0 archived artifacts.
17:33:25  [Elastic] No build metadata found.
17:33:25  [Elastic] Looking for JUnit result data.
17:33:25  [Elastic] No JUnit data found.
17:33:25  [Elastic] Writing the build data to the workspace for indexing.
17:33:25  [Elastic] Plugin disabled, not recording the build result.
17:33:25  [Elastic] Done with build 20200120163315-434968F0.
17:33:25  java.net.SocketException: Socket closed
17:33:25  	at java.net.SocketInputStream.read(SocketInputStream.java:204)
17:33:25  	at java.net.SocketInputStream.read(SocketInputStream.java:141)
17:33:25  	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
17:33:25  	at sun.security.ssl.InputRecord.read(InputRecord.java:503)
17:33:25  	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)
17:33:25  	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)
17:33:25  	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
17:33:25  	at okio.Okio$2.read(Okio.java:139)
17:33:25  	at okio.AsyncTimeout$2.read(AsyncTimeout.java:211)
17:33:25  Caused: java.net.SocketTimeoutException: timeout
17:33:25  	at okio.Okio$3.newTimeoutException(Okio.java:207)
17:33:25  	at okio.AsyncTimeout.exit(AsyncTimeout.java:261)
17:33:25  	at okio.AsyncTimeout$2.read(AsyncTimeout.java:215)
17:33:25  	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:306)
17:33:25  	at okio.RealBufferedSource.indexOf(RealBufferedSource.java:300)
17:33:25  	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:196)
17:33:25  	at com.squareup.okhttp.internal.http.Http1xStream.readResponse(Http1xStream.java:186)
17:33:25  	at com.squareup.okhttp.internal.http.Http1xStream.readResponseHeaders(Http1xStream.java:127)
17:33:25  	at com.squareup.okhttp.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:737)
17:33:25  	at com.squareup.okhttp.internal.http.HttpEngine.readResponse(HttpEngine.java:609)
17:33:25  	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:460)
17:33:25  	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:399)
17:33:25  	at com.squareup.okhttp.internal.huc.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:527)
17:33:25  	at com.squareup.okhttp.internal.huc.DelegatingHttpsURLConnection.getResponseCode(DelegatingHttpsURLConnection.java:105)
17:33:25  	at com.squareup.okhttp.internal.huc.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:25)
17:33:25  	at org.kohsuke.github.Requester.parse(Requester.java:615)
17:33:25  Caused: org.kohsuke.github.HttpException: Server returned HTTP response code: -1, message: 'null' for URL: https://api.github.com/repos/elastic/apm-agent-ruby/git/refs/heads/master
17:33:25  	at org.kohsuke.github.Requester.parse(Requester.java:646)
17:33:25  	at org.kohsuke.github.Requester.parse(Requester.java:644)
17:33:25  	at org.kohsuke.github.Requester.parse(Requester.java:644)
17:33:25  	at org.kohsuke.github.Requester.parse(Requester.java:607)
17:33:25  	at org.kohsuke.github.Requester._to(Requester.java:285)
17:33:25  	at org.kohsuke.github.Requester.to(Requester.java:247)
17:33:25  	at org.kohsuke.github.GHRepository.getRef(GHRepository.java:891)
17:33:25  	at org.jenkinsci.plugins.github_branch_source.GitHubSCMSource.retrieve(GitHubSCMSource.java:1598)
17:33:25  	at jenkins.scm.api.SCMSource.fetch(SCMSource.java:582)
17:33:25  	at org.jenkinsci.plugins.workflow.multibranch.SCMBinder.create(SCMBinder.java:98)
17:33:25  	at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:299)
17:33:25  	at hudson.model.ResourceController.execute(ResourceController.java:97)
17:33:25  	at hudson.model.Executor.run(Executor.java:428)
17:33:25  Finished: FAILURE

See build

What kind of details you would like me to provide?

Thanks

[bitwiseman]

@v1v
I think I know what is going on.

This code should be performing a retry:
https://github.com/github-api/github-api/blob/5791843d1633d7ad4c5cfb22c4ac0ee99ea3c083/src/main/java/org/kohsuke/github/Requester.java#L904-L908

However, it isn't actually starting up a new connection, so I'm not sure that it is actually doing anything.

I think the retry logic needs to be moved to https://github.com/github-api/github-api/blob/master/src/main/java/org/kohsuke/github/Requester.java#L496-L497 but I'm don't have high confidence that I won't cause a breaking change while fixing it.

What is needed is some basic mokito tests that cover exception handling in Requester and then we can go in and clean this up.

[v1v]

Based on your analysis, I've just seen the condition is regarding the SocketTimeoutException and the error in the stacktrace refers to SocketException. What's the diff between SocketTimeoutException and SocketException? Does it make sense to add the e instanceof SocketException condition to retry too?

https://github.com/github-api/github-api/blob/5791843d1633d7ad4c5cfb22c4ac0ee99ea3c083/src/main/java/org/kohsuke/github/Requester.java#L905

[bitwiseman]

@v1v
Ah, I see the trace now. Sure, we can add that but ultimately, we're still going fail on

Adding that new exception, I believe this minimum change needed is this:

} catch (IOException e) {
            if (((e instanceof SocketException && e.getCause()  instanceof SocketTimeoutException)  || e instanceof SocketTimeoutException) && timeouts > 0) {
                LOGGER.log(INFO, "timed out accessing " + uc.getURL() + "; will try " + timeouts + " more time(s)", e);
                uc = setupConnection(uc.getURL());
                return parse(type, instance, timeouts - 1);
            }

But like I said, we need test coverage to move forward.