error: unpack requires a string argument of length 4

[Francisco Reyes]

Is there a document stating how to report crashes? Was looking for one, but did not see it.

Other than output from mount log anything else we need to provide?

Have a volume I had populated with rsync without problems. Switched to unison and has been crashing.

First it was file descriptors, after increasing now got a new error. Going to try switching back to rsync and see if that finishes. Each unison run seems to take many hours before it crashes so will report more once I have been able to do more testing.

mount parameter:

mount.s3ql --cachesize 2048000 --cachedir /S3ql-cache --max-cache-entries 5000 --allow-other --metadata-upload-interval 3600 s3c://valid-bucket /valid-mount

ulimit is set to 25,000

Have another mount point with max cache entries set to 8000 that is not having any problems. Main difference between the two is that the one crashing the average file size is 126MB.

2012-11-10 06:34:48.301 [13731] Dummy-16: [fuse] Exception after kill:

Traceback (most recent call last):

  File "handlers.pxi", line 296, in llfuse.fuse_read (src/llfuse.c:6832)

  File "handlers.pxi", line 297, in llfuse.fuse_read (src/llfuse.c:6776)

  File "/usr/lib/s3ql/s3ql/fs.py", line 932, in read

    tmp = self._read(fh, offset, length)

  File "/usr/lib/s3ql/s3ql/fs.py", line 964, in _read

    with self.cache.get(id_, blockno) as fh:

  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__

    return self.gen.next()

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 538, in get

    el = backend.perform_read(do_read, 's3ql_data_%d' % obj_id)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 61, in wrapped

    return fn(self, *a, **kw)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 224, in perform_read

    return fn(fh)

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 533, in do_read

    shutil.copyfileobj(fh, el, BUFSIZE)

  File "/usr/lib/python2.7/shutil.py", line 49, in copyfileobj

    buf = fsrc.read(length)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 619, in read

    buf = self._read(BUFSIZE)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 703, in _read

    buf = self.fh.read(size)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 619, in read

    buf = self._read(BUFSIZE)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 858, in _read

    :self.remaining + self.off_size])[0]

error: unpack requires a string argument of length 4

2012-11-10 06:34:48.359 [13731] MainThread: [mount] Encountered exception, trying to clean up...

2012-11-10 06:34:48.359 [13731] MainThread: [mount] Unmounting file system...

2012-11-10 06:34:48.871 [13731] MainThread: [mount] Exception during cleanup:

Traceback (most recent call last):

  File "/usr/lib/s3ql/s3ql/mount.py", line 187, in main

    op()

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 275, in destroy

    os.rmdir(self.path)

OSError: [Errno 39] Directory not empty: '/S3ql-cache/s3c:=2F=2Fs.greenqloud.com=2Fnatserv-default-cache'

2012-11-10 06:34:48.872 [13731] MainThread: [root] Uncaught top-level exception:

Traceback (most recent call last):

  File "/usr/bin/mount.s3ql", line 9, in <module>

    load_entry_point('s3ql==1.12', 'console_scripts', 'mount.s3ql')()

  File "/usr/lib/s3ql/s3ql/mount.py", line 139, in main

    llfuse.main(options.single)

  File "fuse_api.pxi", line 213, in llfuse.main (src/llfuse.c:18034)

  File "handlers.pxi", line 296, in llfuse.fuse_read (src/llfuse.c:6832)

  File "handlers.pxi", line 297, in llfuse.fuse_read (src/llfuse.c:6776)

  File "/usr/lib/s3ql/s3ql/fs.py", line 932, in read

    tmp = self._read(fh, offset, length)

  File "/usr/lib/s3ql/s3ql/fs.py", line 964, in _read

    with self.cache.get(id_, blockno) as fh:

  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__

    return self.gen.next()

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 538, in get

    el = backend.perform_read(do_read, 's3ql_data_%d' % obj_id)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 61, in wrapped

    return fn(self, *a, **kw)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 224, in perform_read

    return fn(fh)

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 533, in do_read

    shutil.copyfileobj(fh, el, BUFSIZE)

  File "/usr/lib/python2.7/shutil.py", line 49, in copyfileobj

    buf = fsrc.read(length)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 619, in read

    buf = self._read(BUFSIZE)

 File "/usr/lib/s3ql/s3ql/backends/common.py", line 703, in _read

    buf = self.fh.read(size)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 619, in read

    buf = self._read(BUFSIZE)

  File "/usr/lib/s3ql/s3ql/backends/common.py", line 858, in _read

    :self.remaining + self.off_size])[0]

error: unpack requires a string argument of length 4

[Francisco Reyes]

On Saturday, November 10, 2012 7:01:32 AM UTC-5, Francisco Reyes wrote:

Have a volume I had populated with rsync without problems. Switched to unison and has been crashing.

Tried with rsync and now it is also crashing. After each crash have to use fusermount and fsck before can try again.

2012-11-10 16:26:45.411 [14495] MainThread: [mount] Encountered exception, trying to clean up...

2012-11-10 16:26:45.416 [14495] MainThread: [mount] Unmounting file system...

2012-11-10 16:26:46.281 [14495] MainThread: [mount] Exception during cleanup:

Traceback (most recent call last):

  File "/usr/lib/s3ql/s3ql/mount.py", line 187, in main

    op()

  File "/usr/lib/s3ql/s3ql/block_cache.py", line 275, in destroy

    os.rmdir(self.path)

OSError: [Errno 39] Directory not empty: '/S3ql-cache/s3c:=2F=2Fs.greenqloud.com=2Fnatserv-default-cache'

2012-11-10 16:26:46.289 [14495] MainThread: [root] Uncaught top-level exception:

2012-11-10 16:31:26.633 [10455] Metadata-Upload-Thread: [mount] File system unchanged, not uploading metadata.

[Francisco Reyes]

On Saturday, November 10, 2012 7:01:32 AM UTC-5, Francisco Reyes wrote:

Is there a document stating how to report crashes? Was looking for one, but did not see it.

Found  http://code.google.com/p/s3ql/wiki/ProvidingDebuggingInfo

When do I need to:

>Run setfattr -n fuse_stacktrace [mountpoint]

>Make a copy of the mount.log logfile in ~/.s3ql and attach it to your email or bug report

Before the crash? i.e.

Mount, run setfattr, try rsync/unison again to cause the crash?

Going to try and follow the instructions on providing debug info.. 

[Nikolaus Rath]

Hi Francesco,

Thanks for reporting this. Could you please open an issue on
http://code.google.com/p/s3ql/issues/list as well?

Unfortunately I don't think I'll have time to look into this before Mid
December, but I'll do my best.

You could help a lot if you could find a way for me to reliably
reproduce the problem (either starting from an empty volume, or by
giving me access to a test volume that has the problem). That'd make
debugging a lot easier for me.

You do not need to run setfattr, this is just for debugging a
hanging/frozen process.

According to the log, the error happens when data is read from the
backend, but I if I understood you correctly, you are using rsync to
*write* data. Is that correct? Or did you use the -c flag, so that rsync
might also be reading?



Best,

-Nikolaus

--
»Time flies like an arrow, fruit flies like a Banana.«

PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6 02CF A9AD B7F8 AE4E 425C

[Francisco Reyes]

On Saturday, November 10, 2012 5:18:42 PM UTC-5, Nikolaus Rath wrote:
>>Thanks for reporting this. Could you please open an issue on
>>http://code.google.com/p/s3ql/issues/list as well?

Will do.

>>Unfortunately I don't think I'll have time to look into this before Mid
>>December, but I'll do my best. 

Let me know what I can do to help.

One thing I could to that is near trivial is to re-run a few times and see if it always crashes on the same file.

>>You could help a lot if you could find a way for me to reliably
>>reproduce the problem

Will try, but we are talking about 100GB+

The entire set had already gotten uploaded without problems. This all started when I switched to unison instead of rsync. Whatever the problem seems to have stuck after that.

>> (either starting from an empty volume,

>> or by giving me access to a test volume that has the problem).

Will see what I can do.

>> That'd make debugging a lot easier for me. 

Ok.. in the mean time let me know if there is anything else.

>>You do not need to run setfattr, this is just for debugging a
>>hanging/frozen process. 

Ok

>>According to the log, the error happens when data is read from the
>>backend, but I if I understood you correctly, you are using rsync to
>>*write* data. Is that correct? Or did you use the -c flag, so that rsync
>>might also be reading?

Was using the -c flag so yes, it was reading.

Just had an idea.. will try and compute the MD5 of all the files and see if that triggers the problem and if so, in which file.

I think I will try:

* Attempt to compute md5 of all files

* If md5 does not crash try running rsync several times and see if it crashes on the same file

Both of those although time/bandwith/compute intensive use so little of my time that are worth trying. Specially if somehow they show it always crashes on the same file. Would make testing go a lot faster. Right now it is hours between crashes.

[Nikolaus Rath]

On 11/10/2012 06:47 PM, Francisco Reyes wrote:
>>>Unfortunately I don't think I'll have time to look into this before Mid
>>>December, but I'll do my best.
>
> Let me know what I can do to help.
> One thing I could to that is near trivial is to re-run a few times and
> see if it always crashes on the same file.
>
>>>You could help a lot if you could find a way for me to reliably
>>>reproduce the problem
>
> Will try, but we are talking about 100GB+
> The entire set had already gotten uploaded without problems. This all
> started when I switched to unison instead of rsync. Whatever the problem
> seems to have stuck after that.
>

>>>According to the log, the error happens when data is read from the
>>>backend, but I if I understood you correctly, you are using rsync to
>>>*write* data. Is that correct? Or did you use the -c flag, so that rsync
>>>might also be reading?
>
> Was using the -c flag so yes, it was reading.
> Just had an idea.. will try and compute the MD5 of all the files and see
> if that triggers the problem and if so, in which file.
>
> I think I will try:
> * Attempt to compute md5 of all files
> * If md5 does not crash try running rsync several times and see if it
> crashes on the same file
>
> Both of those although time/bandwith/compute intensive use so little of
> my time that are worth trying. Specially if somehow they show it always
> crashes on the same file. Would make testing go a lot faster. Right now
> it is hours between crashes.

From the error message, it seems that a storage object has not been
written correctly. Therefore, I expect that it will always crash at the
same time, and it should not matter how you read that file (md5sum,
unison, rsync). That said, this is a hypothesis so it should still be
tested.


If that is correct, then the more important question is really what went
wrong when the object was written. This can most likely not be
determined after the fact, thus my interested in reproducing the problem
with a fresh volume.

[Francisco Reyes]

On Sunday, November 11, 2012 11:33:09 AM UTC-5, Nikolaus Rath wrote:

>From the error message, it seems that a storage object has not been
>written correctly. Therefore, I expect that it will always crash at the
>same time

Ok. That should help.

Waiting to hear back from the cloud provider I am using to find out if I pay for bandwith between the VM and their cloud storage ( both at same provider. Got account few weeks ago and have not seen that info). If they charge for traffic between VM and storage then I may change provider and may not be able to continue troubleshooting otherwise every time I run an MD5 or "rsync -c" would be paying for bandwith.

>If that is correct, then the more important question is really what went
>wrong when the object was written. This can most likely not be
>determined after the fact

I guess in that case the best would be trap the error and mark the file as bad and delete it.

>, thus my interested in reproducing the problem with a fresh volume. 

Have a machine coming which will store 100GB + for a client. Will let you know if bump into that error.

[Nikolaus Rath]

On 11/11/2012 02:33 PM, Francisco Reyes wrote:
> On Sunday, November 11, 2012 11:33:09 AM UTC-5, Nikolaus Rath wrote:
>
>>From the error message, it seems that a storage object has not been
>>written correctly. Therefore, I expect that it will always crash at the
>>same time
>
> Ok. That should help.
> Waiting to hear back from the cloud provider I am using to find out if I
> pay for bandwith between the VM and their cloud storage ( both at same
> provider. Got account few weeks ago and have not seen that info). If
> they charge for traffic between VM and storage then I may change
> provider and may not be able to continue troubleshooting otherwise every
> time I run an MD5 or "rsync -c" would be paying for bandwith.
>
>>If that is correct, then the more important question is really what went
>>wrong when the object was written. This can most likely not be
>>determined after the fact
>
> I guess in that case the best would be trap the error and mark the file
> as bad and delete it.

Yeah, that'll correct the problem. I can give you a patch for that if
you want to.

However, I'm much more interested in finding out how the error got
produced, so that I can ensure it won't happen again. Your file
system/computer didn't by any chance crash while you were writing data
or something like that?

[Francisco Reyes]

On Sunday, November 11, 2012 3:41:11 PM UTC-5, Nikolaus Rath wrote:

>produced, so that I can ensure it won't happen again. Your file
>system/computer didn't by any chance crash while you were writing data
>or something like that?

The complete history of the error is..

Did rsync (without -c). Worked. Did it a few times over a few days without problems. 100GB+

Switched to unison. Crashed.

Unison kept crashing.

Figured during those crashes something may have gone wrong so switched to "rsync -c". Has been crashing ever since.

[Francisco Reyes]

On Saturday, November 10, 2012 7:01:32 AM UTC-5, Francisco Reyes wrote:

>>Have a volume I had populated with rsync without problems. Switched to unison and has been crashing.

Have an update.

Ran md5. It worked against the entire filesystem.

Ran rsync -c, now worked..

Ran rsync -c again.. still worked..

Tried unison again, crashed with the same error have been getting:

File "/usr/lib/s3ql/s3ql/backends/common.py", line 858, in _read

    :self.remaining + self.off_size])[0]

Did an md5 on the file unison reported, but it ran ok.

Trying rsync -c again..

[Francisco Reyes]

Not sure what impact this has, but I discovered a significant amount of packet drops on the last hops between source and destination. Between 15% and 70%.

Starting to wonder if the times I tried unison this was occurring or if it is that unison is more susceptible to fail and somehow corrupt a file in S3QL due to bad connectivity. 

[Nikolaus Rath]

Can you ran unison only on that file? Or maybe that file + the previous
3 and next 3?

[Francisco Reyes]

On Wednesday, November 14, 2012 8:47:00 AM UTC-5, Nikolaus Rath wrote:
>Can you ran unison only on that file? Or maybe that file + the previous
>3 and next 3?

Will setup unison to do the folder after the current rsync finishes.

I use this setup for offsite backup so once a day or every two days I upload whatever has changed. The file that crashed I don't believe even has been changed in a while so don't expect the current rsync that is running now to change it.

Also, heard back from the cloud provider, GreenQloud, and they are telling me the dropped packets as reported by mtr are normal.. even if I don't see that behavior with any other provider I use..

Will report back once the current backup/rsync finishes and try again unison.

[Francisco Reyes]

I finished an "rsync -c" on a set of data earlier today.

Ran it again, just as a tets.

No crashes.

Tried unison and it crashed.

Did fsck.

Changed  unison to run on just the folder that had crashed before. It crashed again.

Did fsck again.

Did md5sum of all files in the folder unison was crashing. No problems.

Ran unison again. This time instead of crashing it detected a single file as different. There is no way that file could have changed. Nothing updated it and had run two rsync -c today.

Is it possible the fsck changed it? Shouldn't the fsck have deleted/moved to lost+found.. the file?

Unison is not set to do checksum right now.. so it is possible only attributes may have changed.. but even that would fsck have changed any attributes?

[Francisco Reyes]

Wrote too soon...

Unison just crashed again.

I guess I can say that found a folder that is consistently crashing s3ql when I run unison against it.

[Nikolaus Rath]

Hmm. I just can't get a clear picture of what is happening. Here are my
thoughts:

* Any file whose contents are touched by fsck will be moved to lost+found

* fsck may change file attributes if they are corrupted, but it will
always report this

* The S3QL crash happens in a function whose only parameter is the name
of the storage object that needs to be retrieved. I can not imagine how
this can possibly fail with unison but work with rsync and md5sum.

* The S3QL crash can only happen if some process is reading file system
data. So either your crash is not actually produced by unison but some
other process, or unison is doing more than comparing checksums.

* If you do not write any data, fsck should not find any errors. If you
want, I can give you a special fsck that just marks the file system as
intact (so save time when testing). Let me know if you want it.

* We need to get more logging information. Running mount.s3ql with
--debug, and unison under strace will do that, but the information is
only useful if it isn't too much. How big is the folder that seems to be
consistently crashing?

* Did you flush the S3QL cache between the different runs of unison,
rsync and md5sum? If not, this may explain the different results.

* How many unison/rsync/md5sum runs have you done in total? So far, the
most likely explanation is still that S3QL fails to detect some data
corruption when retrieving data from the network. But in that case the
differences with rsync et al would need to be by chance...


I'm sorry that this is so hard to debug. I very much appreciate the time
you're spending on this.

[Francisco Reyes]

On Thursday, November 15, 2012 2:36:15 PM UTC-5, Nikolaus Rath wrote:

Before I reply..

Today was doing a "rsync -c" and it crashed.

It is the first time it crashes with rsync.

>>Hmm. I just can't get a clear picture of what is happening. Here are my
>>thoughts: 

I am tempted to create a new bucket and move everything over.

 >* The S3QL crash happens in a function whose only parameter is the name
>of the storage object that needs to be retrieved. I can not imagine how
>this can possibly fail with unison but work with rsync and md5sum. 

Not sure why has happened, or changed, but this time it crashed with rsync -c, for the first time.

>* The S3QL crash can only happen if some process is reading file system
>data. So either your crash is not actually produced by unison but some
>other process, or unison is doing more than comparing checksums. 

So far, have not had a crash with regular rsync. The reason unison is doing a checksum check is because it is the first pass. Have yet to have a single clean pass with unison.

>* If you do not write any data, fsck should not find any errors. If you
>want, I can give you a special fsck that just marks the file system as
>intact (so save time when testing). Let me know if you want it.

My biggest concern is to help you figure out what is going on. This is just backup and I have all data  in at least a second machine. This is my offsite, disaster recovery backup.

>>* We need to get more logging information. Running mount.s3ql with
>>--debug, and unison under strace will do that, but the information is
>>only useful if it isn't too much. How big is the folder that seems to be
>>consistently crashing? 

244 files, 9.3G

>* Did you flush the S3QL cache between the different runs of unison,
>rsync and md5sum? If not, this may explain the different results. 

No. How would I do that?

s3qlctrl  flushcache ?

>* How many unison/rsync/md5sum runs have you done in total?

Hm.. Don't recall exact number, but somewhere around:

5 md5s

10 rsyncs

4 unison

The reason so many more rsyncs is that I have been doing backups any time I have some important data I want to backup, in addition to probably 4 to 6 that were just testing.

>most likely explanation is still that S3QL fails to detect some data
>corruption when retrieving data from the network. But in that case the
>differences with rsync et al would need to be by chance...

Agree that it is something along those lines.

>I'm sorry that this is so hard to debug. I very much appreciate the time
>you're spending on this.

Not at all. I am grateful for all your work with this program and I am glad to help in any way I can.

What really has me puzzled is that it has never crashed with the md5s.

Going to flush the cache and try a md5.

[Nikolaus Rath]

On 11/17/2012 06:43 PM, Francisco Reyes wrote:
> On Thursday, November 15, 2012 2:36:15 PM UTC-5, Nikolaus Rath wrote:
>
> Before I reply..
> Today was doing a "rsync -c" and it crashed.
> It is the first time it crashes with rsync.
>
>
>>>Hmm. I just can't get a clear picture of what is happening. Here are my
>>>thoughts:
>
> I am tempted to create a new bucket and move everything over.
>
> >* The S3QL crash happens in a function whose only parameter is the name
>>of the storage object that needs to be retrieved. I can not imagine how
>>this can possibly fail with unison but work with rsync and md5sum.
>
> Not sure why has happened, or changed, but this time it crashed with
> rsync -c, for the first time.

Ah. That's a good think, actually. It confirms my theory :-).

>>* The S3QL crash can only happen if some process is reading file system
>>data. So either your crash is not actually produced by unison but some
>>other process, or unison is doing more than comparing checksums.
>
> So far, have not had a crash with regular rsync. The reason unison is
> doing a checksum check is because it is the first pass. Have yet to have
> a single clean pass with unison.

Ah, ok.

>>>* We need to get more logging information. Running mount.s3ql with
>>>--debug, and unison under strace will do that, but the information is
>>>only useful if it isn't too much. How big is the folder that seems to be
>>>consistently crashing?
>
> 244 files, 9.3G

Ok, that would produce way to much information in the logs. In any case,
I am pretty sure that there is no specific damaged file here but a
random network problem.

>>* Did you flush the S3QL cache between the different runs of unison,
>>rsync and md5sum? If not, this may explain the different results.
>
> No. How would I do that?
> s3qlctrl flushcache ?

Exactly.

>
>>* How many unison/rsync/md5sum runs have you done in total?
>
> Hm.. Don't recall exact number, but somewhere around:
> 5 md5s
> 10 rsyncs
> 4 unison

Ok, if we combine this with the cache not being flushed, then I'm
relatively confident that it was just by chance that unison appeared to
fail but rsync appeared to work.



As soon as I have time for some coding, I'm going to implement some
extra checks (based on my guess of it being a network problem) and send
you a patch. That will hopefully confirm my theory and either allow me
to fix the problem or allow you to complain to your storage provider
:-). (but I guess even then I should change S3QL to generate a more
useful error message instead of just crashing).

[Francisco Reyes]

On Saturday, November 17, 2012 7:09:18 PM UTC-5, Nikolaus Rath wrote:

>>> s3qlctrl flushcache ?

>Exactly. 

Md5 just crashed.

>As soon as I have time for some coding, I'm going to implement some
>extra checks (based on my guess of it being a network problem) and send
>you a patch.

Thanks.

How come fsck is not catching there is a problem?

[Francisco Reyes]

Just saw the  note in tickett 374. 

How about also making it so instead of crashing the file in question is marked bad instead?

[Nikolaus Rath]

On 11/17/2012 07:22 PM, Francisco Reyes wrote:
>>As soon as I have time for some coding, I'm going to implement some
>>extra checks (based on my guess of it being a network problem) and send
>>you a patch.
>
> Thanks.
>
> How come fsck is not catching there is a problem?

Well, because it's probably a network problem. The file system is
perfectly alright :-).

[Nikolaus Rath]

On 11/17/2012 07:24 PM, Francisco Reyes wrote:

I don't think there's anything wrong with the file, it's just that
occasionally data isn't transferred correctly.

I bet that if you flush the cache and try reading the file again a few
times, it's going to work some times.

[john]

Hi

my s3ql evaluation system crashes with the same error, when doing a rsync -c. So maybe I can help debugging. I am a professional software developer, so I know one or two strategies to hunt a bug. But I have only a very basic understainding of python, doing mainly C.

My installation is different, as I do rsync between two disks connected to the same machine. But the s3ql filesystem is running on top of a network mounted sshfs filesystem, so it is a network based rsync.

It seems to crash at different files, but I will dig into that a little bit before making a definate statement.

However, I think it might help to know that this bug shows up on a machine which does only internal network traffic. So the crash isn't raised by heavy network errors. A more stable network connection would be hard to get.

Except sshfs does introduce network errors. Maybe I should check if the crash is triggered without sshfs.

cu
John

[Nikolaus Rath]

On 12/05/2012 10:56 AM, john wrote:
> Hi
>
> my s3ql evaluation system crashes with the same error, when doing a
> rsync -c. So maybe I can help debugging. I am a professional software
> developer, so I know one or two strategies to hunt a bug. But I have
> only a very basic understainding of python, doing mainly C.
>
> My installation is different, as I do rsync between two disks connected
> to the same machine. But the s3ql filesystem is running on top of a
> network mounted sshfs filesystem, so it is a network based rsync.
>
> It seems to crash at different files, but I will dig into that a little
> bit before making a definate statement.

If the same file can sometimes be read correctly, and sometimes not,
then I know what the problem is. Just have to find a free minute to
write a patch.

Thanks for your help!

[Nikolaus Rath]

On 12/05/2012 06:02 PM, Nikolaus Rath wrote:
> On 12/05/2012 10:56 AM, john wrote:
>> Hi
>>
>> my s3ql evaluation system crashes with the same error, when doing a
>> rsync -c. So maybe I can help debugging. I am a professional software
>> developer, so I know one or two strategies to hunt a bug. But I have
>> only a very basic understainding of python, doing mainly C.
>>
>> My installation is different, as I do rsync between two disks connected
>> to the same machine. But the s3ql filesystem is running on top of a
>> network mounted sshfs filesystem, so it is a network based rsync.
>>
>> It seems to crash at different files, but I will dig into that a little
>> bit before making a definate statement.
>
> If the same file can sometimes be read correctly, and sometimes not,
> then I know what the problem is. Just have to find a free minute to
> write a patch.

Just attached a patch to
https://code.google.com/p/s3ql/issues/detail?id=374. It'd be great if
you could test it.


Best,

[john]

Hi Nikolaus

Before you posted your patch I started a "rsync --checksum --dry-run" operation on a locally mounted s3ql filesystem (no sshfs involved). This resulted in the same type of error and definitely at a different file position as in the other test runs.

rsync starts showing failures on a directory with 1107 files (without . and ..). Let's name them file_0001 to file_1107 for an easier description of what happened. What I got on the terminal, where rsync was running, was:

dir_1/.../dir_A    <--- normal rsync output of the processed directory
rsync: recv_generator: failed to stat "/s3ql_mount_point/backup_dir/dir_1/.../dir_B/file_0972": Transport endpoint is not connected (107)
... skipping 133 lines of output with the same error for file_0973 to file_1106
rsync: recv_generator: failed to stat "/s3ql_mount_point/backup_dir/dir_1/.../dir_B/file_1107": Transport endpoint is not connected (107)
dir_1/.../dir_B/file_0971

So, rsync reports a normal copy operation of file_0971 after giving an error for all files following file_0971 in the same directory.

From here on every file is reported by rsync as changed, as if it would read on an empty directory while accessing /s3ql_mount_point. However a "ls /s3ql_mount_point" results in:
ls: cannot access /s3ql_mount_point: Transport endpoint is not connected

That's a little confusing at first sight, but it would not produce any harm here. If rsync would be running without --dry-run, the destination could not be written. Still it's not an expected result.
I wonder what would happen, if the s3ql filesystem would be the source of the rsync operation. Would it overwrite all destination data beginning at the point of the failure? I could make a test with --dry-run. But maybe that isn't a good test, as rsync would only detect a change, but skip the copy operation. Testing without --dry-run is not possible with this data set, as this would overwrite valuable data.

As next step I will apply the patch and start another test run.

Have a nice day
John

[Nikolaus Rath]

On 12/08/2012 04:08 AM, john wrote:
> Hi Nikolaus
>
> Before you posted your patch I started a "rsync --checksum --dry-run"
> operation on a locally mounted s3ql filesystem (no sshfs involved). This
> resulted in the same type of error and definitely at a different file
> position as in the other test runs.

Hmm. That is worrying. I don't see this being caused by the bug that I
fixed with the last patch. Still, it'd be worthwhile to see if the patch
changes anything.

What's the size of the test data set you are using, and how often does
the error happen? If it happens with the local backend as well, then I
will hopefully be able to reproduce it.

>
> rsync starts showing failures on a directory with 1107 files (without .
> and ..). Let's name them file_0001 to file_1107 for an easier
> description of what happened. What I got on the terminal, where rsync
> was running, was:
>
> dir_1/.../dir_A <--- normal rsync output of the processed directory
> rsync: recv_generator: failed to stat
> "/s3ql_mount_point/backup_dir/dir_1/.../dir_B/file_0972": Transport
> endpoint is not connected (107)
> ... skipping 133 lines of output with the same error for file_0973 to
> file_1106
> rsync: recv_generator: failed to stat
> "/s3ql_mount_point/backup_dir/dir_1/.../dir_B/file_1107": Transport
> endpoint is not connected (107)
> dir_1/.../dir_B/file_0971
>
> So, rsync reports a normal copy operation of file_0971 after giving an
> error for all files following file_0971 in the same directory.

Yeah, that's expected. S3QL crashed at file_0971, so afterwards the
mountpoint is not accessible anymore. This is what "Transport Endpoint
not connected" means.

> From here on every file is reported by rsync as changed, as if it would
> read on an empty directory while accessing /s3ql_mount_point. However a
> "ls /s3ql_mount_point" results in:
> ls: cannot access /s3ql_mount_point: Transport endpoint is not connected
>
> That's a little confusing at first sight, but it would not produce any
> harm here. If rsync would be running without --dry-run, the destination
> could not be written. Still it's not an expected result.
> I wonder what would happen, if the s3ql filesystem would be the source
> of the rsync operation. Would it overwrite all destination data
> beginning at the point of the failure? I could make a test with
> --dry-run. But maybe that isn't a good test, as rsync would only detect
> a change, but skip the copy operation. Testing without --dry-run is not
> possible with this data set, as this would overwrite valuable data.

rsync is smart enough to detect this and will not perform any updates on
the receiving side. From rsync(1):

> If the sending side detects any I/O errors, then the deletion of any files at the destina‐
> tion will be automatically disabled. This is to prevent temporary filesystem failures (such
> as NFS errors) on the sending side from causing a massive deletion of files on the destina‐
> tion. You can override this with the --ignore-errors option.

[john]

Hi Nikolaus

What's the size of the test data set you are using, and how often does the error happen? If it happens with the local backend as well, then I will hopefully be able to reproduce it.

About 2.5TB. I did quite some rsync runs without --checksum and some s3qlcp on the whole dataset. Then, as a data integrity check, run rsync with --checksum. This failed on first try and ever since after.

[Francisco Reyes]

On Mon, Dec 10, 2012 at 6:42 AM, john <sas...@googlemail.com> wrote:
> About 2.5TB. I did quite some rsync runs without --checksum and some s3qlcp
> on the whole dataset. Then, as a data integrity check, run rsync with
> --checksum. This failed on first try and ever since after.

Did you try flushing the cache?
That seemed to help when I had the same problem

[john]

With the patch applied, I get this:



Traceback (most recent call last):
  File "/usr/bin/mount.s3ql-2.7", line 9, in <module>
    load_entry_point('s3ql==1.12', 'console_scripts', 'mount.s3ql')()
  File "/usr/lib64/python2.7/site-packages/s3ql/mount.py", line 139, in main
    llfuse.main(options.single)
  File "fuse_api.pxi", line 213, in llfuse.main (src/llfuse.c:18034)
  File "handlers.pxi", line 528, in llfuse.fuse_getxattr (src/llfuse.c:11337)
  File "handlers.pxi", line 529, in llfuse.fuse_getxattr (src/llfuse.c:11283)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 177, in getxattr
    return self.extstat()
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 795, in extstat
    entries = self.db.get_val("SELECT COUNT(rowid) FROM contents")
  File "/usr/lib64/python2.7/site-packages/s3ql/database.py", line 179, in get_val
    return self.get_row(*a, **kw)[0]
  File "/usr/lib64/python2.7/site-packages/s3ql/database.py", line 193, in get_row
    res = ResultSet(self._execute(*a, **kw))
  File "/usr/lib64/python2.7/site-packages/s3ql/database.py", line 157, in _execute
    return self.conn.cursor().execute(statement)
  File "src/cursor.c", line 231, in resetcursor
CorruptError: CorruptError: database disk image is malformed

[john]

Did you try flushing the cache?
That seemed to help when I had the same problem

Parallel to the rsync I did run a shell script that called "s3qlctrl flushcache" every minute. Result: Same error...

[john]

And fsck now reports this (for the first time):

Using cached metadata.
Remote metadata is outdated.
Checking DB integrity...
Local metadata is corrupted. Remove or repair the following files manually and re-run fsck:
/home/root/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs.db (corrupted)
/home/root/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs.param (intact)

Don't be confused by the bucket path: It really is locally mounted, not above sshfs. I just replaced the sshfs mount by "mount -bind", so didn't have to change anything else.

[john]

Local metadata is corrupted. Remove or repair the following files manually and re-run fsck:

After deleting the mentioned metadata, fsck gives me a "no space on device error", see below. As the path isn't listed: Which device is the problem? Because ~/.s3ql lies on a device with about 250GB free space.

 Dumping metadata...
..objects..
..blocks..
..inodes..
Uncaught top-level exception:

Traceback (most recent call last):

  File "/usr/bin/fsck.s3ql-2.7", line 9, in <module>
    load_entry_point('s3ql==1.12', 'console_scripts', 'fsck.s3ql')()
  File "/usr/lib64/python2.7/site-packages/s3ql/fsck.py", line 1214, in main
    dump_metadata(db, fh)
  File "/usr/lib64/python2.7/site-packages/s3ql/metadata.py", line 98, in dump_metadata
    dump_table(table, order, columns, db=db, fh=fh)
  File "_deltadump.pyx", line 172, in s3ql._deltadump.dump_table (src/s3ql/_deltadump.c:1306)
  File "_deltadump.pyx", line 216, in s3ql._deltadump._dump_or_load (src/s3ql/_deltadump.c:2793)
  File "_deltadump.pyx", line 274, in s3ql._deltadump._dump_or_load (src/s3ql/_deltadump.c:2739)
  File "_deltadump.pyx", line 308, in s3ql._deltadump._dump_table (src/s3ql/_deltadump.c:3113)
  File "_deltadump.pyx", line 407, in s3ql._deltadump.write_integer (src/s3ql/_deltadump.c:4104)
  File "_deltadump.pyx", line 101, in s3ql._deltadump.fwrite (src/s3ql/_deltadump.c:750)
IOError: [Errno 28] No space left on device


Thanks
John

[Nikolaus Rath]

That'd be in the default place for temporary files, so probably either /tmp or /var/tmp.


Best,
Niko

[john]

Hi Nikolaus

That'd be in the default place for temporary files, so probably either /tmp or /var/tmp.

Makes sense, as tmp is 1G, but the local database in .s3ql needs about 2.5G.
But strange enough, running fsck for the second time finished without an error, although the free storage space on all volumes didn't change. How could that be?
Is there any relation between needed tmp filesystem size and maximum file size in the s3ql filesystem?
I looked for an configuration variable to change the tmp folder to a filesystem with more free space, but didn't find it in the documentation. Can this be configured?

[Nikolaus Rath]

On 12/11/2012 02:49 AM, john wrote:

Hi Nikolaus

That'd be in the default place for temporary files, so probably either /tmp or /var/tmp.

Makes sense, as tmp is 1G, but the local database in .s3ql needs about 2.5G.
But strange enough, running fsck for the second time finished without an error, although the free storage space on all volumes didn't change. How could that be?

Not sure. Maybe you've had other programs accessing /tmp at the same time?

Is there any relation between needed tmp filesystem size and maximum file size in the s3ql filesystem?

Yes. The bigger the file system, the more tmp space required :-). I don't have exact numbers.

I looked for an configuration variable to change the tmp folder to a filesystem with more free space, but didn't find it in the documentation. Can this be configured?

Yes, S3QL just uses the system default. You can overwrite it using the TMPDIR, TEMP or TMP environment variables.

Best,
Niko

[john]

On Tuesday, December 11, 2012 6:00:01 PM UTC+1, Nikolaus Rath wrote:

Is there any relation between needed tmp filesystem size and maximum file size in the s3ql filesystem?

Yes. The bigger the file system, the more tmp space required :-). I don't have exact numbers.

No no, I didn't mean it that way. It's obvious that a bigger filesystem needs more local storage. I meant: Does the maximum single file size relate to local store size. For example how does a filesystem with 100.000 file, each of 1MB in size compare with a filesystem holding a single file with 100GB (like in my case a virtual machine image). My first guess would be, that the 100.000 files fs needs more tmp space, because it contains more metadata. But maybe the 100GB file is temporarily stored locally...

I looked for an configuration variable to change the tmp folder to a filesystem with more free space, but didn't find it in the documentation. Can this be configured?

Yes, S3QL just uses the system default. You can overwrite it using the TMPDIR, TEMP or TMP environment variables.

Thanks, I will check this. Would be to bad, if most of the debug runs aren't very valuable because of to less temporary space.
 
Have a nice day
Alexander

[john]

Another test run later...

What I did:
1. # rm ~/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs*
2. # fsck.s3ql local:///home/root/s3ql/s3qlbucket_via_sshfs
3. mount local:///home/root/s3ql/s3qlbucket_via_sshfs ...
4. rsync --checksum --dry-run ...

Remember: /home/root/s3ql/s3qlbucket_via_sshfs is a locally mounted filesystem without any network layer involved. The path /home/root/s3ql/s3qlbucket_via_sshfs might give a wrong impression, as the system is intended to run via sshfs.

So, here's the error log:

2012-12-12 21:59:08.082 [12384] Dummy-22: [fs] Backend returned malformed data for block 51 of inode 29258561 (HMAC mismatch)
2012-12-12 21:59:08.744 [12384] Dummy-23: [fs] Backend returned malformed data for block 51 of inode 29258561 (HMAC mismatch)
2012-12-12 21:59:08.745 [12384] Dummy-23: [fuse] Exception after kill:

Traceback (most recent call last):

  File "handlers.pxi", line 296, in llfuse.fuse_read (src/llfuse.c:6832)
  File "handlers.pxi", line 297, in llfuse.fuse_read (src/llfuse.c:6776)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 932, in read
    tmp = self._read(fh, offset, length)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 964, in _read
    with self.cache.get(id_, blockno) as fh:
  File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 538, in get
    el = backend.perform_read(do_read, 's3ql_data_%d' % obj_id)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 61, in wrapped
    return fn(self, *a, **kw)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 224, in perform_read
    return fn(fh)
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 533, in do_read
    shutil.copyfileobj(fh, el, BUFSIZE)
  File "/usr/lib64/python2.7/shutil.py", line 49, in copyfileobj
    buf = fsrc.read(length)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 619, in read
    buf = self._read(BUFSIZE)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 703, in _read
    buf = self.fh.read(size)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 619, in read
    buf = self._read(BUFSIZE)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 870, in _read
    raise ChecksumError('HMAC mismatch')
ChecksumError: HMAC mismatch
2012-12-12 21:59:09.267 [12384] MainThread: [mount] Encountered exception, trying to clean up...
2012-12-12 21:59:09.269 [12384] MainThread: [mount] Unmounting file system...
2012-12-12 22:00:50.243 [12384] MainThread: [mount] Exception during cleanup:

Traceback (most recent call last):

  File "/usr/lib64/python2.7/site-packages/s3ql/mount.py", line 187, in main
    op()
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 275, in destroy
    os.rmdir(self.path)
OSError: [Errno 39] Directory not empty: '/home/root/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs-cache'
2012-12-12 22:00:50.287 [12384] MainThread: [root] Uncaught top-level exception:

Traceback (most recent call last):

  File "/usr/bin/mount.s3ql-2.7", line 9, in <module>
    load_entry_point('s3ql==1.12', 'console_scripts', 'mount.s3ql')()
  File "/usr/lib64/python2.7/site-packages/s3ql/mount.py", line 139, in main
    llfuse.main(options.single)
  File "fuse_api.pxi", line 213, in llfuse.main (src/llfuse.c:18034)

  File "handlers.pxi", line 296, in llfuse.fuse_read (src/llfuse.c:6832)
  File "handlers.pxi", line 297, in llfuse.fuse_read (src/llfuse.c:6776)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 932, in read
    tmp = self._read(fh, offset, length)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 964, in _read
    with self.cache.get(id_, blockno) as fh:
  File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 538, in get
    el = backend.perform_read(do_read, 's3ql_data_%d' % obj_id)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 61, in wrapped
    return fn(self, *a, **kw)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 224, in perform_read
    return fn(fh)
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 533, in do_read
    shutil.copyfileobj(fh, el, BUFSIZE)
  File "/usr/lib64/python2.7/shutil.py", line 49, in copyfileobj
    buf = fsrc.read(length)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 619, in read
    buf = self._read(BUFSIZE)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 703, in _read
    buf = self.fh.read(size)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 619, in read
    buf = self._read(BUFSIZE)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 870, in _read
    raise ChecksumError('HMAC mismatch')
ChecksumError: HMAC mismatch

[Nikolaus Rath]

Hi John,

It'd be great if you could quote the parts of the message that you're
replying to, and put your own text below the quote (see
http://email.about.com/cs/netiquettetips/qt/et090402.htm for an
example). I prefer this style on mailing lists like this, because it
makes it much easier for others to follow the discussion. Thanks!

john <sas...@googlemail.com> writes:
> Another test run later...
>
> What I did:
> 1. # rm ~/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs*
> 2. # fsck.s3ql local:///home/root/s3ql/s3qlbucket_via_sshfs
> 3. mount local:///home/root/s3ql/s3qlbucket_via_sshfs ...
> 4. rsync --checksum --dry-run ...
>
> Remember: /home/root/s3ql/s3qlbucket_via_sshfs is a locally mounted
> filesystem without any network layer involved. The path
> /home/root/s3ql/s3qlbucket_via_sshfs might give a wrong impression, as the
> system is intended to run via sshfs.
>
> So, here's the error log:
>
> 2012-12-12 21:59:08.082 [12384] Dummy-22: [fs] Backend returned malformed
> data for block 51 of inode 29258561 (HMAC mismatch)

Ok, that's an improvement.

When you try to access this file multiple times, does it always crash,
or only sometimes?

You can run stat <file> and check that the inode is 29258561 to make
sure that you're testing the right file.


Thanks,

[john]

Hi Nikolaus

Happy New Year and Happy Bug Hunting

the story so far...

Last year I did some integrity tests with a s3ql filesystem on a locally attached harddisk, mounted with an sshfs layer in between. Basically the tests consisted of "rsync --checksum --dry-run ..." and lead to various errors reported in this thread before.

Now for a little surprise:
While digging into this further after my last post here the harddisk started to give I/O-errors. The badblocks program and S.M.A.R.T. self tests showed thousands of read errors. Obviously the drive was defect, so I got an replacement disk.

I then copied all the data of the old, bad drive to the new one. This means that the new drive now holds a s3ql filesystem with various invalid data blocks, where the old drive could not be read anymore.

A nice little test to check how s3ql deals with data corruption, I thought, and run fsck.s3ql followed by the "rsync ..." again.

After some hours it gave an exception and unmounted the filesystem. Not nice, as this means, that some corrupt data blocks prevent you from accessing still valid data. Is this the intended behaviour? Are my assumptions okay? And of course: What to do next to improve s3ql?
Remember: The data itself is only test data, than can be deleted. So I am quite relaxed. But it makes me wonder, if it's a good idea currently to store valuable data on a s3ql fs.

cu
John

mount.log showing the exception:

2013-01-10 04:10:19.533 [9446] MainThread: [mount] Using 8 upload threads.
2013-01-10 04:10:22.415 [9446] MainThread: [mount] Using cached metadata.
2013-01-10 04:10:24.585 [9446] MainThread: [mount] Mounting filesystem...
2013-01-10 04:10:24.820 [9474] MainThread: [daemonize] Daemonizing, new PID is 9475
2013-01-10 23:40:38.520 [9475] Dummy-22: [fs] Backend returned malformed data for block 33 of inode 866932 (Invalid compressed stream)
2013-01-10 23:40:39.277 [9475] Dummy-23: [fs] Backend returned malformed data for block 33 of inode 866932 (Invalid compressed stream)
2013-01-10 23:40:39.294 [9475] Dummy-23: [fuse] Exception after kill:

Traceback (most recent call last):
  File "handlers.pxi", line 296, in llfuse.fuse_read (src/llfuse.c:6832)
  File "handlers.pxi", line 297, in llfuse.fuse_read (src/llfuse.c:6776)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 932, in read
    tmp = self._read(fh, offset, length)
  File "/usr/lib64/python2.7/site-packages/s3ql/fs.py", line 964, in _read
    with self.cache.get(id_, blockno) as fh:
  File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 538, in get
    el = backend.perform_read(do_read, 's3ql_data_%d' % obj_id)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 61, in wrapped
    return fn(self, *a, **kw)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 224, in perform_read
    return fn(fh)
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 533, in do_read
    shutil.copyfileobj(fh, el, BUFSIZE)
  File "/usr/lib64/python2.7/shutil.py", line 49, in copyfileobj
    buf = fsrc.read(length)
  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 619, in read
    buf = self._read(BUFSIZE)

  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 713, in _read
    raise ChecksumError('Invalid compressed stream')
ChecksumError: Invalid compressed stream
2013-01-10 23:40:40.348 [9475] MainThread: [mount] Encountered exception, trying to clean up...
2013-01-10 23:40:40.353 [9475] MainThread: [mount] Unmounting file system...
2013-01-10 23:41:07.421 [9475] MainThread: [mount] Exception during cleanup:

Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/s3ql/mount.py", line 187, in main
    op()
  File "/usr/lib64/python2.7/site-packages/s3ql/block_cache.py", line 275, in destroy
    os.rmdir(self.path)
OSError: [Errno 39] Directory not empty: '/home/root/.s3ql/local:=2F=2F=2Fhome=2Froot=2Fs3ql=2Fs3qlbucket_via_sshfs-cache'

2013-01-10 23:41:07.477 [9475] MainThread: [root] Uncaught top-level exception:

  File "/usr/lib64/python2.7/site-packages/s3ql/backends/common.py", line 713, in _read
    raise ChecksumError('Invalid compressed stream')
ChecksumError: Invalid compressed stream

[Nikolaus Rath]

On 01/14/2013 10:21 AM, john wrote:
>
> Hi Nikolaus
>
> Happy New Year and Happy Bug Hunting
>
> the story so far...
>
> Last year I did some integrity tests with a s3ql filesystem on a
> locally attached harddisk, mounted with an sshfs layer in between.
> Basically the tests consisted of "rsync --checksum --dry-run ..." and
> lead to various errors reported in this thread before.
>
> Now for a little surprise:
> While digging into this further after my last post here the harddisk
> started to give I/O-errors. The badblocks program and S.M.A.R.T. self
> tests showed thousands of read errors. Obviously the drive was defect,
> so I got an replacement disk.

Ah, that's actually what I hoped for. I really couldn't think of any
other explanation :-).

>
> I then copied all the data of the old, bad drive to the new one. This
> means that the new drive now holds a s3ql filesystem with various
> invalid data blocks, where the old drive could not be read anymore.
>
> A nice little test to check how s3ql deals with data corruption, I
> thought, and run fsck.s3ql followed by the "rsync ..." again.
>
> After some hours it gave an exception and unmounted the filesystem.
> Not nice, as this means, that some corrupt data blocks prevent you
> from accessing still valid data. Is this the intended behaviour? Are
> my assumptions okay? And of course: What to do next to improve s3ql?

The current S3QL idea is to fail as loudly as possible when there is
data corruption, so that there is no way for the user to miss it. After
all, you probably want to know about it if your harddisk is about too
fail or if someone tampers with your data in the cloud (of course, if
you blame S3QL instead of your harddisk, there is nothing I can do ;-).

Changing S3QL to only report an error for the specific data that is
corrupted is pretty easy, and you're right that that would be desirable
to recover anything that's left. However, I don't think it should be the
default behavior. What would you think about a new option aka
--recovery-mode? In that mode S3QL would give just read-only access, and
return an error for corrupted data (instead of unmounting).


Best,
Niko

[Francisco Reyes]

On Mon, Jan 14, 2013 at 1:48 PM, Nikolaus Rath <Niko...@rath.org> wrote:
> Changing S3QL to only report an error for the specific data that is
> corrupted is pretty easy, and you're right that that would be desirable
> to recover anything that's left. However, I don't think it should be the
> default behavior.

Why not?

>What would you think about a new option aka
> --recovery-mode? In that mode S3QL would give just read-only access, and
> return an error for corrupted data (instead of unmounting).

I think skipping bad files is a better default behavior than unmounted.
Perhaps make it a mount option so depending in that option the
filesystem would unmount in case of problems, otherwise would just
report the bad file(s) in the log.

[Nikolaus Rath]

On 01/14/2013 11:18 AM, Francisco Reyes wrote:
> On Mon, Jan 14, 2013 at 1:48 PM, Nikolaus Rath <Niko...@rath.org> wrote:
>> Changing S3QL to only report an error for the specific data that is
>> corrupted is pretty easy, and you're right that that would be desirable
>> to recover anything that's left. However, I don't think it should be the
>> default behavior.
> Why not?

Look in the previous paragraph :-)

The current S3QL idea is to fail as loudly as possible when there is
data corruption, so that there is no way for the user to miss it. After
all, you probably want to know about it if your harddisk is about too

fail or if someone tampers with your data in the cloud.

>> What would you think about a new option aka
>> --recovery-mode? In that mode S3QL would give just read-only access, and
>> return an error for corrupted data (instead of unmounting).
> I think skipping bad files is a better default behavior than unmounted.
> Perhaps make it a mount option so depending in that option the
> filesystem would unmount in case of problems, otherwise would just
> report the bad file(s) in the log.
>

I think there's a good chance of people not checking the log files
regularly. In my opinion, the default should always be the safest
choice, which is to make sure that data corruption does not go unnoticed.


Best,
-Niko

[john]

Hi

sorry it took so long for me to answer. I had a lot of thoughts about this matter and wanted to let them settle down a little bit (besides having the flu for quite some time). Hopefully this helpes and my text is understandable...

On Monday, January 14, 2013 8:55:00 PM UTC+1, Nikolaus Rath wrote:
On 01/14/2013 11:18 AM, Francisco Reyes wrote:
On Mon, Jan 14, 2013 at 1:48 PM, Nikolaus Rath <Niko...@rath.org> wrote:

>>> Changing S3QL to only report an error for the specific data that is corrupted is pretty easy, and you're right that that would be desirable to recover anything that's left. However, I don't think it should be the default behavior.

>> Why not?

> Look in the previous paragraph :-)
>
> The current S3QL idea is to fail as loudly as possible when there is data corruption, so that there is no way for the user to miss it. After all, you probably want to know about it if your harddisk is about too fail or if someone tampers with your data in the cloud.

The user should notice such failures. And unmounting is a good way to do this. The user might work with some GUI that rarely shows status and errors. But if the volume gets unmounted the user sooner or later will notice that, as any operation on the volume will just fail. If the volume would not be unmounted, the user might not notice for a long time that some files are corrupted.

Another very important issues is how to keep damage as low as possible. There might be running fully automatic programs without any user intervention at all. I'm quite sure for any action of s3ql to deal with data corruption I could write a program where that specific kind of action is the worst thing that can happen.

A small example with rsync:
If you use rsync with the --delete and --recursive option it will delete any files and directories in the destination tree that do not exist in the source. If rsync encounters any error it will deactivate the delete functionality. So, if the source of a rsync operation is a s3ql volume that gets unounted, rsync will just do nothing after the point of error. Fine.

Now think of a bad rsync implemention (let's call it rsync_bad), that does not check for errors on the source files. That rsync_bad would complete wipe out the destination tree, only the files that were accessed before the unmount would survive.

rsync_bad would do much less damage, if s3ql would not unmount the filesystem, but skip the corrupted files.

My opinion is, that unmounting the filesystem is the better default, as this prevents any further operation on the corrupted volume. The examples above are only about reading from the s3ql fs. Think about writing to a corrupted volume by fully automatic processes without getting noticed for maybe months and you will easily end in a data recovery nightmare.

The normal behavior from a system administrators point of view will be: As soon as the filesystem encounters data corruption, freeze the filesystem (aka unmount) and enter data analyze and recovery mode. Special use cases might need other behaviours, see rsync_bad, but in most cases freezing a corrupted filesystem is the way to go.

Unmounting is already implemented. Not unmounting, which is needed for data recovery (and rsync_bad) is not yet implemented.

Besides the question between to unmount or not to unmount, something else needs to be looked at: What does s3ql do with the corrupted files themselfes? A process is reading a file until the position of the first data corruption. I think s3ql will then report some kind of read error via the filesystem layer. Is this right?

BTW: If that would be the case, the normal good rsync would even deactivate the delete option, although the s3ql fs is not unmounted. But I'm not sure what it would do with those files in the destination tree, that are affected by data corruption in the s3ql source. Another example that is better to unmount the filesystem, when not doing data recovery.

So, you mounted the s3ql fs with an option not to unmount it in case of data corruption and recovered all needed data (hopefully).

What to do next?

I would like to get the filesystem in a consistent state again. And fsck.s3ql cannot do this.

What I can think of is another mount option, that instructs s3ql to repair any file where it encounters data corruption. Of course repairing cannot recover the original data. But it could put the file into a state where all following accesses would not report an error anymore.

Three variants come into my mind:
Just delete the corrupted file, freeing all blocks in the underlying filesystem layer.
Truncate the corrupted file at the first invalid data block.
Truncate the file and move it into some special directory like lost+found.

Maybe all three options are useful, I think that needs some discussion. But at least one of this options is neccessary to make the once corrupted filesystem work normally again.

With these new features/options a full s3ql filesystem check resulting in a clean state could be done like that:
fsck.s3ql
mount.s3ql with option truncate or delete
tar c <s3ql-mountpoint> >/dev/null

I think it needs no discussion, that a file delete option should not be the default.

In my special case, where the s3ql volume is purely a backup of data that is still completly available on the source, I need no data recovery. I only need to get the s3ql fs into a clean state. So, if that feature would be available I would mount the s3ql with the truncate option (without move) and just "rsync --checksum ..." onto it. In that truncate mode, the s3ql fs should not report any error to the application, just silently truncate.

Would it make sense to have a truncate mode, but returning IO errors on corrupted files?

>>> What would you think about a new option aka --recovery-mode? In that mode S3QL would give just read-only access, and return an error for corrupted data (instead of unmounting).

Such an option seems quite useful to me. One could recover whatever data pieces are left without altering the filesystem. Is it possible that files can be read up to the corruption point, so maybe valuable parts of files can be recovered (aka truncate)?

And as I showed above the option where corrupted data is cleaned without returning an error seems also very neccessary. Otherwise I see no change to get the filesysten into a clean state again. So you would have to throw away the whole filesystem after data recovery and start over again with an empty one. Which is some cases means that you have to copy all recoverable files to another data storage, reinitialize the s3ql fs and then copy all the data back.

Many thanks for your patience... ;-)

cu
John

[Nikolaus Rath]

On 02/10/2013 03:56 PM, john wrote:
> Besides the question between to unmount or not to unmount, something
> else needs to be looked at: What does s3ql do with the corrupted files
> themselfes? A process is reading a file until the position of the first
> data corruption. I think s3ql will then report some kind of read error
> via the filesystem layer. Is this right?

Yes.

> So, you mounted the s3ql fs with an option not to unmount it in case of data corruption and recovered all needed data (hopefully).
>
> What to do next?
>
> I would like to get the filesystem in a consistent state again. And fsck.s3ql cannot do this.

You can just delete every file for which you get a read error (or
truncate at the last readable position). No extra tools or changes in
S3QL are required (once --recover is implemented, that is).



Best,

[john]

Hi Nikolaus

On Monday, February 11, 2013 1:42:40 AM UTC+1, Nikolaus Rath wrote:

You can just delete every file for which you get a read error (or
truncate at the last readable position). No extra tools or changes in
S3QL are required (once --recover is implemented, that is).

Is there an estimate, when this option will be available? Because I'm on hold considering my s3ql backup. I could easily throw away the current s3ql filesystem and initialize freshly.  In that case I could not test the new option, when it is available. But I would like to help the project by testing this. On the other hand I would like to continue working with the s3ql backup. Do you see my dilemma?

cu
John

[Nikolaus Rath]

Sorry, I didn't know you were waiting for this.

There are several other issues I want to work on before getting to
--recover, so it will take at least a couple of weeks.

Would it be possible for you to just create a new file system using a
different prefix? That way you could keep doing backups, and once
--recover is available you can just test it on the old file system.

Let me know if I misunderstood your problem. Thanks for your willingness
to help with this!

Best,
-Nikolaus

[john]

On Thursday, May 2, 2013 11:13:14 PM UTC+2, Nikolaus Rath wrote:

On 05/02/2013 02:52 AM, john wrote:

> Is there an estimate, when this option will be available? Because I'm on
> hold considering my s3ql backup.

 

Sorry, I didn't know you were waiting for this.

Nothing to be sorry about. How should you have know if I wait silently? ;-)
 

There are several other issues I want to work on before getting to
--recover, so it will take at least a couple of weeks.

I am happy that you want to implement this at all.
 

Would it be possible for you to just create a new file system using a
different prefix? That way you could keep doing backups, and once
--recover is available you can just test it on the old file system.

Not really, the filesystem is about 80% full.
 

cu
John

[Nikolaus Rath]

On 05/03/2013 05:19 AM, john wrote:
> Would it be possible for you to just create a new file system using a
> different prefix? That way you could keep doing backups, and once
> --recover is available you can just test it on the old file system.
>
> Not really, the filesystem is about 80% full.

Do you mean that you are using the local backend and the backend file
system is 80% full? Otherwise I don't understand.

Best,
Nikolaus

[Nikolaus Rath]

On 05/02/2013 02:52 AM, john wrote:

> Hi Nikolaus
>
> On Monday, February 11, 2013 1:42:40 AM UTC+1, Nikolaus Rath wrote:
>
>
> You can just delete every file for which you get a read error (or
> truncate at the last readable position). No extra tools or changes in
> S3QL are required (once --recover is implemented, that is).
>
>
> Is there an estimate, when this option will be available? Because I'm on
> hold considering my s3ql backup. I could easily throw away the current
> s3ql filesystem and initialize freshly. In that case I could not test
> the new option, when it is available. But I would like to help the
> project by testing this.

I just uploaded S3QL 1.15 Beta 1 to
http://code.google.com/p/s3ql/downloads/list. It'd be great if you could
give that a try. It does not have a --recover option, but it should
switch to read-only mode if there are any problems with the backend.

[john]

On Friday, May 3, 2013 5:25:41 PM UTC+2, Nikolaus Rath wrote:

On 05/03/2013 05:19 AM, john wrote:
> Not really, the filesystem is about 80% full.

Do you mean that you are using the local backend and the backend file
system is 80% full?

Yes. In that special case this also means the harddisc is 80% full. One partition, only used as s3ql backend.
 

Otherwise I don't understand.

 Sure, otherwise it won't make sense.

 cu
John

[john]

On Sunday, May 5, 2013 12:08:41 AM UTC+2, Nikolaus Rath wrote:

I just uploaded S3QL 1.15 Beta 1 to
http://code.google.com/p/s3ql/downloads/list. It'd be great if you could
give that a try. It does not have a --recover option, but it should
switch to read-only mode if there are any problems with the backend.

That was fast...
I will test as soon as possible, However, this might take same days.

cu
John