dependency-track icon indicating copy to clipboard operation
dependency-track copied to clipboard
verified publisher icon DependencyTrack

NpmMetaAnalyzer Request Failure

Open msymons opened this issue 6 years ago • 8 comments

Current Behavior:

I have continious Dependency-Track logs going back to 14 May 2019 (when I was running v3.4.1).

Starting one hour after upgrade from 3.4.1 to 3.5.0 on 7 June, the logs show (for me) 748 occurrences of:

2019-06-07 11:39:24,654 [] ERROR [org.dependencytrack.tasks.repositories.NpmMetaAnalyzer] Request failure
kong.unirest.UnirestException: java.net.SocketTimeoutException: Read timed out

There is no logging for NpmMetaAnalyzer before upgrade to 3.5.0 and no logging after upgrade that is not a Request failure ERROR.

The errors all seem to occur around the middle of the day (UTC), with sometimes just 2 or 3 per day and sometimes as many as 10.

Steps to Reproduce:

Search logs for NpmMetaAnalyzer]

Expected Behavior:

Log events for NpmMetaAnalyzer should not be associated with "Request failure" & SocketTimeoutException

Environment:

  • Dependency-Track Version: 3.6.0
  • Distribution: [ Executable WAR ]
  • BOM Format & Version: CycloneDX 1.1
  • Database Server: [ PostgreSQL ]
  • Browser: Firefox 69.0.2

Additional Details:

From today's log (running DT 3.6.0):

2019-10-09 14:19:49,845 [] ERROR [org.dependencytrack.tasks.repositories.NpmMetaAnalyzer] Request failure
kong.unirest.UnirestException: java.net.SocketTimeoutException: Read timed out
	at kong.unirest.apache.ApacheClient.request(ApacheClient.java:133)
	at kong.unirest.BaseRequest.asJson(BaseRequest.java:213)
	at org.dependencytrack.tasks.repositories.NpmMetaAnalyzer.analyze(NpmMetaAnalyzer.java:80)
	at org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask.analyze(RepositoryMetaAnalyzerTask.java:87)
	at org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask.inform(RepositoryMetaAnalyzerTask.java:70)
	at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:97)
	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:983)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)
	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:261)
	at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165)
	at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
	at kong.unirest.apache.ApacheClient.request(ApacheClient.java:125)
	... 8 common frames omitted

msymons avatar Oct 10 '19 15:10 msymons

Note to self. Ensure that all meta analyzers have info and debug logging options

stevespringett avatar Oct 10 '19 15:10 stevespringett

Hi! Almost the same issue here, DTrack 4.3.4.

13:17:53.764 ERROR [NpmMetaAnalyzer] Request failure
kong.unirest.UnirestException: javax.net.ssl.SSLException: Connection reset
at kong.unirest.DefaultInterceptor.onFail(DefaultInterceptor.java:43)
at kong.unirest.CompoundInterceptor.lambda$onFail$2(CompoundInterceptor.java:54)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
at java.base/java.util.Collections$2.tryAdvance(Unknown Source)
at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
at java.base/java.util.stream.FindOps$FindOp.evaluateSequential(Unknown Source)
at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
at java.base/java.util.stream.ReferencePipeline.findFirst(Unknown Source)
at kong.unirest.CompoundInterceptor.onFail(CompoundInterceptor.java:56)
at kong.unirest.apache.ApacheClient.request(ApacheClient.java:132)
at kong.unirest.Client.request(Client.java:57)
at kong.unirest.BaseRequest.asJson(BaseRequest.java:241)
at org.dependencytrack.tasks.repositories.NpmMetaAnalyzer.analyze(NpmMetaAnalyzer.java:80)
at org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask.analyze(RepositoryMetaAnalyzerTask.java:84)
at org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask.inform(RepositoryMetaAnalyzerTask.java:58)
at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:99)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: javax.net.ssl.SSLException: Connection reset
at java.base/sun.security.ssl.Alert.createSSLException(Unknown Source)
at java.base/sun.security.ssl.TransportContext.fatal(Unknown Source)
at java.base/sun.security.ssl.TransportContext.fatal(Unknown Source)
at java.base/sun.security.ssl.TransportContext.fatal(Unknown Source)
at java.base/sun.security.ssl.SSLSocketImpl.handleException(Unknown Source)
at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(Unknown Source)
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:280)
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:157)
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:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:118)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
at kong.unirest.apache.ApacheClient.request(ApacheClient.java:123)
... 9 common frames omitted
Suppressed: java.net.SocketException: Broken pipe (Write failed)
at java.base/java.net.SocketOutputStream.socketWrite0(Native Method)
at java.base/java.net.SocketOutputStream.socketWrite(Unknown Source)
at java.base/java.net.SocketOutputStream.write(Unknown Source)
at java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(Unknown Source)
... 32 common frames omitted
Caused by: java.net.SocketException: Connection reset
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.read(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(Unknown Source)
at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(Unknown Source)
... 28 common frames omitted

StyleT avatar Sep 10 '21 13:09 StyleT

I experience the same for

PypiMetaAnalyzer

and

NpmAuditAnalysisTask + NpmMetaAnalyzer

DrakezulsMinimalism avatar Nov 08 '21 10:11 DrakezulsMinimalism

I also see same error. Can someone at least confirm if this is serious issue and impacts analysis?

2022-01-04T08:00:06+05:30 02:30:06.792 INFO [NpmAuditAnalysisTask] Analyzing 119 component(s)
2022-01-04T08:00:06+05:30 02:30:06.794 ERROR [NpmAuditAnalysisTask] Request failure
2022-01-04T08:00:06+05:30 kong.unirest.UnirestException: java.net.SocketException: Connection reset
2022-01-04T08:00:06+05:30 	at kong.unirest.DefaultInterceptor.onFail(DefaultInterceptor.java:43)
2022-01-04T08:00:06+05:30 	at kong.unirest.CompoundInterceptor.lambda$onFail$2(CompoundInterceptor.java:54)

iamrahul127 avatar Jan 04 '22 07:01 iamrahul127

We're also seeing this issue, DT v4.5

kabo avatar Sep 09 '22 10:09 kabo

For everyone being affected by this, could you please share:

  • Whether you have configured DT to use a proxy
  • How often you see this error; Does it only occur sometimes? Regularly?
  • Can you correlate this happening with situations where DT is doing a lot of analyses in parallel? Or does it happen randomly?

When I google for the NPM registry doing connection resets, I'm getting a lot of results that also affect native NPM tooling. Maybe we need a circuit breaker or at least a form of retry to deal with the registry being a little unreliable at times.

nscuro avatar Sep 09 '22 11:09 nscuro

  • DT is not using a proxy for outgoing requests
  • It does appear to come and go, when it happens it happens a lot, and then it's fine for hours
  • we have 640+ projects in DT, most of them javascript/typescript

Not sure if it's related or not, but I did try setting ALPINE_HTTP_TIMEOUT_CONNECTION and ALPINE_HTTP_TIMEOUT_SOCKET to 5, and ALPINE_HTTP_TIMEOUT_POOL to 10. The issue seems to have gone away, but it may just be coincidence, too soon to tell.

kabo avatar Sep 10 '22 00:09 kabo

Thanks.

Not sure if it's related or not, but I did try setting ALPINE_HTTP_TIMEOUT_CONNECTION and ALPINE_HTTP_TIMEOUT_SOCKET to 5, and ALPINE_HTTP_TIMEOUT_POOL to 10. The issue seems to have gone away, but it may just be coincidence, too soon to tell.

Highly unlikely. To my understanding Connection reset means that the other party (the NPM registry) actively decided to drop the connection. Maybe they do this for clients that cause excessive traffic in a short time...

nscuro avatar Sep 10 '22 13:09 nscuro