Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
I opened a pull request:
https://github.com/apache/jclouds/pull/94
On Fri, Jan 08, 2021 at 10:01:56AM +0900, Andrew Gaul wrote:
> Hi John, the code in LocalBlobStore.putBlob looks like this:
>
> String eTag = storageStrategy.putBlob(containerName, blob);
> setBlobAccess(containerName, blobKey, options.getBlobAccess());
>
> I suspect that the object is being removed by another client in between
> these calls. Instead FilesystemStorageStrategyImp.putBlob should allow
> an options parameter to set the blobAccess on the temporary file which
> then gets renamed to the real file name. Would you like to submit a PR
> for this?
>
> On Thu, Jan 07, 2021 at 10:09:29PM -, John Calcote wrote:
> > We use the filesystem (LocalBlobStore) implementation for integration
> > testing in our code.
> >
> > I'm seeing the following behavior in version 2.2.1 which I recently
> > upgraded to:
> >
> > ```
> > 2021-01-07 20:03:43.503,7964896021968234 {} DEBUG
> > c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> > (data) chunk [0-1048575] - uploading
> > 2021-01-07 20:03:43.575,7964896093429743 {} DEBUG
> > o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating
> > container test-container
> > 2021-01-07 20:03:43.575,7964896093478721 {} DEBUG
> > o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating
> > directory //tmp/16100498223118761388361431415820/test-container
> > 2021-01-07 20:03:43.575,7964896093881924 {} DEBUG
> > c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> > (data) chunk [1048576-2097151] - checksummed
> > checksum=D8ACDD71E006E090F4FBF32CAF0627A3
> > 2021-01-07 20:03:43.575,7964896093909591 {} DEBUG
> > c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> > (data) chunk [1048576-2097151] - uploading
> > ..
> > 2021-01-07 20:03:43.576,7964896094167857 {} DEBUG o.j.b.c.LocalBlobStore
> > [cloud-normalpri-0] Put blob with key [byHashV1/0001001020
> > B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> > container [test-container]
> > ..
> > 2021-01-07 20:03:43.577,7964896095288960 {} DEBUG o.j.b.c.LocalBlobStore
> > [cloud-normalpri-0] Put blob with key [byHashV1/0001001020
> > B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> > container [test-container]
> > ..
> > 2021-01-07 20:03:43.584,7964896102791478 {} DEBUG o.j.b.c.LocalBlobStore
> > [cloud-normalpri-1] Put blob with key [byHashV1/0001001020
> > B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> > container [test-container]
> > ..
> > 2021-01-07 20:03:43.597,7964896115564074 {} DEBUG o.j.b.c.LocalBlobStore
> > [cloud-normalpri-1] Put blob with key [byHashV1/0001001020
> > B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> > container [test-container]
> > ..
> > 2021-01-07 20:03:43.605,7964896123355487 {} ERROR
> > c.p.d.m.j.AbstractUploadCallable [cloud-normalpri-0] [task 1] Upload
> > failed: chunk [1048576-2097151] - uploading
> > java.lang.RuntimeException: java.nio.file.NoSuchFileException:
> > /tmp/16100498223118761388361431415820/test-container/byHashV1/0001001020
> > B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3
> > at com.google.common.base.Throwables.propagate(Throwables.java:240)
> > ~[guava-21.0.jar:?]
> > at
> > org.jclouds.filesystem.strategy.internal.FilesystemStorageStrategyImpl.setBlobAccess(FilesystemStorageStrategyImpl.java:694)
> > ~[filesystem-2.2.1.jar:2.2.1]
> > at
> > org.jclouds.blobstore.config.LocalBlobStore.setBlobAccess(LocalBlobStore.java:409)
> > ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> > at
> > org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:794)
> > ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> > at
> > org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:533)
> > ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> > at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
> > ~[?:?]
> > at
> > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > ~[?:1.8.0_181]
> > at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_181]
> > at
> > com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
> > ~[guice-3.0.jar:?]
> > at com.sun.proxy.$Proxy66.putBlob(Unknown Source) ~[?:?]
> > at
> > com.hammerspace.csp.rest.client.jclouds.JCloudsCspRestClient$1UploadRunnable.run(JCloudsCspRestClient.java:454)
> > [csp-rest-client-4.5.1.jar:?]
> > at
> > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> > [?:1.8.0_181]
> > at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> > [?:1.8.0_181]
> > at
> >
Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
I looked over the code changes myself and I agree with you. It's unlikely anything in jclouds is causing this error. I'm currently investigating issues without build system where the tmp directory may be close to full or some other space/perms-related issue. Thanks, John
Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
I looked through:
git log upstream/2.2.x blobstore/
git log upstream/2.2.x apis/filesystem/
But there are only a few changes and I do not believe that these commits
could cause your symptoms. You could try bisecting to be sure. Given
that my suggested race condition is so easy to fix I would try that
though and in any case it would help the project.
On Fri, Jan 08, 2021 at 05:49:17PM -, John Calcote wrote:
> Hi Andrew,
>
> Your theory about another client deleting the file cannot be correct. This is
> an integration test where a single test is running - the container is created
> in /tmp//test-container. The test creates the test
> container in the setup method, uploads several files, manipulates some data,
> and then deletes the entire container in the teardown method.
>
> This is the very first file added, and the test-container itself was created
> milliseconds earlier. There are no other clients running at this time. If you
> look back at the log snippet I pasted, you'll see that the log line
>
> 2021-01-07 20:03:43.576,7964896094167857 {} DEBUG o.j.b.c.LocalBlobStore
> [cloud-normalpri-0] Put blob with key [byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> container [test-container]
>
> which is logged by jclouds filesystem impl is logged four times in a row
> (because jclouds is retrying under the covers for us, as we use Payload style
> payloads, which are retriable). Only the last error is logged ultimately, but
> it's clear this error is happening at least four times in quick succession
> before jclouds gives up and throws the exception (which we log).
>
> Just prior to this log line, jclouds logs the creation of the container and
> the test-container directory.
>
> We upgraded from 2.2.0 to 2.2.1 recently and this started happening. The test
> has been in place for years, without seeing this issue. Suddenly, after
> upgrading, it starts happening.
>
> Thanks,
> John
--
Andrew Gaul
http://gaul.org/
Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
Hi Andrew,
Your theory about another client deleting the file cannot be correct. This is
an integration test where a single test is running - the container is created
in /tmp//test-container. The test creates the test
container in the setup method, uploads several files, manipulates some data,
and then deletes the entire container in the teardown method.
This is the very first file added, and the test-container itself was created
milliseconds earlier. There are no other clients running at this time. If you
look back at the log snippet I pasted, you'll see that the log line
2021-01-07 20:03:43.576,7964896094167857 {} DEBUG o.j.b.c.LocalBlobStore
[cloud-normalpri-0] Put blob with key [byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to container
[test-container]
which is logged by jclouds filesystem impl is logged four times in a row
(because jclouds is retrying under the covers for us, as we use Payload style
payloads, which are retriable). Only the last error is logged ultimately, but
it's clear this error is happening at least four times in quick succession
before jclouds gives up and throws the exception (which we log).
Just prior to this log line, jclouds logs the creation of the container and the
test-container directory.
We upgraded from 2.2.0 to 2.2.1 recently and this started happening. The test
has been in place for years, without seeing this issue. Suddenly, after
upgrading, it starts happening.
Thanks,
John
Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
Hi John, the code in LocalBlobStore.putBlob looks like this:
String eTag = storageStrategy.putBlob(containerName, blob);
setBlobAccess(containerName, blobKey, options.getBlobAccess());
I suspect that the object is being removed by another client in between
these calls. Instead FilesystemStorageStrategyImp.putBlob should allow
an options parameter to set the blobAccess on the temporary file which
then gets renamed to the real file name. Would you like to submit a PR
for this?
On Thu, Jan 07, 2021 at 10:09:29PM -, John Calcote wrote:
> We use the filesystem (LocalBlobStore) implementation for integration testing
> in our code.
>
> I'm seeing the following behavior in version 2.2.1 which I recently upgraded
> to:
>
> ```
> 2021-01-07 20:03:43.503,7964896021968234 {} DEBUG
> c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> (data) chunk [0-1048575] - uploading
> 2021-01-07 20:03:43.575,7964896093429743 {} DEBUG
> o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating container
> test-container
> 2021-01-07 20:03:43.575,7964896093478721 {} DEBUG
> o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating directory
> //tmp/16100498223118761388361431415820/test-container
> 2021-01-07 20:03:43.575,7964896093881924 {} DEBUG
> c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> (data) chunk [1048576-2097151] - checksummed
> checksum=D8ACDD71E006E090F4FBF32CAF0627A3
> 2021-01-07 20:03:43.575,7964896093909591 {} DEBUG
> c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
> (data) chunk [1048576-2097151] - uploading
> ..
> 2021-01-07 20:03:43.576,7964896094167857 {} DEBUG o.j.b.c.LocalBlobStore
> [cloud-normalpri-0] Put blob with key [byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> container [test-container]
> ..
> 2021-01-07 20:03:43.577,7964896095288960 {} DEBUG o.j.b.c.LocalBlobStore
> [cloud-normalpri-0] Put blob with key [byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> container [test-container]
> ..
> 2021-01-07 20:03:43.584,7964896102791478 {} DEBUG o.j.b.c.LocalBlobStore
> [cloud-normalpri-1] Put blob with key [byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> container [test-container]
> ..
> 2021-01-07 20:03:43.597,7964896115564074 {} DEBUG o.j.b.c.LocalBlobStore
> [cloud-normalpri-1] Put blob with key [byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to
> container [test-container]
> ..
> 2021-01-07 20:03:43.605,7964896123355487 {} ERROR
> c.p.d.m.j.AbstractUploadCallable [cloud-normalpri-0] [task 1] Upload failed:
> chunk [1048576-2097151] - uploading
> java.lang.RuntimeException: java.nio.file.NoSuchFileException:
> /tmp/16100498223118761388361431415820/test-container/byHashV1/0001001020
> B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3
> at com.google.common.base.Throwables.propagate(Throwables.java:240)
> ~[guava-21.0.jar:?]
> at
> org.jclouds.filesystem.strategy.internal.FilesystemStorageStrategyImpl.setBlobAccess(FilesystemStorageStrategyImpl.java:694)
> ~[filesystem-2.2.1.jar:2.2.1]
> at
> org.jclouds.blobstore.config.LocalBlobStore.setBlobAccess(LocalBlobStore.java:409)
> ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> at
> org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:794)
> ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> at
> org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:533)
> ~[jclouds-blobstore-2.2.1.jar:2.2.1]
> at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source) ~[?:?]
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> ~[?:1.8.0_181]
> at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_181]
> at
> com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
> ~[guice-3.0.jar:?]
> at com.sun.proxy.$Proxy66.putBlob(Unknown Source) ~[?:?]
> at
> com.hammerspace.csp.rest.client.jclouds.JCloudsCspRestClient$1UploadRunnable.run(JCloudsCspRestClient.java:454)
> [csp-rest-client-4.5.1.jar:?]
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> [?:1.8.0_181]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> [?:1.8.0_181]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> [?:1.8.0_181]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> [?:1.8.0_181]
> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
> Caused by: java.nio.file.NoSuchFileException:
>
Re: filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
One more comment - it's an intermittent failure. Sometimes it works, sometimes not.
filesystem (LocalBlobStore) failing intermittently on initial "upload" in v2.2.1
We use the filesystem (LocalBlobStore) implementation for integration testing
in our code.
I'm seeing the following behavior in version 2.2.1 which I recently upgraded to:
```
2021-01-07 20:03:43.503,7964896021968234 {} DEBUG
c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
(data) chunk [0-1048575] - uploading
2021-01-07 20:03:43.575,7964896093429743 {} DEBUG
o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating container
test-container
2021-01-07 20:03:43.575,7964896093478721 {} DEBUG
o.j.f.s.i.FilesystemStorageStrategyImpl [cpu-normalpri-1] Creating directory
//tmp/16100498223118761388361431415820/test-container
2021-01-07 20:03:43.575,7964896093881924 {} DEBUG
c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
(data) chunk [1048576-2097151] - checksummed
checksum=D8ACDD71E006E090F4FBF32CAF0627A3
2021-01-07 20:03:43.575,7964896093909591 {} DEBUG
c.p.d.m.j.AbstractUploadCallable [cpu-normalpri-1] [task 1] State change:
(data) chunk [1048576-2097151] - uploading
..
2021-01-07 20:03:43.576,7964896094167857 {} DEBUG o.j.b.c.LocalBlobStore
[cloud-normalpri-0] Put blob with key [byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to container
[test-container]
..
2021-01-07 20:03:43.577,7964896095288960 {} DEBUG o.j.b.c.LocalBlobStore
[cloud-normalpri-0] Put blob with key [byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to container
[test-container]
..
2021-01-07 20:03:43.584,7964896102791478 {} DEBUG o.j.b.c.LocalBlobStore
[cloud-normalpri-1] Put blob with key [byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to container
[test-container]
..
2021-01-07 20:03:43.597,7964896115564074 {} DEBUG o.j.b.c.LocalBlobStore
[cloud-normalpri-1] Put blob with key [byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3 ] to container
[test-container]
..
2021-01-07 20:03:43.605,7964896123355487 {} ERROR
c.p.d.m.j.AbstractUploadCallable [cloud-normalpri-0] [task 1] Upload failed:
chunk [1048576-2097151] - uploading
java.lang.RuntimeException: java.nio.file.NoSuchFileException:
/tmp/16100498223118761388361431415820/test-container/byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3
at com.google.common.base.Throwables.propagate(Throwables.java:240)
~[guava-21.0.jar:?]
at
org.jclouds.filesystem.strategy.internal.FilesystemStorageStrategyImpl.setBlobAccess(FilesystemStorageStrategyImpl.java:694)
~[filesystem-2.2.1.jar:2.2.1]
at
org.jclouds.blobstore.config.LocalBlobStore.setBlobAccess(LocalBlobStore.java:409)
~[jclouds-blobstore-2.2.1.jar:2.2.1]
at
org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:794)
~[jclouds-blobstore-2.2.1.jar:2.2.1]
at
org.jclouds.blobstore.config.LocalBlobStore.putBlob(LocalBlobStore.java:533)
~[jclouds-blobstore-2.2.1.jar:2.2.1]
at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source) ~[?:?]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_181]
at
com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
~[guice-3.0.jar:?]
at com.sun.proxy.$Proxy66.putBlob(Unknown Source) ~[?:?]
at
com.hammerspace.csp.rest.client.jclouds.JCloudsCspRestClient$1UploadRunnable.run(JCloudsCspRestClient.java:454)
[csp-rest-client-4.5.1.jar:?]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[?:1.8.0_181]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_181]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_181]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_181]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
Caused by: java.nio.file.NoSuchFileException:
/tmp/16100498223118761388361431415820/test-container/byHashV1/0001001020
B3A2D81C390E0531DBCF0DEC082C4CA96D26F26AA9A26A26E80B5F00FA9F48E3
at
sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
~[?:1.8.0_181]
at
sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
~[?:1.8.0_181]
at
sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
~[?:1.8.0_181]
at
sun.nio.fs.UnixFileAttributeViews$Posix.readAttributes(UnixFileAttributeViews.java:218)
~[?:1.8.0_181]
at
sun.nio.fs.UnixFileAttributeViews$Posix.readAttributes(UnixFileAttributeViews.java:131)
~[?:1.8.0_181]
at
sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:144)
~[?:1.8.0_181]
at
