Google cloud storage insufficient data written

[eLod]

We have a secor setup where everything works with s3, but when switching to GS it throws

2016-02-11 23:45:10,502 [Thread-3] (com.pinterest.secor.common.FileRegistry:162) INFO  Deleting writer for path /data/secor/message_logs/partition/30946_12/organic-impressions/dt=2016-02-04/1_0_00000000000025099615
2016-02-11 23:45:10,503 [Thread-3] (com.pinterest.secor.uploader.GsUploadManager:73) INFO  uploading file /data/secor/message_logs/partition/30946_12/organic-impressions/dt=2016-02-04/1_0_00000000000025099615 to gs://trendmd-druid/raw/organic-impressions/dt=2016-02-04/1_0_00000000000025099615
Feb 11, 2016 11:45:11 PM com.twitter.common.zookeeper.DistributedLockImpl unlock
INFO: Cleaning up this locks ephemeral node.
Feb 11, 2016 11:45:11 PM com.twitter.common.zookeeper.DistributedLockImpl cleanup
INFO: Cleaning up!
2016-02-11 23:45:11,622 [Thread-3] (com.pinterest.secor.main.ConsumerMain$1:65) ERROR Thread Thread[Thread-3,5,main] failed
java.lang.RuntimeException: Failed to apply upload policy
    at com.pinterest.secor.consumer.Consumer.checkUploadPolicy(Consumer.java:112)
    at com.pinterest.secor.consumer.Consumer.run(Consumer.java:102)
Caused by: java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.io.IOException: insufficient data written
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.util.concurrent.FutureTask.get(FutureTask.java:188)
    at com.pinterest.secor.uploader.FutureHandle.get(FutureHandle.java:34)
    at com.pinterest.secor.uploader.Uploader.uploadFiles(Uploader.java:95)
    at com.pinterest.secor.uploader.Uploader.checkTopicPartition(Uploader.java:186)
    at com.pinterest.secor.uploader.Uploader.applyPolicy(Uploader.java:207)
    at com.pinterest.secor.consumer.Consumer.checkUploadPolicy(Consumer.java:110)
    ... 1 more
Caused by: java.lang.RuntimeException: java.io.IOException: insufficient data written
    at com.pinterest.secor.uploader.GsUploadManager$1.run(GsUploadManager.java:94)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: insufficient data written
    at sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.close(HttpURLConnection.java:3228)
    at com.google.api.client.http.javanet.NetHttpRequest.execute(NetHttpRequest.java:81)
    at com.google.api.client.http.HttpRequest.execute(HttpRequest.java:972)
    at com.google.api.client.googleapis.media.MediaHttpUploader.executeCurrentRequestWithoutGZip(MediaHttpUploader.java:545)
    at com.google.api.client.googleapis.media.MediaHttpUploader.resumableUpload(MediaHttpUploader.java:417)
    at com.google.api.client.googleapis.media.MediaHttpUploader.upload(MediaHttpUploader.java:336)
    at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.executeUnparsed(AbstractGoogleClientRequest.java:427)
    at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.executeUnparsed(AbstractGoogleClientRequest.java:352)
    at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.execute(AbstractGoogleClientRequest.java:469)
    at com.pinterest.secor.uploader.GsUploadManager$1.run(GsUploadManager.java:92)
    ... 5 more

this only happens if the file size is larger than the chunk size (10MB), if we set secor.max.file.size.bytes to 7500000 it results in a file about 9.5MB and is uploaded to GS ok, but when we set secor.max.file.size.bytes to it 8000000 throws the exception (secor.messages.per.second=10000).

secor version: 0.16 (0.13 also)
jdk version: 7u91-2.6.3-1~deb8u1

[HenryCaiHaiying]

Not familiar with GS, seems it might be hitting some file size limit on GS

[eLod]

@HenryCaiHaiying i dont think GS imposes a 10MB limit on you, it would be insane. We are fairly confident it has to do with chunk size 10MB, especially because we see that in sun.net.www.protocol.http.HttpURLConnection#close the insufficient data exception is also related to chunked.

[eLod]

@HenryCaiHaiying another update: if we set the upload as request.getMediaHttpUploader().setDirectUploadEnabled(true); in GsUploadManager then the upload succeeds, obviously file will be uploaded in single request and won't be resumable, but at least it works.

[HenryCaiHaiying]

This sounds good, how about you prepare a PR for this fix. And make sure
you take in a config parameter on whether calling
setDirectUploadEnabled(true) in case someone doesn't want that behavior.

On Mon, Feb 15, 2016 at 6:32 AM, eLod notifications@github.com wrote:

@HenryCaiHaiying https://github.com/HenryCaiHaiying another update: if
we set the upload as
request.getMediaHttpUploader().setDirectUploadEnabled(true); in
GsUploadManager then the upload succeeds, obviously file will be uploaded
in single request and won't be resumable, but at least it works.

—
Reply to this email directly or view it on GitHub
#177 (comment).

[eLod]

i would, but on my local machine it fails to build master, i think i'm hitting #78

Tests run: 3, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.075 sec <<< FAILURE!
testExtractDateUsingInputPattern(com.pinterest.secor.parser.DateMessageParserTest)  Time elapsed: 0.065 sec  <<< FAILURE!
junit.framework.ComparisonFailure: expected:<dt=[2001-07-04]> but was:<dt=[1970-01-01]>

[HenryCaiHaiying]

Did you try the workaround suggested by in the issue?

Or you can just prepare the PR, the travis-CI robot runs in US locale, it
probably won't hit that problem.

On Mon, Feb 15, 2016 at 8:46 PM, eLod notifications@github.com wrote:

i would, but on my local machine it fails to build master, i think i'm
hitting #78 #78

Tests run: 3, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.075 sec <<< FAILURE!
testExtractDateUsingInputPattern(com.pinterest.secor.parser.DateMessageParserTest) Time elapsed: 0.065 sec <<< FAILURE!
junit.framework.ComparisonFailure: expected:<dt=[2001-07-04]> but was:<dt=[1970-01-01]>

—
Reply to this email directly or view it on GitHub
#177 (comment).

[eLod]

when i added the commit i noticed the implementation once had direct upload already (introduced in 54c234a, removed in 2a0cb58), maybe @jgagnon1 could help us debug the issue?

[jgagnon1]

@eLod I initially added the setDirectUploadEnabled(true) in order to fix the actual issue you're having (Caused by: java.io.IOException: insufficient data written) - but it didn't end up working for us.

I thought I fixed that by using the exponential backoff introduced in b9b49d1 - In fact that fixed it for us.

[eLod]

@jgagnon1 do you think we can investigate this further, or should we just have the directUpload as a config key and be done with it. Disabling resumable uploads is something we feel have some downsides that it's worth some of our time to investigate (and possibly find a better solution), but we are not well versed enough in java to do this only by ourselves. If you happen to have energy (for this) we would gladly help as we can, otherwise we would just use direct uploads and move on.