intermittent getBlob exception #303

kahing · 2019-06-06T18:29:21Z

I haven't narrowed down what triggers this yet, but goofys CI tests trigger this (unclear which test):

java.util.NoSuchElementException: null
        at java.util.ArrayDeque.removeFirst(ArrayDeque.java:285)
        at com.google.common.io.Closer.close(Closer.java:212)
        at org.jclouds.util.Closeables2.closeQuietly(Closeables2.java:40)
        at org.jclouds.io.payloads.ByteSourcePayload.release(ByteSourcePayload.java:52)
        at org.jclouds.http.internal.PayloadEnclosingImpl.setPayload(PayloadEnclosingImpl.java:56)
        at org.jclouds.blobstore.domain.internal.BlobImpl.setPayload(BlobImpl.java:114)
        at org.jclouds.http.internal.PayloadEnclosingImpl.setPayload(PayloadEnclosingImpl.java:97)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:723)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
        at com.sun.proxy.$Proxy40.getBlob(Unknown Source)
        at org.gaul.s3proxy.S3ProxyHandler.handleGetBlob(S3ProxyHandler.java:1640)
        at org.gaul.s3proxy.S3ProxyHandler.doHandle(S3ProxyHandler.java:673)
        at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:70)
        at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
        at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
        at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
        at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
        at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
        at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
        at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
        at java.lang.Thread.run(Thread.java:748)

The text was updated successfully, but these errors were encountered:

gaul · 2019-06-06T19:49:03Z

This is an interesting stack trace! Closer raises an exception in removeFirst below:

    while (!stack.isEmpty()) {
      Closeable closeable = stack.removeFirst();

Closer.register protects against null elements so one would assume that this is impossible without concurrent modification. Yet only a single thread should ever handle this...

kahing · 2019-09-12T06:09:56Z

another one with a different backtrace:

[s3proxy] W 09-12 05:33:33.879 S3Proxy-Jetty-28 o.g.s.o.e.j.server.HttpChannel:396 |::] /goofys-test-a0gh6o5fe00nh9qu/testLargeFile
java.lang.IllegalStateException: STREAM
	at org.gaul.shaded.org.eclipse.jetty.server.Response.getWriter(Response.java:910)
	at org.gaul.s3proxy.S3ProxyHandler.sendSimpleErrorResponse(S3ProxyHandler.java:2864)
	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:146)
	at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
	at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.base/java.lang.Thread.run(Thread.java:834)

This one causes the test to be stuck: https://travis-ci.org/kahing/goofys/jobs/583981057#L11071

gaul · 2019-09-12T19:46:26Z

Does this also happen in getBlob or another operation? The stack trace looks like one of the handlers called getWriter and while emitting some XML it throws an S3Exception. The handler closes the Writer and sendSimpleErrorResponse attempts to reopen it but fails. If you can reproduce this, adding a printStaceTrace will reveal the cause.

gaul · 2019-09-12T19:48:53Z

Actually the line

	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:146)

reveals the cause, a TimeoutException, likely from the client. In this case we need more robust handling, first figure out if the stream has be opened and conditionally call into sendSimpleErrorResponse.

gaul · 2019-09-12T21:32:09Z

It looks like sendSimpleErrorResponse should check ServletResponse.isCommitted:

https://docs.oracle.com/javaee/6/api/javax/servlet/ServletResponse.html#isCommitted()

If an error occurs when writing the body of a response, e.g., TimeoutException, previously S3Proxy would try to emit the AWS error code. Since this stream was already opened and closed, this failed and Jetty emitted this warning: Could not send response error 500: java.lang.IllegalStateException: STREAM References #303.

gaul · 2020-07-11T08:08:13Z

Similar symptom seen in s3fs CI:

[s3proxy] W 07-09 12:54:28.324 S3Proxy-Jetty-95 o.g.s.o.e.j.server.HttpChannel:396 |::] /s3fs-integration-test/testrun-7332/big-file-s3fs.txt
java.lang.ArrayIndexOutOfBoundsException: -662657112
	at java.util.ArrayDeque.addFirst(ArrayDeque.java:227)
	at com.google.common.io.Closer.register(Closer.java:126)
	at org.jclouds.io.payloads.ByteSourcePayload.openStream(ByteSourcePayload.java:39)
	at org.jclouds.blobstore.config.LocalBlobStore.copyBlob(LocalBlobStore.java:759)
	at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:677)
	at sun.reflect.GeneratedMethodAccessor17.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
	at com.sun.proxy.$Proxy40.getBlob(Unknown Source)
	at org.gaul.s3proxy.S3ProxyHandler.handleGetBlob(S3ProxyHandler.java:1712)
	at org.gaul.s3proxy.S3ProxyHandler.doHandle(S3ProxyHandler.java:684)
	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:76)
	at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
	at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)

This avoids a race condition due to sharing the same Closer instance and unbounded growth of its Closeable Deque. References gaul/s3proxy#303.

gaul · 2021-06-01T01:32:11Z

Fixed in S3Proxy 1.8.0.

gaul · 2022-07-24T12:16:01Z

I still see this with S3Proxy 2.0.0:

java.lang.ArrayIndexOutOfBoundsException: Index 12 out of bounds for length 12
        at java.base/java.util.ArrayDeque.grow(ArrayDeque.java:158)
        at java.base/java.util.ArrayDeque.addFirst(ArrayDeque.java:290)
        at com.google.common.io.Closer.register(Closer.java:126)
        at org.jclouds.io.payloads.ByteSourcePayload.openStream(ByteSourcePayload.java:39)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:741)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:205)
        at org.jclouds.blobstore.config.LocalBlobStore.blobMetadata(LocalBlobStore.java:762)

Closer is not thread safe and lack of synchronization can throw ArrayIndexOutOfBoundsExceptions. Fixes gaul/s3proxy#303.

ByteSourcePayload's.openStream is not thread safe and lack of synchronization can throw ArrayIndexOutOfBoundsExceptions. Fixes gaul/s3proxy#303.

ByteSourcePayload.openStream is not thread safe and lack of synchronization can throw ArrayIndexOutOfBoundsExceptions. Instead deep copy the underlying Payload. Fixes gaul/s3proxy#303.

gaul · 2022-08-08T02:31:34Z

Needs jclouds 2.6.0 upgrade.

gaul changed the title ~~intermitten GetBlob exception~~ intermittent getBlob exception Jun 8, 2019

gaul mentioned this issue Jul 9, 2020

Fix NULL pointer deference s3fs-fuse/s3fs-fuse#1329

Merged

asfgit pushed a commit to apache/jclouds that referenced this issue Jul 11, 2020

Store transient Blob data with ByteArrayPayload

8de7b69

This avoids a race condition due to sharing the same Closer instance and unbounded growth of its Closeable Deque. References gaul/s3proxy#303.

gaul mentioned this issue Sep 21, 2020

Configure Travis with Ubuntu Xenial s3fs-fuse/s3fs-fuse#1412

Closed

gaul closed this as completed Jun 1, 2021

gaul reopened this Jul 24, 2022

gaul added a commit to gaul/jclouds-1 that referenced this issue Jul 24, 2022

Synchronize ByteSourcePayload Closer methods

a473c70

Closer is not thread safe and lack of synchronization can throw ArrayIndexOutOfBoundsExceptions. Fixes gaul/s3proxy#303.

gaul mentioned this issue Jul 24, 2022

Synchronize ByteSourcePayload in LocalBlobStore apache/jclouds#146

Closed

gaul added a commit to gaul/jclouds-1 that referenced this issue Jul 30, 2022

Synchronize ByteSourcePayload in LocalBlobStore

dea756a

ByteSourcePayload's.openStream is not thread safe and lack of synchronization can throw ArrayIndexOutOfBoundsExceptions. Fixes gaul/s3proxy#303.

gaul mentioned this issue Aug 1, 2022

Deep copy Blob in LocalBlobStore.getBlob apache/jclouds#150

Merged

gaul closed this as completed in apache/jclouds#150 Aug 4, 2022

gaul reopened this Aug 8, 2022

gaul mentioned this issue Jul 14, 2023

Explicitly handle CommonPrefixes with nocompat_dir s3fs-fuse/s3fs-fuse#2212

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

intermittent getBlob exception #303

intermittent getBlob exception #303

kahing commented Jun 6, 2019

gaul commented Jun 6, 2019 •

edited

Loading

kahing commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Jul 11, 2020

gaul commented Jun 1, 2021

gaul commented Jul 24, 2022

gaul commented Aug 8, 2022

intermittent getBlob exception #303

intermittent getBlob exception #303

Comments

kahing commented Jun 6, 2019

gaul commented Jun 6, 2019 • edited Loading

kahing commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Sep 12, 2019

gaul commented Jul 11, 2020

gaul commented Jun 1, 2021

gaul commented Jul 24, 2022

gaul commented Aug 8, 2022

gaul commented Jun 6, 2019 •

edited

Loading