All vhosts are backed up under the same S3 account but randomly one of them fails

76 posts / 0 new
Last post
#1 Mon, 06/23/2014 - 04:51
eddieb

All vhosts are backed up under the same S3 account but randomly one of them fails

I've been having this for a few days:

Uploading archive to Amazon's S3 service .. .. upload failed! Empty response to HTTP request

Under a single backup plan, all using the same credentials, backing up to the same bucket, one night vhost A fails, the other night vhost D, the other night F, then A again, etc.

What should I look into? The firewall doesn't show anything (as it shouldn't).

Tue, 06/24/2014 - 04:18
martinmanyhats

FWIW, I've also been having this intermittently for some months. Like your experience, there is no obvious pattern. Two different servers, each with a 20-30 virtual servers. Maybe a 1% failure to upload. Latest Virtualmin release 4.08 at present).

If anyone can suggest some diagnostic steps I'd be happy to try.

Tue, 06/24/2014 - 05:38
eddieb

The only thing I know that changed recently was the following:

I went in via the mobile interface (on Android) to update the backup plans - I wanted to exclude a certain site from backup. When I saved the backup plan, every piece of information in the credential area got doubled up, like this: http://i.imgur.com/avc6XnY.png

Naturally, ALL backups failed the following day. So I went in and corrected this. They started working again. A few days later I started having this problem. Since the credentials have been corrected, I imagine that this past issue has nothing to do with the current one, but it's nonetheless worth mentioning, even if just to bring attention to the mobile interface bug.

Thu, 07/03/2014 - 08:06
blDraX

I have exactly the same problem.

The backups started failing on about June 11th.

Sometimes all backups are completed (I backup around 15 vhosts) but most of the time, at least one or two fail when trying to upload with the message already stated above:

Uploading archive to Amazon's S3 service .. .. upload failed! Empty response to HTTP request

Thu, 07/03/2014 - 09:23
martinmanyhats

Getting worse here :(. Failure rate per site backed up is slowly increasing.

martin

Thu, 07/03/2014 - 10:56
eddieb

Aha! Mine started failing on June 14th. I can rule out the mobile interface bug, as that happened one month earlier (finally pulled logs from storage to check on this)

we need a fix :/

thanks virtualmin team for all your hard work. i'm looking to convert to a paid version this year.

Thu, 07/03/2014 - 11:18
CapstoneWorks

Backups to S3 were working, but we tried to create a new backup job on a new web server and now get - "upload failed! Empty response to HTTP request." at the end as the uploaad begins. Trying to create a similar job on other web servers and we find they are all failing too with the same message.

Please keep us updated.

Webmin version 1.690 Virtualmin version 4.08.gpl GPL

Thu, 07/03/2014 - 12:21
andreychek

Jamie tells me that this can happen if S3 closes the connection before returning a response to a request.

One work-around is to increase the number of re-tries for S3 uploads, at System Settings -> Virtualmin Configuration -> Backup and Restore -> Number of times to re-try FTP or S3 uploads.

I'm curious if increasing the re-tries resolves the issues you're seeing.

-Eric

Thu, 07/03/2014 - 13:45
eddieb

Increased from 3 to 6. will keep you posted, Eric. gracias.

Tue, 07/08/2014 - 03:02
Gerard

Increasing from 3 to 6 seems to help for several VPS. Only one virtual server failed last night. Yesterday 11 failed.

The problem occurs on CentOS 5 VPS only, I have one CentOS 6 VPS that never had a problem with backups.

Tue, 07/08/2014 - 03:23
martinmanyhats

I have also increased from 3 to 6, has greatly reduced (but not eliminated) the symptoms. Running on CentOS 6.5, two different VPS.

Tue, 07/08/2014 - 03:57
eddieb

Increase from 3 to 6 also helped, but did not solve the problem. Gerard, I'm also on CentOS 6.5

Thu, 07/10/2014 - 02:13
Gerard

Same here, it helped but did not solve the problem. Changing from 6 to 10 doesn't make a difference.

Thu, 07/10/2014 - 03:50
eddieb

Now I guess it's just wait for a fix from the Virtualmin team. Because the likelihood that the problem is on the S3 side are realistically negligible, given how long the problem has been occurring.

Thu, 07/10/2014 - 08:35
andreychek

Howdy,

Jamie has been looking into this issue, though thus far he hasn't found any awesome fixes that will make that issue go away.

Here's the one thing he did come up with though -- right now, the time between retries is 10 seconds.

We're wondering if increasing that might help a bit.

So the next Virtualmin version will wait longer in between retries.

If you'd like to try that out now, the change to the Virtualmin code is very simple to implement that.

What you can do is edit the file s3-lib.pl that comes in the root Virtualmin directory, and on line 51 you'll see this code:

sleep(10);

Try increasing that "10"... perhaps making that "30" would be a good place to start. And then be sure to let us know if that helps.

-Eric

Thu, 07/10/2014 - 08:53
eddieb

I did that and I will report on it.

Thanks Eric.

Mon, 07/14/2014 - 03:26
Gerard

I edited /usr/libexec/webmin/virtual-server/s3-lib.pl and increased the value to "30" like you suggested but it does' seem to make a difference. Should I have restarted Virtualmin / Webmin?

Mon, 07/14/2014 - 04:47
eddieb

I'm still seeing issues after increasing to 30.

thanks

Wed, 07/16/2014 - 04:05
amityweb

I also changed the retries from 3 to 6 on one of my servers, and a few of the virtual servers on it still failed backup

Wed, 07/16/2014 - 10:19
andreychek

Howdy,

Thanks for your input!

I'll talk to Jamie, but we're unfortunately running low on ideas :-/

We haven't been able to reproduce this issue in our testing, and there doesn't seem to be any pattern to why it doesn't work... especially since the same files might work the next day.

We understand that it's not a fluke though, as it seems to semi-regularly happen to some people.

If any of you have some time to tinker (or perhaps are just sick of this not working :-), I'd be most curious to hear if anyone has better luck using the Rackspace Cloud backup option.

But we'll continue to look into the S3 backup issues.

-Eric

Wed, 07/16/2014 - 11:38
eddieb

Eric, i imagined you guys already looked into all the updates that occur near the date the issue started occurring?

i dont have a rackspace acct but im willing to help. LMK how.

thank you!

Wed, 07/16/2014 - 11:50
amityweb

Could a firewall be preventing Amazon connection? We have CSF on all our servers, and we block all non-public ports, e.g. SSH, FTP etc. We only open port 80 for incoming traffic, and email ports. Would Amazon S3 be connecting on specific ports, or kicking off some LFD block like too many connections too quickly? I did search for "amazon" in the LFD log but nothing there.

I have approx. 10 servers all backing up to Amazon S3 at the same time each night, midnight, so also wondered if connecting to the buckets in my one S3 account at the same time caused some issue at Amazon? Although if it did then I am sure S3 is not very robust for larger organisations, so probably not this.

Wed, 07/16/2014 - 14:06
andreychek

I'll review the git check-ins to double-check that nothing there changed that might be causing the issue.

Did this start occurring at the same time for everyone, roughly mid-june?

-Eric

Wed, 07/16/2014 - 14:49
eddieb

13-16 of june at least for two ppl here...

Wed, 07/16/2014 - 15:40
andreychek

Howdy,

Thanks for the info.

Reviewing the Virtualmin releases, it looks like the most recent Virtualmin version, which is where the S3 code is implemented, was released on May 14th.

The most recent Webmin version was released on May 22nd.

I suspect since so many folks began seeing this issue in mid-June, that something else may have changed around that time (assuming it's client-side, and not related to S3 itself... which it very well may be).

I tried to answer this next question by reviewing the posts in this thread quickly, but I just wanted to confirm -- is everyone who's having this issue using CentOS? It sounds like there's a mix of CentOS 5 and CentOS 6 systems, but I didn't notice any that were running Ubuntu or Debian.

I don't imagine any of you still have yum logs from roughly the time when the problem began occurring, where you could check to see what packages were installed/updated around that time?

-Eric

Wed, 07/16/2014 - 16:49
martinmanyhats

yum.log for June 2014:

Jun 03 09:32:53 Updated: tzdata-2014d-1.el6.noarch
Jun 03 09:33:00 Updated: tzdata-java-2014d-1.el6.noarch
Jun 04 17:12:17 Updated: gnutls-2.8.5-14.el6_5.x86_64
Jun 04 17:12:25 Updated: libtasn1-2.3-6.el6_5.x86_64
Jun 06 00:01:02 Updated: openssl-1.0.1e-16.el6_5.14.x86_64
Jun 06 00:01:05 Updated: openssl-devel-1.0.1e-16.el6_5.14.x86_64
Jun 11 22:54:45 Updated: goaccess-0.8-1.el6.x86_64
Jun 21 09:50:37 Updated: kernel-firmware-2.6.32-431.20.3.el6.noarch
Jun 21 09:51:03 Installed: kernel-2.6.32-431.20.3.el6.x86_64
Jun 21 09:52:58 Updated: kernel-headers-2.6.32-431.20.3.el6.x86_64
Jun 21 09:53:12 Updated: libxml2-2.7.6-14.el6_5.2.x86_64
Jun 21 09:53:13 Updated: libxml2-python-2.7.6-14.el6_5.2.x86_64
Jun 21 09:53:21 Updated: tzdata-2014e-1.el6.noarch
Jun 21 09:53:28 Updated: tzdata-java-2014e-1.el6.noarch
Jun 23 10:54:03 Updated: nodejs-packaging-7-1.el6.noarch
Jun 23 23:03:26 Updated: avahi-libs-0.6.25-12.el6_5.1.x86_64
Jun 23 23:03:33 Updated: kpartx-0.4.9-72.el6_5.3.x86_64
Jun 23 23:03:39 Updated: ql2400-firmware-7.03.00-1.el6_5.noarch
Jun 23 23:03:44 Updated: ql2500-firmware-7.03.00-1.el6_5.noarch
Jun 26 10:44:13 Updated: 1:dovecot-2.0.9-7.el6_5.1.x86_64
Jun 26 10:53:59 Updated: coreutils-libs-8.4-31.el6_5.2.x86_64
Jun 26 10:54:10 Updated: coreutils-8.4-31.el6_5.2.x86_64
Jun 28 08:10:25 Updated: clamav-db-0.98.4-1.el6.x86_64
Jun 28 08:10:35 Updated: clamav-0.98.4-1.el6.x86_64
Jun 28 08:10:37 Updated: clamd-0.98.4-1.el6.x86_64

martin

Thu, 07/17/2014 - 02:24
eddieb

CentOS 6.

Updates on the week of 10-17 of June:

Updated mod_security-1:2.8.0-20.el6.art.x86_64 @asl-4.0 Updated libxml2-2.7.6-14.el6_5.1.x86_64 Updated libxml2-python-2.7.6-14.el6_5.1.x86_64

Thu, 07/17/2014 - 04:25
amityweb

I attach my yum.log for June, for one of my servers. Let me know if you want more of my servers (all 10 of them have the issue). They are all more or less similar in setup, and all would have been updated the same time, I try to run yum update once a month on all servers. They are all CentOS 6.

Thu, 07/17/2014 - 08:30
T2thec

Just two put my +1 to this. Sadly I have lost a clients database now as things weren't being backed up fully. :-(

I had this issue some time ago and I found that the server time was a little off which seemed to cause the failing.

Another note for some, Amazon, not so long ago changed their authentication method (IAM). Not sure if it is related or not, but I have changed the credentials now.

Not sure how either of these suggestions have anything to do with Empty response to HTTP request. Just clutching at straws really.

It still doesn't get everything across, but I got more servers over than I have done in the past. I'm going to tweak reties now and see if that helps.

Thu, 07/17/2014 - 09:49
siwuch

Hi,

We use Ubuntu 12.04 LTS and we have the same observations:

I contacted AWS support and they are asking for request/response headers of the failed requests. Is there any way for me to find some debugging info in logs that I could pass to AWS team?

Thu, 07/17/2014 - 10:14
andreychek

The biggest thing I see in common that's been updated is libxml2.

I'm reluctant to think that's the source of issue, but I also don't want to rule it out. I mean, I suppose if one of you guys wanted to try rolling libxml2 back to the previous version, I'd be curious if that makes a difference.

I'm a bit more curious about this though --

I've been reviewing the code used to push the backups to S3, and I'm wondering if anyone would be so kind to try making a change in /usr/libexec/webmin/virtual-server/s3-lib.pl to enable some additional debugging.

On line 208 of that file is the following:

$err = "Empty response to HTTP request";

Could you change that line to read as follows:

$err = "Empty response to HTTP request: [line: $line], [out: $out]";

That will show a bit more info about what's really being returned by Amazon when this error occurs.

After making that change, restart Webmin (/etc/init.d/webmin restart).

Then, next time that error is thrown, could you paste in the full error output here? It's possible those variables will be completely empty. But it's also possible they'll contain exactly what we need to determine what's going on :-)

Thanks!

-Eric

Thu, 07/17/2014 - 10:40
siwuch

Thanks Eric, I've made the change. We run backups every night Europe time. I will respond with an updatede if anything comes up unless someone else is faster than me.

Leszek

Thu, 07/17/2014 - 11:36
amityweb

@T2thec about the server time... Amazon does indeed check server time. If its 15 minutes or more difference it wont connect. I discovered this some time ago when using a plugin for Expression Engine. You can see my report here http://expressionengine.stackexchange.com/questions/10170/assets-stopped..., and Amazons FAQ on the matter http://aws.amazon.com/articles/1109#04. BUT, my server times are now correct following this issue, so that may not be the issue here.

Thu, 07/17/2014 - 16:46
martinmanyhats

Two servers updated, will report back tomorrow.

martin

Fri, 07/18/2014 - 03:07 (Reply to #34)
martinmanyhats

One domain failed, the report contained:

Uploading archive to Amazon's S3 service .. .. upload failed! Empty response to HTTP request: [line: ], [out: ]

martin

Fri, 07/18/2014 - 03:57
T2thec

Hey. Reporting back.

• Bumped retires up to 10 • Changed to new AWS IAM passkey details • Checked server time wasn't out

72 vps fully backed up three times without a hitch.

I am a happy man again... For now.

Fri, 07/18/2014 - 04:54 (Reply to #36)
eddieb

T2thec,

Whats the new AWS IAM passkey details?

and everyone, how would server time be an issue OCCASIONALLY?

thanks

Mon, 07/21/2014 - 04:58
siwuch

Dear Eric,

Similarly to martinmanyhats I see the same output in my backup logs:

Creating incremental TAR file of home directory .. .. done Uploading archive to Amazon's S3 service .. .. upload failed! Empty response to HTTP request: [line: ], [out: ]

.. completed in 1 minutes, 24 seconds

Thanks!

Mon, 07/21/2014 - 05:55
jfquestiaux

Hi. I had the same problem on a Debian 7 server, starting on May 27th: random backup failures of virtual server.

I tried to set up a new scheduled backup and it failed every time until I increased the retries from 3 to 10 in the Virtualmin settings.

I'll do the same on the server with the random failures and see what it does next time.

Mon, 07/21/2014 - 09:53
andreychek

Thank you for sharing the additional output in the backup logs. That does look like it's truly empty.

It sounds like Amazon is suggesting we review (or pass along to them) the headers being sent to them, and received from them, during the backup process.

I'll work with Jamie to get a patch that retrieves that information, and we'll get back with you shortly!

-Eric

Mon, 07/21/2014 - 17:15
siwuch

Thanks a lot, I'm staying in touch with AWS Support so we can work on it. I have also enabled S3 logging to gather complete info and what I noticed is that lot's of responses for PUT and DELETE are not 2xx but 301 Permament redirects. I'm not very familar with AWS API so I can't tell if it is an issue or not but I think that 301 redirect are actually empty besides the headers so maybe that is at least a hint for you.

EDIT: Below is a filtered log from S3 for a single domain that has failed last night to upload. I have cenzored private information. S3 logs to a set of files so I just did cat * > file on them and the log entries are not in order but since the time stamps are not very precise anyway I just did not bother to sort it as it does not seem to make sense anyway. What seems interesting to me is that all the entries with 301 redirects have the "requester" field empty (dash mark between IP and RequesID) which, I think, indicates an issue somewhere in the area of authentication against S3. S3 log format explanation I used: http://docs.aws.amazon.com/AmazonS3/latest/dev/LogFormat.html .

79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:12 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin D6661E214D40B083 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 17 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:38 +0000] 54.217.X.Y - 7F39D54D44A9D0D9 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 2 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:03 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin D953A7C00443AC96 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 22 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:03 +0000] 54.217.X.Y - 6AD6C2FF2C27FFE7 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:16 +0000] 54.217.X.Y - 540EF2D1EAD3B928 REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 4 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:38 +0000] 54.217.X.Y - C3C0BECC2D63E0A7 REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:12 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 6D69AC203FF98C08 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 21 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:24 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 1B959C46A4F9DB49 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 16 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:25 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 78F680105E729E6D REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 19 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:50 +0000] 54.217.X.Y - 3C6235B6990D9055 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:15 +0000] 54.217.X.Y - 91114288E4089419 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:50 +0000] 54.217.X.Y - 7301F2438009C10A REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:03 +0000] 54.217.X.Y - 4E13FA77A206330A REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 5 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:02 +0000] 54.217.X.Y - 1E6A72CB1665D9EC REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:15 +0000] 54.217.X.Y - 957E8E0DFF542030 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 5 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:15 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 4CE889B92C2FD3E6 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 19 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:37 +0000] 54.217.X.Y - FE308A809668CA26 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 3 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:51 +0000] 54.217.X.Y - 0CCE957045A7F7CC REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 5 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:15 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin FFE1DF799FCB803A REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 20 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:50 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 7F84240580ED5C3D REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 18 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:37 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin F61230938AC30666 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 19 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:12 +0000] 54.217.X.Y - F8BB4603BFD47860 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 3 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:38 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 3DBE1484B6283574 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 18 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:13 +0000] 54.217.X.Y - C87F712F17BA9A70 REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:26 +0000] 54.217.X.Y - AFAC1CA89C11B9FF REST.PUT.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz "PUT /bucketname/PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:25 +0000] 54.217.X.Y - E5FA16806F75F8B2 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 301 PermanentRedirect 451 - 98 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:50 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 88CDA58EFE9EFC2D REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.dom "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Edom HTTP/1.1" 204 - - - 24 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:14:02 +0000] 54.217.X.Y arn:aws:iam::ACCOUNTID:user/virtualmin 54179B7AE7732EB4 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 204 - - - 28 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:12 +0000] 54.217.X.Y - 1A33BA3E3968E51F REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 3 - "-" "libwww-perl/6.03" -
79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [21/Jul/2014:00:13:24 +0000] 54.217.X.Y - 662FC96E9AF20102 REST.DELETE.OBJECT PRO/daily/Mon-2014-07-21/domainname.co.uk.tar.gz.info "DELETE /bucketname/PRO%2Fdaily%2FMon-2014-07-21%2Fdomainname%2Eco%2Euk%2Etar%2Egz%2Einfo HTTP/1.1" 301 PermanentRedirect 451 - 2 - "-" "libwww-perl/6.03" -
Tue, 07/22/2014 - 03:43
jfquestiaux

Just a word to report that, for the first time since the issue appeared (end of May), no backup failed last night, after changing "S3 retry" from 3 to 10.

Wed, 07/23/2014 - 05:13
siwuch

Hi again,

I received another response from AWS support this night. I mentioned them that I noticed the pattern that the logs indicate authentication issue as the redirects are issued to the requests without the "requester" field. AWS Support responded as follows:

"I can see from the logs that some requests are not authenticated (sent anonymously) and S3 responds with redirect for these requests. Probably there are authentication headers missing, as I would expect different answer for wrong signature.

You are right, there are request IDs in the log. Unfortunately these are useless to us without second part of the ID, which is twice as long and is returned in "x-amz-id-2" header [1].

Even then, I doubt if any valuable information is there for us, as we don't log HTTP headers, so we will only see some "Unathenticated" status, similar to the log you provided."

...

  1. http://docs.aws.amazon.com/AmazonS3/latest/API/RESTCommonResponseHeaders... "

So it seems we really need those headers.

Kind regards, Leszek Eljasz

Wed, 07/23/2014 - 09:15
andreychek

I will pass along the above info from Amazon to Jamie.

Sorry for the delay in providing a way to view the headers -- Jamie is on vacation now, and although he's still working while away, his communication is a bit more delayed :-)

He and I have been discussing how best to build what Amazon is requesting, and late last night Jamie responded with a patch. With the updated code included in that patch, anytime the above error is thrown, /var/webmin/miniserv.error will contain the headers sent to and from Amazon during the failed request.

This is the patch, and I'll attach the full s3-lib.pl as an attachment to this post:

modules/virtual-server/s3-lib.pl
@@ -162,8 +162,10 @@ sub s3_upload
         "for $page failed : $h";
  next;
  }
+ local $hinput;
  foreach my $hfn ($req->header_field_names) {
  &write_http_connection($h, $hfn.": ".$req->header($hfn)."\r\n");
+ $hinput .= $hfn.": ".$req->header($hfn)."\r\n";
  }
  &write_http_connection($h, "\r\n");
 
@@ -208,6 +210,11 @@ sub s3_upload
 
  if ($line !~ /\S/) {
  $err = "Empty response to HTTP request. Headers were : $htext";
+ print STDERR "host=$host port=$port page=$page\n";
+ print STDERR "Request headers :\n";
+ print STDERR $hinput;
+ print STDERR "Reply headers :\n";
+ print STDERR $htext;
  }
  elsif ($line !~ /^HTTP\/1\..\s+(200|30[0-9])(\s+|$)/) {
  $err = "Invalid HTTP response : $line";

Edit: sorry for all the typos (they should be corrected now), it looks like the 'n' key on my laptop is wearing out :-)

Fri, 07/25/2014 - 06:48
siwuch

Hi Eric,

Is this helpful in any way? I doesn't seem to be complete info to me as there is no HTTP method logged for instance, also the reply headers are empty. Please take a look:

host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:42:18 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:I8M1SF9k/WDcCPIbBd3bxTScNzA=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:42:31 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:o7CDVreSEg5lgpyxRu4kE96+lhk=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:42:54 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:gWE74zUEHdPPRdNZSJAogHRyzKg=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:43:27 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:jjndyR4NOeQLw+ErEf8a55CX/oo=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:44:10 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:0Be6agAU8nGI2rRx8tWuVZf/nTM=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:45:04 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:bH1Z3PnWZQw+XDh96Oy3sxtJa6A=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:46:07 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:AiROi1wxbi/yiIOWhSTkLS7cqJ4=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:47:21 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:ANKOkM/cTkC9UdxAZKSXpF0+sGU=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:48:44 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:/h3Cjs1lXE5sLakuJxix77NO+LM=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :
host=s3.amazonaws.com port=443 page=/bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz
Request headers :
Date: Fri, 25 Jul 2014 00:50:18 GMT
Authorization: AWS AWS_ACCESS_KEY_ID:Z4Zg4NVjTxbMcxkH+qPNWGNd5Ig=
Host: s3.amazonaws.com
Content-Length: 66299370
Reply headers :

Corresponding S3 log entires:

2014-07-25-01-21-44-A94E019966C80758:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:50:17 +0000] 54.X.Y.Z - 881701437ECFBECC REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 463 - 2 - "-" "-" -
2014-07-25-01-21-54-1807F64F1B8E82DC:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:44:10 +0000] 54.X.Y.Z - B9585724DDAC5808 REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
2014-07-25-01-22-08-2D4352E69FD38B14:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:42:17 +0000] 54.X.Y.Z - 68B7F095F3D2262E REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 463 - 2 - "-" "-" -
2014-07-25-01-28-56-AF74355EB64ABF32:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:43:27 +0000] 54.X.Y.Z - 1D3BCFC5EE516372 REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
2014-07-25-01-30-00-A7C3528A1AD65F2B:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:47:21 +0000] 54.X.Y.Z - 661B0AC7383968CC REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
2014-07-25-01-38-14-70D7F84266889FAB:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:45:03 +0000] 54.X.Y.Z - 72E4A5B6D75A9F18 REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 2 - "-" "-" -
2014-07-25-01-39-04-67F5B519B8DA69A0:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:42:54 +0000] 54.X.Y.Z - 208E8D97FEC32B5F REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 463 - 3 - "-" "-" -
2014-07-25-01-40-35-AFE8001C3D232AE9:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:42:30 +0000] 54.X.Y.Z - AF359983C48646A3 REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 463 - 2 - "-" "-" -
2014-07-25-01-43-11-EB261D46E4EEAAFA:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:48:44 +0000] 54.X.Y.Z - 7AF0A976133FAFBB REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 451 - 3 - "-" "-" -
2014-07-25-01-48-22-8E6DEDCD19FD8FF0:79a59df900b949e55d96a1e698fbacedfd6e09d98eacf8f8d5218e7cd47ef2be bucketname [25/Jul/2014:00:46:07 +0000] 54.X.Y.Z - 80AF3138B2CFF698 REST.PUT.OBJECT PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz "PUT /bucketname/PRO/daily/Fri-2014-07-25/domain.co.uk.tar.gz HTTP/1.0" 301 PermanentRedirect 463 - 2 - "-" "-" -

It also seems that user agent is gone now.

Wed, 08/20/2014 - 03:07
Gerard

I still get errors every day. Is there any progress?

Thank you

Wed, 08/20/2014 - 03:16
eddieb

I havent' received the warning in a while.

Wed, 08/20/2014 - 04:01
siwuch

No changes on my side, we still observe the issue. Recently I raised the amount of repeated attempts to 15 which seems to help for incremental backups but the full weekly backups never make it.

Eric, is there anything else I can do to help you guys resolve this issue?

Thu, 08/28/2014 - 03:45
eddieb

Yes, it happened today again.

Tue, 09/23/2014 - 08:33
RealGecko

I have Debian 7 server with Virtualmin 4.10 GPL and have the same issue. Backups are randomly failing with random vservers. Even not so big incremental backups are failing from time to time.

Tue, 09/23/2014 - 15:44
andreychek

The debugging output we've been seeing hasn't led to any sort of resolution... it certainly appears that all requests to S3 are being authenticated, and that, in some cases, the response is blank. Which is very odd!

What Jamie is doing is revamping the S3 support to use the latest code available in the S3 library that it was based on. Virtualmin's S3 support was built some years ago, and not much with it has changed since then.

So to rule out any sort of unusual compatibility issue, Jamie is redoing it to include all the changes and updates in the S3 library. Let's see if that helps!

-Eric

Pages