On Sunday, October 19, 2014 1:50:45 PM UTC-4, Nikolaus Rath wrote: > > On 10/19/2014 08:00 AM, Rich B wrote: > > Hello, > > I'm trying to use S3QL with Google Storage, but I'm consistently running > into a problem where blocks from the cache are not making it to the > backend. I'm running on Ubuntu 14.04 and using S3QL from the PPA (version > 2.11.1+dfsg-1~trusty1). > > My mount command looks like this: > > $ mount.s3ql --threads 4 --metadata-upload-interval 7200 --allow-other > --debug --cachedir /data/s3ql-cache --cachesize 1048567 > gs://MyBucket/MyPrefix /mnt/MyBucket > > Here is a sample from the mount log sometime after copying 200+ files > (0.5-3MB each) into the mount point: > > 2014-10-19 09:57:42.902 28314:Dummy-23 (name)s.statfs: statfs(): start > 2014-10-19 09:57:44.365 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:57:44.365 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:57:49.382 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:57:49.382 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:57:52.902 28314:Dummy-20 (name)s.statfs: statfs(): start > 2014-10-19 09:57:53.237 28314:Thread-6 (name)s.close: > ObjectW(s3ql_data_4).close(): start > 2014-10-19 09:57:53.238 28314:Thread-6 (name)s._do_request: preparing PUT > /MyPrefixs3ql_data_4?None, qs=None > 2014-10-19 09:57:53.239 28314:Thread-6 (name)s._send_request: > _send_request(): PUT /MyPrefixs3ql_data_4 > 2014-10-19 09:57:53.351 28314:Thread-5 (name)s.close: > ObjectW(s3ql_data_3).close(): start > 2014-10-19 09:57:53.352 28314:Thread-5 (name)s._do_request: preparing PUT > /MyPrefixs3ql_data_3?None, qs=None > 2014-10-19 09:57:53.353 28314:Thread-5 (name)s._send_request: > _send_request(): PUT /MyPrefixs3ql_data_3 > 2014-10-19 09:57:54.383 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:57:54.383 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:57:54.702 28314:Thread-3 (name)s.close: > ObjectW(s3ql_data_1).close(): start > 2014-10-19 09:57:54.702 28314:Thread-3 (name)s._do_request: preparing PUT > /MyPrefixs3ql_data_1?None, qs=None > 2014-10-19 09:57:54.703 28314:Thread-3 (name)s._send_request: > _send_request(): PUT /MyPrefixs3ql_data_1 > 2014-10-19 09:57:59.384 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:57:59.384 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:57:59.793 28314:Thread-4 (name)s.close: > ObjectW(s3ql_data_2).close(): start > 2014-10-19 09:57:59.794 28314:Thread-4 (name)s._do_request: preparing PUT > /MyPrefixs3ql_data_2?None, qs=None > 2014-10-19 09:57:59.795 28314:Thread-4 (name)s._send_request: > _send_request(): PUT /MyPrefixs3ql_data_2 > 2014-10-19 09:58:02.902 28314:Dummy-24 (name)s.statfs: statfs(): start > 2014-10-19 09:58:03.506 28314:Thread-6 (name)s.wrapped: Encountered > ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to > ObjectW.close for the 33-th time... > 2014-10-19 09:58:03.631 28314:Thread-5 (name)s.wrapped: Encountered > ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to > ObjectW.close for the 33-th time... > 2014-10-19 09:58:04.385 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:58:04.385 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:58:05.282 28314:Thread-3 (name)s.wrapped: Encountered > ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to > ObjectW.close for the 33-th time... > 2014-10-19 09:58:09.386 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:58:09.386 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:58:10.943 28314:Thread-4 (name)s.wrapped: Encountered > ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to > ObjectW.close for the 33-th time... > 2014-10-19 09:58:12.902 28314:Dummy-19 (name)s.statfs: statfs(): start > 2014-10-19 09:58:14.387 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:58:14.387 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:58:19.388 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:58:19.388 28314:CommitThread (name)s.put: waiting for > reader.. > 2014-10-19 09:58:22.902 28314:Dummy-18 (name)s.statfs: statfs(): start > 2014-10-19 09:58:24.389 28314:CommitThread (name)s.put: timeout, returning > 2014-10-19 09:58:24.389 28314:CommitThread (name)s.put: waiting for > reader.. > > Could you give some more context? In particular, I'd like to see the logs > from the 32st and 1st retry. > > Because of log rotations, I had to re-run the test to get the 1st and 32nd retry. This time more of the blocks managed to get uploaded. Some of the threads seemed to have better luck than others:
2014-10-19 16:15:35.030 22580:Dummy-21 (name)s.write: write(221, 282624, datalen=4096): start 2014-10-19 16:15:35.031 22580:Dummy-20 (name)s.write: write(221, 286720, datalen=4096): start 2014-10-19 16:15:35.031 22580:Dummy-19 (name)s.write: write(221, 290816, datalen=4096): start 2014-10-19 16:15:35.032 22580:Dummy-18 (name)s.flush: flush(221): start 2014-10-19 16:15:35.032 22580:Dummy-21 (name)s.release: release(221): start 2014-10-19 16:15:35.033 22580:Dummy-20 (name)s.getattr: getattr(39): start 2014-10-19 16:15:35.034 22580:Dummy-19 (name)s.getattr: getattr(221): start 2014-10-19 16:15:35.034 22580:Dummy-18 (name)s.setattr: setattr(221, st_atime=1413749735.0310807, st_atime_ns=1413749735031080803, st_mtime=0.0, st_mtime_ns=0): start 2014-10-19 16:15:35.035 22580:Dummy-18 (name)s.removexattr: removexattr(221, b'security.ima'): start 2014-10-19 16:15:35.036 22580:Dummy-21 (name)s.setattr: setattr(221, st_mode=33261): start 2014-10-19 16:15:35.036 22580:Dummy-21 (name)s.removexattr: removexattr(221, b'security.ima'): start 2014-10-19 16:15:35.037 22580:Dummy-20 (name)s.lookup: lookup(39, b'IMG_2789.JPG'): start 2014-10-19 16:15:35.037 22580:Dummy-19 (name)s.rename: rename(39, b'.IMG_2789.JPG.ce7SnF', 39, b'IMG_2789.JPG'): start 2014-10-19 16:15:35.038 22580:Dummy-19 (name)s.lookup: lookup(39, b'.IMG_2789.JPG.ce7SnF'): start 2014-10-19 16:15:35.038 22580:Dummy-19 (name)s.lookup: lookup(39, b'IMG_2789.JPG'): start 2014-10-19 16:15:35.039 22580:Dummy-19 (name)s.forget: forget([ (221, 1)]): start 2014-10-19 16:15:37.161 22580:Dummy-18 (name)s.statfs: statfs(): start 2014-10-19 16:15:39.819 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 16:15:39.820 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 16:15:41.661 22580:Thread-5 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 1-th time... 2014-10-19 16:15:41.681 22580:Thread-5 (name)s.close: ObjectW(s3ql_data_1).close(): start 2014-10-19 16:15:41.682 22580:Thread-5 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_1?None, qs=None 2014-10-19 16:15:41.682 22580:Thread-5 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_1 2014-10-19 16:15:42.165 22580:Thread-4 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 1-th time... 2014-10-19 16:15:42.186 22580:Thread-4 (name)s.close: ObjectW(s3ql_data_3).close(): start 2014-10-19 16:15:42.187 22580:Thread-4 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_3?None, qs=None 2014-10-19 16:15:42.188 22580:Thread-4 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_3 2014-10-19 16:15:42.453 22580:Thread-3 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 1-th time... 2014-10-19 16:15:42.474 22580:Thread-3 (name)s.close: ObjectW(s3ql_data_4).close(): start 2014-10-19 16:15:42.474 22580:Thread-3 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_4?None, qs=None 2014-10-19 16:15:42.475 22580:Thread-3 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_4 2014-10-19 16:15:43.718 22580:Thread-6 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 1-th time... 2014-10-19 16:15:43.738 22580:Thread-6 (name)s.close: ObjectW(s3ql_data_2).close(): start 2014-10-19 16:15:43.739 22580:Thread-6 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_2?None, qs=None 2014-10-19 16:15:43.740 22580:Thread-6 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_2 2014-10-19 16:15:44.820 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 16:15:44.821 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 16:15:47.161 22580:Dummy-21 (name)s.statfs: statfs(): start 2014-10-19 16:15:49.823 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 16:15:49.823 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 16:15:53.679 22580:Thread-5 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 2-th time... 2014-10-19 16:15:53.720 22580:Thread-5 (name)s.close: ObjectW(s3ql_data_1).close(): start 2014-10-19 16:15:53.720 22580:Thread-5 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_1?None, qs=None ------8<---*SNIP*8<----------- 2014-10-19 17:52:26.626 22580:CommitThread (name)s.upload: upload(<Dirty CacheEntry, inode=162, blockno=0>): created new block 41 2014-10-19 17:52:26.626 22580:CommitThread (name)s.upload: upload(<Dirty CacheEntry, inode=162, blockno=0>): adding to upload queue 2014-10-19 17:52:26.626 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:26.942 22580:Thread-4 (name)s.close: ObjectW(s3ql_data_40).close(): start 2014-10-19 17:52:26.942 22580:Thread-4 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_40?None, qs=None 2014-10-19 17:52:26.943 22580:Thread-4 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_40 2014-10-19 17:52:27.161 22580:Dummy-20 (name)s.statfs: statfs(): start 2014-10-19 17:52:31.626 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:31.627 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:36.627 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:36.628 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:36.968 22580:Thread-4 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 1-th time... 2014-10-19 17:52:36.989 22580:Thread-4 (name)s.close: ObjectW(s3ql_data_40).close(): start 2014-10-19 17:52:36.989 22580:Thread-4 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_40?None, qs=None 2014-10-19 17:52:36.990 22580:Thread-4 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_40 2014-10-19 17:52:37.161 22580:Dummy-19 (name)s.statfs: statfs(): start 2014-10-19 17:52:41.629 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:41.629 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:44.440 22580:Thread-6 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 32-th time... 2014-10-19 17:52:45.592 22580:Thread-3 (name)s.close: ObjectW(s3ql_data_38).close(): start 2014-10-19 17:52:45.592 22580:Thread-3 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_38?None, qs=None 2014-10-19 17:52:45.593 22580:Thread-3 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_38 2014-10-19 17:52:46.630 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:46.630 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:46.905 22580:Thread-5 (name)s.close: ObjectW(s3ql_data_1).close(): start 2014-10-19 17:52:46.906 22580:Thread-5 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_1?None, qs=None 2014-10-19 17:52:46.906 22580:Thread-5 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_1 2014-10-19 17:52:47.161 22580:Dummy-18 (name)s.statfs: statfs(): start 2014-10-19 17:52:47.658 22580:Thread-4 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 2-th time... 2014-10-19 17:52:47.699 22580:Thread-4 (name)s.close: ObjectW(s3ql_data_40).close(): start 2014-10-19 17:52:47.700 22580:Thread-4 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_40?None, qs=None 2014-10-19 17:52:47.700 22580:Thread-4 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_40 2014-10-19 17:52:51.631 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:51.631 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:56.195 22580:Thread-3 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 19-th time... 2014-10-19 17:52:56.632 22580:CommitThread (name)s.put: timeout, returning 2014-10-19 17:52:56.632 22580:CommitThread (name)s.put: waiting for reader.. 2014-10-19 17:52:57.161 22580:Dummy-21 (name)s.statfs: statfs(): start 2014-10-19 17:52:57.810 22580:Thread-5 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 32-th time... 2014-10-19 17:52:58.488 22580:Thread-4 (name)s.wrapped: Encountered ConnectionTimedOut exception (send/recv timeout exceeded), retrying call to ObjectW.close for the 3-th time... 2014-10-19 17:52:58.569 22580:Thread-4 (name)s.close: ObjectW(s3ql_data_40).close(): start 2014-10-19 17:52:58.570 22580:Thread-4 (name)s._do_request: preparing PUT /MyPrefixs3ql_data_40?None, qs=None 2014-10-19 17:52:58.570 22580:Thread-4 (name)s._send_request: _send_request(): PUT /MyPrefixs3ql_data_40 2014-10-19 17:53:01.633 22580:CommitThread (name)s.put: timeout, returning If I manually kill mount.s3ql and umount the filesystem, then run > fsck.s3ql, the cache does get uploaded (with some difficulty): > > $ fsck.s3ql --cachedir /data/s3ql-cache > gs://MyBucket/MyPrefix > > > Starting fsck of gs://MyBucket/MyPrefix > Using cached metadata. > Remote metadata is outdated. > Checking DB integrity... > Creating temporary extra indices... > Checking lost+found... > Checking cached objects... > Committing block 0 of inode 143 to backend > Committing block 0 of inode 289 to backend > Committing block 0 of inode 212 to backend > Committing block 0 of inode 338 to backend > Committing block 0 of inode 334 to backend > Committing block 0 of inode 154 to backend > Committing block 0 of inode 350 to backend > Committing block 0 of inode 354 to backend > Committing block 0 of inode 224 to backend > Committing block 0 of inode 215 to backend > Committing block 0 of inode 221 to backend > Committing block 0 of inode 339 to backend > Committing block 0 of inode 278 to backend > Committing block 0 of inode 178 to backend > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 3-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 4-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 5-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 6-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 7-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 8-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 9-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 10-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 11-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 12-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 13-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 14-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 15-th time... > Encountered ConnectionTimedOut exception (send/recv timeout exceeded), > retrying call to ObjectW.close for the 16-th time... > 2014-10-19 10:45:45.960 4472:MainThread (name)s.log_error: Committing > block 0 of inode 344 to backend > 2014-10-19 10:45:54.484 4472:MainThread (name)s.log_error: Committing > block 0 of inode 240 to backend > > > I'm stumped. Has anyone got an idea of what might be causing my problem? > > > Do you have the same problem when you store data in Amazon S3 from the > same system? > > Yes, I just tried Amazon and I get similar results. > Do you have the same problem when you store data in Google Storage, but > from a different system with a different internet connection? > > This will be a bit more difficult to test. I'll give it a try at my first opportunity. If you have the necessary SSL-fu, you could also do a traffic capture using > Wireshark. That's gonna be a bit tricky, but it should tell us a lot more. > > I've worked with tcpdump/wireshark before, but my SSL-fu is weak can you tell me what I should look for? Thanks, Rich B -- You received this message because you are subscribed to the Google Groups "s3ql" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/d/optout.
