NpmMetaAnalyzer Request Failure

msymons commented 5 years ago

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

stevespringett commented 5 years ago

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

StyleT commented 3 years ago

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

DrakezulsMinimalism commented 3 years ago

I experience the same for

PypiMetaAnalyzer

and

NpmAuditAnalysisTask + NpmMetaAnalyzer

iamrahul127 commented 2 years ago

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)

kabo commented 2 years ago

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

nscuro commented 2 years ago

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.

kabo commented 2 years ago

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.

nscuro commented 2 years ago

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...

DependencyTrack / dependency-track