search

NOAA-OWP / wres

Code and scripts for the Water Resources Evaluation Service
Other
2 stars 1 forks source link

As a user, I want WRES to retry web GET when body processing times out #251

Open epag opened 3 months ago

epag commented 3 months ago

Author Name: Jesse (Jesse) Original Redmine Issue: 88829, https://vlab.noaa.gov/redmine/issues/88829 Original Date: 2021-03-02

Given a web request to data services (e.g. NWIS or WRDS) When the response headers have been returned and the body is processing and a timeout occurs Then WRES should retry the request with backoff similar to the way it would have had an issue occurred during getting the headers So that my evaluation can complete successfully when there are temporary network failures

epag commented 3 months ago

Original Redmine Comment Author Name: Jesse (Jesse) Original Date: 2021-03-02T21:10:46Z

From user report in #88675:

2021-02-26T04:09:38.904+0000 ERROR Main Operation 'execute' completed unsuccessfully
wres.control.InternalWresException: Could not complete project execution
    at wres.control.Control.accept(Control.java:319)
    at wres.control.Control.applyAsInt(Control.java:174)
    at wres.MainFunctions.execute(MainFunctions.java:140)
    at wres.MainFunctions.call(MainFunctions.java:105)
    at wres.Main.main(Main.java:91)
Caused by: wres.control.WresProcessingException: Encountered an error while processing evaluation 'liNlBHY-Vu_Bj_aACBzvIfzjxCc': 
    at wres.control.ProcessorHelper.processEvaluation(ProcessorHelper.java:213)
    at wres.control.Control.accept(Control.java:306)
    ... 4 common frames omitted
Caused by: wres.io.reading.IngestException: An ingest task could not be completed.
    at wres.io.Operations.doIngestWork(Operations.java:432)
    at wres.io.Operations.ingest(Operations.java:344)
    at wres.control.ProcessorHelper.processProjectConfig(ProcessorHelper.java:335)
    at wres.control.ProcessorHelper.processEvaluation(ProcessorHelper.java:155)
    ... 5 common frames omitted
Caused by: java.util.concurrent.CompletionException: wres.io.reading.IngestException: Failed to get web ingest results.
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1702)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: wres.io.reading.IngestException: Failed to get web ingest results.
    at wres.io.reading.WebSource.call(WebSource.java:451)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
    ... 3 common frames omitted
Caused by: java.util.concurrent.ExecutionException: wres.io.concurrency.WRESRunnableException: Callable task failed
    at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at wres.io.reading.WebSource.call(WebSource.java:432)
    ... 4 common frames omitted
Caused by: wres.io.concurrency.WRESRunnableException: Callable task failed
    at wres.io.concurrency.WRESCallable.call(WRESCallable.java:32)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    ... 3 common frames omitted
Caused by: java.io.InterruptedIOException: timeout
    at okhttp3.internal.connection.RealCall.timeoutExit(RealCall.kt:398)
    at okhttp3.internal.connection.RealCall.callDone(RealCall.kt:360)
    at okhttp3.internal.connection.RealCall.messageDone$okhttp(RealCall.kt:309)
    at okhttp3.internal.connection.Exchange.bodyComplete(Exchange.kt:198)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.complete(Exchange.kt:329)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:305)
    at okio.RealBufferedSource$inputStream$1.read(RealBufferedSource.kt:158)
    at java.base/java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:243)
    at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:159)
    at java.base/java.util.zip.GZIPInputStream.read(GZIPInputStream.java:118)
    at java.base/java.io.FilterInputStream.read(FilterInputStream.java:107)
    at org.apache.commons.compress.utils.IOUtils.copy(IOUtils.java:87)
    at org.apache.commons.compress.utils.IOUtils.copy(IOUtils.java:62)
    at org.apache.commons.compress.utils.IOUtils.toByteArray(IOUtils.java:247)
    at wres.io.reading.waterml.WaterMLBasicSource.deserializeInput(WaterMLBasicSource.java:206)
    at wres.io.reading.waterml.WaterMLBasicSource.ingest(WaterMLBasicSource.java:238)
    at wres.io.reading.waterml.WaterMLBasicSource.saveObservation(WaterMLBasicSource.java:133)
    at wres.io.reading.BasicSource.save(BasicSource.java:39)
    at wres.io.concurrency.IngestSaver.execute(IngestSaver.java:502)
    at wres.io.concurrency.IngestSaver.execute(IngestSaver.java:30)
    at wres.io.concurrency.WRESCallable.call(WRESCallable.java:18)
    ... 4 common frames omitted
Caused by: javax.net.ssl.SSLException: Socket closed
    at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:350)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:293)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:288)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:144)
    at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1411)
    at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1376)
    at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:963)
    at okio.InputStreamSource.read(JvmOkio.kt:91)
    at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:129)
    at okio.RealBufferedSource.request(RealBufferedSource.kt:206)
    at okio.RealBufferedSource.require(RealBufferedSource.kt:199)
    at okio.RealBufferedSource.readHexadecimalUnsignedLong(RealBufferedSource.kt:381)
    at okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.readChunkSize(Http1ExchangeCodec.kt:431)
    at okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.kt:410)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:281)
    ... 19 common frames omitted
    Suppressed: java.net.SocketException: Socket closed
        at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
        at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:150)
        at java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSocketOutputRecord.java:81)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:381)
        ... 33 common frames omitted
Caused by: java.net.SocketException: Socket closed
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:183)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:476)
    at java.base/sun.security.ssl.SSLSocketInputRecord.readFully(SSLSocketInputRecord.java:459)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:243)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:181)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:110)
    ... 30 common frames omitted

2021-02-26T04:10:54.652+0000 ERROR Main Operation 'execute' completed unsuccessfully
wres.control.InternalWresException: Could not complete project execution
    at wres.control.Control.accept(Control.java:319)
    at wres.control.Control.applyAsInt(Control.java:174)
    at wres.MainFunctions.execute(MainFunctions.java:140)
    at wres.MainFunctions.call(MainFunctions.java:105)
    at wres.Main.main(Main.java:91)
Caused by: wres.control.WresProcessingException: Encountered an error while processing evaluation 'soxG4sqxNgKE17mkjaQ9xbB8HX4': 
    at wres.control.ProcessorHelper.processEvaluation(ProcessorHelper.java:213)
    at wres.control.Control.accept(Control.java:306)
    ... 4 common frames omitted
Caused by: wres.io.reading.IngestException: An ingest task could not be completed.
    at wres.io.Operations.doIngestWork(Operations.java:432)
    at wres.io.Operations.ingest(Operations.java:344)
    at wres.control.ProcessorHelper.processProjectConfig(ProcessorHelper.java:335)
    at wres.control.ProcessorHelper.processEvaluation(ProcessorHelper.java:155)
    ... 5 common frames omitted
Caused by: java.util.concurrent.CompletionException: wres.io.reading.IngestException: Failed to get web ingest results.
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1702)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: wres.io.reading.IngestException: Failed to get web ingest results.
    at wres.io.reading.WebSource.call(WebSource.java:451)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
    ... 3 common frames omitted
Caused by: java.util.concurrent.ExecutionException: wres.io.concurrency.WRESRunnableException: Callable task failed
    at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at wres.io.reading.WebSource.call(WebSource.java:432)
    ... 4 common frames omitted
Caused by: wres.io.concurrency.WRESRunnableException: Callable task failed
    at wres.io.concurrency.WRESCallable.call(WRESCallable.java:32)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    ... 3 common frames omitted
Caused by: java.io.InterruptedIOException: timeout
    at okhttp3.internal.connection.RealCall.timeoutExit(RealCall.kt:398)
    at okhttp3.internal.connection.RealCall.callDone(RealCall.kt:360)
    at okhttp3.internal.connection.RealCall.messageDone$okhttp(RealCall.kt:309)
    at okhttp3.internal.connection.Exchange.bodyComplete(Exchange.kt:198)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.complete(Exchange.kt:329)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:305)
    at okio.RealBufferedSource$inputStream$1.read(RealBufferedSource.kt:158)
    at java.base/java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:243)
    at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:159)
    at java.base/java.util.zip.GZIPInputStream.read(GZIPInputStream.java:118)
    at java.base/java.io.FilterInputStream.read(FilterInputStream.java:107)
    at org.apache.commons.compress.utils.IOUtils.copy(IOUtils.java:87)
    at org.apache.commons.compress.utils.IOUtils.copy(IOUtils.java:62)
    at org.apache.commons.compress.utils.IOUtils.toByteArray(IOUtils.java:247)
    at wres.io.reading.waterml.WaterMLBasicSource.deserializeInput(WaterMLBasicSource.java:206)
    at wres.io.reading.waterml.WaterMLBasicSource.ingest(WaterMLBasicSource.java:238)
    at wres.io.reading.waterml.WaterMLBasicSource.saveObservation(WaterMLBasicSource.java:133)
    at wres.io.reading.BasicSource.save(BasicSource.java:39)
    at wres.io.concurrency.IngestSaver.execute(IngestSaver.java:502)
    at wres.io.concurrency.IngestSaver.execute(IngestSaver.java:30)
    at wres.io.concurrency.WRESCallable.call(WRESCallable.java:18)
    ... 4 common frames omitted
Caused by: javax.net.ssl.SSLException: Socket closed
    at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:350)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:293)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:288)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:144)
    at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1411)
    at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1376)
    at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:963)
    at okio.InputStreamSource.read(JvmOkio.kt:91)
    at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:129)
    at okio.RealBufferedSource.read(RealBufferedSource.kt:189)
    at okhttp3.internal.http1.Http1ExchangeCodec$AbstractSource.read(Http1ExchangeCodec.kt:333)
    at okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.kt:414)
    at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:281)
    ... 19 common frames omitted
    Suppressed: java.net.SocketException: Socket closed
        at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
        at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:150)
        at java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSocketOutputRecord.java:81)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:381)
        ... 31 common frames omitted
Caused by: java.net.SocketException: Socket closed
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:183)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:476)
    at java.base/sun.security.ssl.SSLSocketInputRecord.readFully(SSLSocketInputRecord.java:459)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:243)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:181)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:110)
    ... 28 common frames omitted

Both appear to be the same stack trace: timeout (edit: or socket closed) when processing NWIS response body. Both appear to be within the same (edit: two) minutes: around 2021-02-26T04:10 or 2021-02-26T22:10-0600.