Closed GoogleCodeExporter closed 9 years ago
Original comment by Nikolaus@rath.org
on 16 Aug 2013 at 7:30
Thanks for the report! I'll need some more information to debug this properly.
Could you please apply the attached patch and post the contents of mount.log
when the error occurs again?
Thanks!
Original comment by Nikolaus@rath.org
on 27 Aug 2013 at 4:54
Attachments:
Hi, I am not convinced I did the patching right, so if the log is not what
you'd expect please let me know. Thanks.
2013-08-28 16:51:49.880 [pid=311, thread='MainThread', module='s3ql.mount',
fn='determine_threads', line=281]: Using 2 upload threads.
2013-08-28 16:51:53.128 [pid=311, thread='MainThread', module='s3ql.mount',
fn='get_metadata', line=300]: Using cached metadata.
2013-08-28 16:51:53.152 [pid=311, thread='MainThread', module='s3ql.mount',
fn='main', line=121]: Mounting filesystem...
2013-08-28 16:51:53.309 [pid=314, thread='MainThread', module='s3ql.daemonize',
fn='detach_process_context', line=67]: Daemonizing, new PID is 315
2013-08-28 16:52:39.869 [pid=315, thread='Thread-5', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/s3.py", line 67, in delete_multi
self._delete_multi(tmp, force=force)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/s3.py", line 85, in _delete_multi
root = self._parse_xml_response(resp)
AttributeError: 'Backend' object has no attribute '_parse_xml_response'
2013-08-28 16:52:46.881 [pid=315, thread='MainThread', module='s3ql.mount',
fn='unmount', line=129]: Unmounting file system...
2013-08-28 16:52:46.883 [pid=315, thread='MainThread', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "bin/mount.s3ql", line 26, in <module>
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/mount.py", line 178, in main
raise tmp0(tmp1).with_traceback(tmp2)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/s3.py", line 67, in delete_multi
self._delete_multi(tmp, force=force)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/home/cloudbackupuk/software/s3ql-2.3/src/s3ql/backends/s3.py", line 85, in _delete_multi
root = self._parse_xml_response(resp)
AttributeError: 'Backend' object has no attribute '_parse_xml_response'
Original comment by czv...@gmail.com
on 28 Aug 2013 at 4:04
Ah, my bad. I accidentally generated the patch for some intermediate S3QL
version rather than the 2.3 release.
Could you just update to the brand-new S3QL 2.4? That already includes the
patch :-).
Original comment by Nikolaus@rath.org
on 28 Aug 2013 at 8:51
Yes, I noticed that the only one bucket I left mounted has been running for the
past few days since I went to 2.4 on that box. Awesome. I will update all
servers and report back if there is still a problem. If you don't hear from me,
all is well! :-)
Thanks for all your hard work, s3ql is awesome!!
Balazs
Original comment by czv...@gmail.com
on 3 Sep 2013 at 12:00
Hmmm...not sure if this is different or the same. I tried witha bigger
rdiff-backup job, and got this after a good 20 minute run:
tail .s3ql/mount.log --lines=100
2013-09-03 09:34:18.129 [pid=19890, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:19.343 [pid=19890, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:19.471 [pid=19890, thread='Thread-6',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:19.903 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:20.501 [pid=19890, thread='Thread-4',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:20.572 [pid=19890, thread='Thread-11',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:20.629 [pid=19890, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:23.121 [pid=19890, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:25.809 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:28.333 [pid=19890, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:32.357 [pid=19890, thread='Thread-4',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:34.469 [pid=19890, thread='Thread-6',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:45.190 [pid=19890, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:46.505 [pid=19890, thread='Thread-15',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend._delete_multi...
2013-09-03 09:34:46.906 [pid=19890, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:47.108 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:34:47.703 [pid=19890, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:35:02.087 [pid=19890, thread='Dummy-25',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend.open_read...
2013-09-03 09:35:08.272 [pid=19890, thread='Thread-17',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:08.497 [pid=19890, thread='Thread-18',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:08.680 [pid=19890, thread='Dummy-24',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend.open_read...
2013-09-03 09:35:11.696 [pid=19890, thread='Thread-14',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:15.733 [pid=19890, thread='Thread-11',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:35:16.872 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:35:21.805 [pid=19890, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
2013-09-03 09:35:21.900 [pid=19890, thread='Thread-3',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
2013-09-03 09:35:22.001 [pid=19890, thread='Thread-22',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend._delete_multi...
2013-09-03 09:35:22.004 [pid=19890, thread='Dummy-25',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend.open_read...
2013-09-03 09:35:23.373 [pid=19890, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:35:23.448 [pid=19890, thread='Thread-6',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:35:23.481 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
2013-09-03 09:35:38.424 [pid=19890, thread='Thread-13',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:38.430 [pid=19890, thread='Thread-21',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:38.475 [pid=19890, thread='Thread-16',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:38.500 [pid=19890, thread='Thread-20',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:38.635 [pid=19890, thread='Thread-19',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:38.794 [pid=19890, thread='Thread-15',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.625 [pid=19890, thread='Thread-13',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.678 [pid=19890, thread='Thread-22',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.693 [pid=19890, thread='Thread-16',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.712 [pid=19890, thread='Thread-20',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.730 [pid=19890, thread='Thread-19',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:43.999 [pid=19890, thread='Thread-21',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:44.019 [pid=19890, thread='Thread-17',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:44.071 [pid=19890, thread='Thread-18',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:44.433 [pid=19890, thread='Thread-15',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend._delete_multi...
2013-09-03 09:35:45.833 [pid=19890, thread='Thread-20',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.920 [pid=19890, thread='Thread-14',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.929 [pid=19890, thread='Thread-13',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.940 [pid=19890, thread='Thread-17',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.949 [pid=19890, thread='Thread-21',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.958 [pid=19890, thread='Thread-18',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-03 09:35:45.969 [pid=19890, thread='Thread-22',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend._delete_multi...
2013-09-03 09:35:46.759 [pid=19890, thread='Thread-22',
module='s3ql.backends.s3c', fn='_parse_xml_response', line=366]: Unexpected
server reply: expected XML, got None
2013-09-03 09:35:46.759 [pid=19890, thread='Thread-22',
module='s3ql.backends.s3c', fn='_parse_xml_response', line=369]: Full response:
200 OK
x-amz-id-2: d3JjxUD32mNNRe8TVaSYSGsvNqUTug5nUErewP7zkxYgL5bJHzDZYNBtdbEMuWJk
x-amz-request-id: FD9524AF67ED8656
Date: Tue, 03 Sep 2013 13:35:44 GMT
Transfer-Encoding: chunked
Server: AmazonS3
b'<?xml version="1.0" encoding="UTF-8"?>\n<DeleteResult
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Deleted><Key>s3ql_data_1352945<
/Key></Deleted></DeleteResult>'
2013-09-03 09:35:46.760 [pid=19890, thread='Thread-22', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/usr/lib/s3ql/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 80, in delete_multi
self._delete_multi(tmp, force=force)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 98, in _delete_multi
root = self._parse_xml_response(resp)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 370, in _parse_xml_response
raise RuntimeError('Unexpected server response')
RuntimeError: Unexpected server response
2013-09-03 09:37:36.054 [pid=19890, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.113 [pid=19890, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.171 [pid=19890, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.173 [pid=19890, thread='Thread-4',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.180 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.212 [pid=19890, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.284 [pid=19890, thread='Thread-11',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.330 [pid=19890, thread='Thread-3',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.363 [pid=19890, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:36.745 [pid=19890, thread='Thread-6',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:38.500 [pid=19890, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:39.537 [pid=19890, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:40.092 [pid=19890, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:40.118 [pid=19890, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:42.793 [pid=19890, thread='Thread-11',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:49.962 [pid=19890, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:50.488 [pid=19890, thread='Thread-6',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-03 09:37:52.975 [pid=19890, thread='MainThread', module='s3ql.mount',
fn='unmount', line=129]: Unmounting file system...
Original comment by czv...@gmail.com
on 3 Sep 2013 at 1:43
This is the same issue. The update to 2.4 wasn't expected to fix the problem,
just to print more information so that I can figure out what was going wrong.
It seems that Amazon is sometimes "forgetting" to set the "Content-Type: xml"
header. I can add a workaround for that, but this is really a bug in Amazon S3.
You don't by any chance have a support contract with AWS that'd allow you to
report this, do you?
(In my experience, reports on the AWS forum have only a small chance of being
noticed)
Original comment by Nikolaus@rath.org
on 3 Sep 2013 at 4:07
I don't, sorry :-( Do you think it is amazon, or could it be squid?
Original comment by czv...@gmail.com
on 3 Sep 2013 at 4:45
There's an easy way to find out: disable squid and retry :-). My guess is that
it's Amazon though.
Original comment by Nikolaus@rath.org
on 3 Sep 2013 at 6:05
I am running without squid now as a test on one of our hosts. So far, no
dismount yet, but I am suspicious as the copy process I am running is now
stuck. I will give it some more time before trying anything. I do see some new
entries in the mount.log, not sure if there are in any shape related:
2013-09-05 02:12:51.706 [pid=7886, thread='Dummy-25',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend.open_read...
2013-09-05 02:12:54.051 [pid=7886, thread='Thread-6', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 300, in _upload_loop
self._do_upload(*tmp)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 319, in _do_upload
obj_size = backend.perform_write(do_write, 's3ql_data_%d' % obj_id).get_obj_size()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 401, in perform_write
return fn(fh)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 857, in __exit__
self.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 850, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 972, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 689, in close
headers=self.headers, body=self.fh)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 470, in _send_request
self.conn.endheaders(None)
File "/usr/lib/python3.3/http/client.py", line 1057, in endheaders
self._send_output(message_body)
File "/usr/lib/python3.3/http/client.py", line 902, in _send_output
self.send(msg)
File "/usr/lib/python3.3/http/client.py", line 840, in send
self.connect()
File "/usr/lib/python3.3/http/client.py", line 1202, in connect
server_hostname=server_hostname)
File "/usr/lib/python3.3/ssl.py", line 210, in wrap_socket
_context=self)
File "/usr/lib/python3.3/ssl.py", line 310, in __init__
raise x
File "/usr/lib/python3.3/ssl.py", line 306, in __init__
self.do_handshake()
File "/usr/lib/python3.3/ssl.py", line 513, in do_handshake
self._sslobj.do_handshake()
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:547)
2013-09-05 02:12:59.755 [pid=7886, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.764 [pid=7886, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.774 [pid=7886, thread='Thread-4',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.774 [pid=7886, thread='Thread-3',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.783 [pid=7886, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.794 [pid=7886, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.807 [pid=7886, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:12:59.835 [pid=7886, thread='Thread-12', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 300, in _upload_loop
self._do_upload(*tmp)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 319, in _do_upload
obj_size = backend.perform_write(do_write, 's3ql_data_%d' % obj_id).get_obj_size()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 401, in perform_write
return fn(fh)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 857, in __exit__
self.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 850, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 972, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 689, in close
headers=self.headers, body=self.fh)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 466, in _send_request
self.conn.putrequest(method, path)
File "/usr/lib/python3.3/http/client.py", line 944, in putrequest
raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2013-09-05 02:13:01.137 [pid=7886, thread='Thread-16', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/usr/lib/s3ql/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 80, in delete_multi
self._delete_multi(tmp, force=force)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 96, in _delete_multi
resp = self._do_request('POST', '/', subres='delete', body=body, headers=headers)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 461, in _send_request
self.conn.request(method, path, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1061, in request
self._send_request(method, url, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1089, in _send_request
self.putrequest(method, url, **skips)
File "/usr/lib/python3.3/http/client.py", line 944, in putrequest
raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2013-09-05 02:13:02.637 [pid=7886, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 02:13:02.841 [pid=7886, thread='Thread-14', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/usr/lib/s3ql/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 80, in delete_multi
self._delete_multi(tmp, force=force)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 96, in _delete_multi
resp = self._do_request('POST', '/', subres='delete', body=body, headers=headers)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 461, in _send_request
self.conn.request(method, path, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1061, in request
self._send_request(method, url, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1089, in _send_request
self.putrequest(method, url, **skips)
File "/usr/lib/python3.3/http/client.py", line 944, in putrequest
raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2013-09-05 02:13:06.057 [pid=7886, thread='Thread-3',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
Original comment by czv...@gmail.com
on 5 Sep 2013 at 8:02
For the record, I've reported this at
https://forums.aws.amazon.com/thread.jspa?threadID=134372
Original comment by Nikolaus@rath.org
on 6 Sep 2013 at 1:57
Thank you, that was on my to-do for today, but your report looks more technical
than what I would have been able to submit :-) Regarding running without squid,
you are correct. I ran a test without squid, and although it ran a whole lot
longer, it did eventually bomb, so it is most likely the missing header that is
random, from S3. Squid has nothing to do with it it seems.
2013-09-05 22:36:53.825 [pid=1560, thread='Dummy-25',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend.open_read...
2013-09-05 22:36:57.463 [pid=1560, thread='Thread-9',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
2013-09-05 22:36:57.569 [pid=1560, thread='Thread-17', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/usr/lib/s3ql/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 80, in delete_multi
self._delete_multi(tmp, force=force)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 96, in _delete_multi
resp = self._do_request('POST', '/', subres='delete', body=body, headers=headers)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 461, in _send_request
self.conn.request(method, path, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1061, in request
self._send_request(method, url, body, headers)
File "/usr/lib/python3.3/http/client.py", line 1099, in _send_request
self.endheaders(body)
File "/usr/lib/python3.3/http/client.py", line 1057, in endheaders
self._send_output(message_body)
File "/usr/lib/python3.3/http/client.py", line 902, in _send_output
self.send(msg)
File "/usr/lib/python3.3/http/client.py", line 840, in send
self.connect()
File "/usr/lib/python3.3/http/client.py", line 1202, in connect
server_hostname=server_hostname)
File "/usr/lib/python3.3/ssl.py", line 210, in wrap_socket
_context=self)
File "/usr/lib/python3.3/ssl.py", line 310, in __init__
raise x
File "/usr/lib/python3.3/ssl.py", line 306, in __init__
self.do_handshake()
File "/usr/lib/python3.3/ssl.py", line 513, in do_handshake
self._sslobj.do_handshake()
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:547)
2013-09-05 22:36:59.996 [pid=1560, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 22:37:00.014 [pid=1560, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 22:37:00.027 [pid=1560, thread='Thread-11',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 22:37:00.041 [pid=1560, thread='Thread-10',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
2013-09-05 22:37:00.103 [pid=1560, thread='Thread-6', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 300, in _upload_loop
self._do_upload(*tmp)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 319, in _do_upload
obj_size = backend.perform_write(do_write, 's3ql_data_%d' % obj_id).get_obj_size()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 401, in perform_write
return fn(fh)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 857, in __exit__
self.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 850, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 972, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 689, in close
headers=self.headers, body=self.fh)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 466, in _send_request
self.conn.putrequest(method, path)
File "/usr/lib/python3.3/http/client.py", line 944, in putrequest
raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2013-09-05 22:37:00.103 [pid=1560, thread='Thread-16',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
Backend._delete_multi...
2013-09-05 22:37:00.109 [pid=1560, thread='Thread-12',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 22:37:00.297 [pid=1560, thread='Thread-8',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-05 22:37:01.833 [pid=1560, thread='Thread-3', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 300, in _upload_loop
self._do_upload(*tmp)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 319, in _do_upload
obj_size = backend.perform_write(do_write, 's3ql_data_%d' % obj_id).get_obj_size()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 401, in perform_write
return fn(fh)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 857, in __exit__
self.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 850, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 972, in close
self.fh.close()
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 689, in close
headers=self.headers, body=self.fh)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 287, in _do_request
resp = self._send_request(method, path, headers, subres, query_string, body)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 466, in _send_request
self.conn.putrequest(method, path)
File "/usr/lib/python3.3/http/client.py", line 944, in putrequest
raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2013-09-05 22:38:55.232 [pid=1560, thread='Thread-7',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BrokenPipeError exception ([Errno 32] Broken pipe), retrying call to
ObjectW.close...
Original comment by czv...@gmail.com
on 6 Sep 2013 at 8:17
This issue was closed by revision 8800e14e318d.
Original comment by Nikolaus@rath.org
on 8 Sep 2013 at 9:55
The attached patch should work around this problem and will be included in the
next release. Thanks for your help debugging this issue!
Original comment by Nikolaus@rath.org
on 8 Sep 2013 at 9:56
Attachments:
Thanks for that. I -believe- I have applied the patch correctly. Ran a test job
and got this below. Does this mean I did not patch correctly? How can I tell?
:-(
Thanks
2013-09-09 11:05:19.255 [pid=24364, thread='Dummy-25',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend.open_read...
2013-09-09 11:05:19.937 [pid=24364, thread='Thread-17',
module='s3ql.backends.s3c', fn='_parse_xml_response', line=366]: Unexpected
server reply: expected XML, got None
2013-09-09 11:05:19.937 [pid=24364, thread='Thread-17',
module='s3ql.backends.s3c', fn='_parse_xml_response', line=369]: Full response:
200 OK
x-amz-id-2: ITZ3AM9b723RkoHAJVT7tiX+8td4PDI7UgFpNRo+iQPSXg+zMyF+Bb/IBF+e9yb4
x-amz-request-id: FAE44064797615C8
Date: Mon, 09 Sep 2013 15:05:16 GMT
Transfer-Encoding: chunked
Server: AmazonS3
b'<?xml version="1.0" encoding="UTF-8"?>\n<DeleteResult
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Deleted><Key>s3ql_data_585063</
Key></Deleted></DeleteResult>'
2013-09-09 11:05:19.938 [pid=24364, thread='Thread-17', module='root',
fn='excepthook', line=123]: Uncaught top-level exception:
Traceback (most recent call last):
File "/usr/lib/s3ql/s3ql/mount.py", line 54, in run_with_except_hook
run_old(*args, **kw)
File "/usr/lib/python3.3/threading.py", line 596, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/s3ql/s3ql/block_cache.py", line 477, in _removal_loop
backend.delete_multi(['s3ql_data_%d' % i for i in ids])
File "/usr/lib/s3ql/s3ql/backends/common.py", line 764, in delete_multi
return self.backend.delete_multi(keys, force=force)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 80, in delete_multi
self._delete_multi(tmp, force=force)
File "/usr/lib/s3ql/s3ql/backends/common.py", line 65, in wrapped
return method(*a, **kw)
File "/usr/lib/s3ql/s3ql/backends/s3.py", line 98, in _delete_multi
root = self._parse_xml_response(resp)
File "/usr/lib/s3ql/s3ql/backends/s3c.py", line 370, in _parse_xml_response
raise RuntimeError('Unexpected server response')
RuntimeError: Unexpected server response
...
2013-09-09 11:14:23.482 [pid=24364, thread='Thread-15',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-09 11:14:25.312 [pid=24364, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-09 11:14:44.121 [pid=24364, thread='Thread-20',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to Backend._delete_multi...
2013-09-09 11:14:45.346 [pid=24364, thread='Thread-5',
module='s3ql.backends.common', fn='wrapped', line=77]: Encountered
BadStatusLine exception (''), retrying call to ObjectW.close...
2013-09-09 11:15:13.336 [pid=24364, thread='MainThread', module='s3ql.mount',
fn='unmount', line=129]: Unmounting file system...
Original comment by czv...@gmail.com
on 9 Sep 2013 at 3:58
That looks as if you did not apply the patch. What exactly did you do? The
procedure is roughly:
1. Download and extract s3ql-1.16.tar.bz2
2. cd s3ql-1.16
3. patch -p1 < the_patch.diff
4. bin/mount.s3ql [everything else]
Original comment by Nikolaus@rath.org
on 9 Sep 2013 at 4:23
Yeah I think it was a matter of removing the other 3 copies of all the
executables I had on there, so I don't think I was running with the patched
version. I am re-testing now, will let you know.
Thanks!
Original comment by czv...@gmail.com
on 9 Sep 2013 at 6:07
All is well, you have definitely fixed it!
Thanks very much! :-)
Original comment by czv...@gmail.com
on 10 Sep 2013 at 12:50
czviin, it seems Amazon needs some more information. Could you provide the
storage URL that you used for the above tests?
Original comment by Nikolaus@rath.org
on 16 Sep 2013 at 3:53
Original issue reported on code.google.com by
czv...@gmail.com
on 14 Aug 2013 at 10:52