S3 unexpected error forbidden: null thrown #291
Comments
andrewrk
changed the title
|
Can you explain what you mean by "there is no way for me to handle the error"? The Forbidden error is generated by S3 for resources that you do not have access to, so this is the correct error to return. I suppose the issue here is that the error is not being returned properly to the callback? Can you provide code that reproduces your issue along with your expected result? Also, what version of the SDK are you using? |
I mean that the error is thrown instead of returned in a callback or event. And that it is thrown in a function that I don't call directly so try/catch won't work.
I am running code that is calling putObject thousands of times, and several thousand times it works, followed by one time that I get this error.
Not reliably. It seems to be a sporadic error. Here is the code I am running: https://github.com/andrewrk/node-s3-client/blob/master/index.js#L407 Doing it on a folder with ~6,000 files each about 5 MB.
Version 2.0.0-rc.18. I've updated now and will try to reproduce with the latest. |
|
a Forbidden error with no body only comes back from requests where the server is not allowed to return a body. In this context, that usually means a HEAD request. That said, I don't see any calls to Can you enable logging in the SDK so we can capture the requests being made? |
|
I turned on the logger and here's the file http://superjoe.s3.amazonaws.com/temp/s3debug-out.txt On this run I got no error but instead the program stalled, as if for some reason a callback wasn't being called. This particular error on this run is probably a bug in my code. I'll do another run. What I noticed about this log file is that the response codes start out as 200s and then they turn into 403s at the end. Same credentials and everything. I also noticed that the time is monotonically increasing. If that is request time, then perhaps what is happening is that I'm starting a bazillion requests at once, and then taking too long to fulfill them. Would a 403 error be given in that situation? My understanding is that I should not worry about starting as many requests as possible, because the global agent socket pooling will make sure that only N number of them will run at once. |
|
Yes. The 403 errors are likely signing errors caused by the signing time expiring. I would recommend reading through #221 and making sure you're only opening at most maxSockets connections at a time. The SDK does some things to mitigate time skew errors, but it may be that we are not doing something correctly, so keeping track of your own request queue would avoid those problems. That said I don't see an error being thrown out of the run loop either. Are you still reproducing this behavior at all? |
|
I'm in the middle of another run. In this one the number of concurrent putObject calls is limited to 20 and the global maxSockets number is 30. So far the log is up to 363 seconds for each request, still monotonically increasing, and number of putObject calls is at 158. How can request times still be increasing? |
|
Request times increase in the logger because we log from the start time when the request was initiated. Since you constructed the requests at the same time, they all have the same start time. Those logs don't show the "time to send" data, but rather, time from construction. Can you print the full error message for your 403 responses? It would be interesting to know exactly why those requests fail. |
|
In this run I am not constructing all multiple-thousand requests at the same time, only 20 at a time. Yet the logger is printing a monotonically increasing time. This run completed and it had the same behavior where it stalled, as if a callback were never called. That's 4 in a row with the same behavior after upgrading to rc19. I think after upgrading to rc19 I'm not seeing the issue that I filed originally. Instead what I think is happening is I'm not getting a callback from putObject. The code is set up to crash and print a stack trace if I get an error from putObject, and that is not happening. I'm doing another run where I will only call putObject one at a time, with output that will enable us to make sure the callback is actually being called. |
|
OK I have verified that there is clearly a bug in my code that manages when to call putObject. It was not throttling it like I thought it was. |
|
Ah ok. No bug, I just put the configuration value in the wrong spot for this comment: #291 (comment) Now I'm doing the real test with putObject only allowed to have 20 requests at a time. |
|
Maybe this issue should be merged with #290 but the results of this run is that the putObject callback was called twice. Results here: #290 (comment) |
|
#290 was fixed and is part of the latest release-- can you verify whether you still have problems related to this issue, or if the fix in the other issue resolves this one too? |
|
I just ran my test case again with 2.0.0-rc.20. The test case is uploading a directory of files that totals to 46 GB to S3. 35% of the way through I started getting AWS SDK JS called callback twice warnings and then progress halted. No error was thrown, and the process looks like it was hanging. |
|
@andrewrk I've been running a similar test a number of times over the day but cannot seem to reproduce multiple callbacks. The code I'm running is: var AWS = require('aws-sdk');
var s3 = new AWS.S3();
var fs = require('fs');
require('https').Agent.maxSockets = 0;
var num = 0;
for (var i = 0; i < 100; i++) {
(function(x) {
var callbackCalled = false;
var file = fs.createReadStream('bigfile');
s3.putObject({Bucket:'mybucket',Key:'big/bigfile'+x,Body:file}, function(err, data) {
if (callbackCalled) { console.log("!!! Duplicate callback!", x); }
callbackCalled = true;
console.log(x, err,data);
if (!err) { num++; if (num >= 100) console.log("Completed."); }
});
})(i);
}bigfile is a 200mb file that I am uploading in 100 parallel requests. Over 10+ runs I only managed to reproduce one RequestTimeout error, but never managed to halt the callback queue or print "Duplicate callback!". I'm curious what you get if you try the above code. You can create a file bigfile or use one of your existing files to test this. |
|
I'm able to get the duplicate callback with a modified test case: require('graceful-fs'); // v2.0.3
var AWS = require('aws-sdk');
var s3 = new AWS.S3({
sslEnabled: false,
});
var fs = require('fs');
var Pend = require('pend');
require('https').Agent.maxSockets = 30;
require('http').Agent.maxSockets = 30;
var pend = new Pend();
var findit = require('findit');
var walker = findit("/home/andy/music/");
walker.on('file', function(file) {
pend.go(function(cb) {
var params = {
Bucket: process.env.S3_BUCKET,
Key: "1tmp1/" + file,
Body: fs.createReadStream(file),
};
var callbackCalled = false;
s3.putObject(params, function(err, data) {
if (callbackCalled) {
console.log("!!! Duplicate callback!", file);
}
callbackCalled = true;
if (err && err.retryable) {
console.log("!!! Retryable error!", file);
}
console.log(file, err, data);
cb();
});
});
});
walker.on('end', function() {
pend.wait(function() {
console.log("done");
});
});This re-introduces the problem of requests timing out, but even in that situation the callback should never be called twice. I'll work on trying to reduce this test case further, notably removing the graceful-fs dependency. |
|
OK here's a test case without graceful-fs: var AWS = require('aws-sdk');
var s3 = new AWS.S3({
sslEnabled: false,
});
var fs = require('fs');
var Pend = require('pend');
require('https').Agent.maxSockets = 30;
require('http').Agent.maxSockets = 30;
var pend = new Pend();
pend.max = 500;
var findit = require('findit');
var walker = findit("/home/andy/music/");
walker.on('file', function(file) {
pend.go(function(cb) {
var params = {
Bucket: process.env.S3_BUCKET,
Key: "1tmp1/" + file,
Body: fs.createReadStream(file),
};
var callbackCalled = false;
s3.putObject(params, function(err, data) {
if (callbackCalled) {
console.log("!!! Duplicate callback!", file);
}
callbackCalled = true;
if (err && err.retryable) {
console.log("!!! Retryable error!", file);
}
console.log(file, err, data);
cb();
});
});
});
walker.on('end', function() {
pend.wait(function() {
console.log("done");
});
});I get the first duplicate callback after the 4th log statement is printed for a RequestTimeTooSkewed. |
|
Same thing, except this time I used SSL and set maxSockets to 0 like you did. var AWS = require('aws-sdk');
var s3 = new AWS.S3();
var fs = require('fs');
var Pend = require('pend');
require('https').Agent.maxSockets = 0;
var pend = new Pend();
pend.max = 500;
var findit = require('findit');
var walker = findit("/home/andy/music/");
walker.on('file', function(file) {
pend.go(function(cb) {
var params = {
Bucket: process.env.S3_BUCKET,
Key: "1tmp1/" + file,
Body: fs.createReadStream(file),
};
var callbackCalled = false;
s3.putObject(params, function(err, data) {
if (callbackCalled) {
console.log("!!! Duplicate callback!", file);
}
callbackCalled = true;
if (err && err.retryable) {
console.log("!!! Retryable error!", file);
}
console.log(file, err, data);
cb();
});
});
});
walker.on('end', function() {
pend.wait(function() {
console.log("done");
});
}); |
|
Next test. This one sets var AWS = require('aws-sdk');
var s3 = new AWS.S3();
var fs = require('fs');
var Pend = require('pend');
require('https').Agent.maxSockets = 0;
var pend = new Pend();
pend.max = 4;
var findit = require('findit');
var walker = findit("/home/andy/music/");
walker.on('file', function(file) {
pend.go(function(cb) {
var params = {
Bucket: process.env.S3_BUCKET,
Key: "1tmp1/" + file,
Body: fs.createReadStream(file),
};
var callbackCalled = false;
s3.putObject(params, function(err, data) {
if (callbackCalled) {
console.log("!!! Duplicate callback!", file);
}
callbackCalled = true;
if (err && err.retryable) {
console.log("!!! Retryable error!", file);
}
console.log(file, err, data);
cb();
});
});
});
walker.on('end', function() {
pend.wait(function() {
console.log("done");
});
});This one took a lot longer before I saw any duplicate callbacks. Here's the first time I got a callback for this certain file: And then later: |
|
I just ran this test over a multiple test of runs with a set of "bigfile" files (20 of them, 200mb each), but could not manage to make this fail once. I tried a various set of regions too, along with modifying the maxSockets from 0 (unlimited) to 3 (a low value). Are you sure you are using the rc.20 release? The RequestTimeTooSkewed error was previously resolved in an earlier RC, so I'm a little surprised to see that popping up. Note: I'm not doubting that you are getting this error, but without being able to reproduce this myself, it will be hard for me to investigate what the fix is. If you can provide any more information about how you might be reproducing this issue I can do some more investigating to see if I can get this failing on my end. |
Yep, 2.0.0-rc.20. On Monday I'll see if I can get another test case going which is independent of the particular files on my computer. |
|
@andrewrk I've been working with @BrandonCopley in #300 on a similar issue where callbacks are firing more than once. This behavior only seems to be related (at least for me) to timeouts, but it might be worth testing against the above commit which should resolve multiple callbacks being fired when timeouts occur. |
|
Any response based on the above changes? |
|
Running a test now. |
|
With that commit I no longer get callback called twice. I do occasionally get a RequestTimeout which is a |
|
Glad to hear this is working for you @andrewrk! The patch will be out with our next release. |
|
This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and link to relevant comments in this thread. |
This error is thrown from inside the library and there is no way for me to handle the error. Also I have reason to believe that it is invalid and I should not be receiving a forbidden null error.
2.0.0-rc.18
The text was updated successfully, but these errors were encountered: