read wrong data from large(?) compressed stream #25

hasse69 · 2015-03-13T10:02:31Z

What steps will reproduce the problem?

Compress large data stream that not have good compression ratio.
I used Blu-ray Image.
Mount archive to any path.
Compare files - original one and file in mounted path.
I used diff for perform it.

What is the expected output? What do you see instead?

It must be identical, but sometimes it doesn't.
Difference location is vary - checked via cmp.

What version of the product are you using? On what operating system?

openSUSE 13.1 x86-64. unrar 5.0.14

# ./rar2fs -V
rar2fs v1.19.3-svnr438 (DLL version 6)    Copyright (C) 2009-2013 Hans Beckerus
This program comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it under
certain conditions; see &lt;http://www.gnu.org/licenses/&gt; for details.
FUSE library version: 2.9.3
using FUSE kernel interface version 7.19

Please provide any additional information below.

I think that doesn't occur with archive that created by sotred mode(-m0). Not sure because I perform this test only 2 times with stored data...

Original issue reported on code.google.com by jyhpsycho on 2014-01-30

The text was updated successfully, but these errors were encountered:

hasse69 · 2015-05-23T21:29:45Z

I only tried with a file in the 200-300MB range. I was not able to reproduce it.
Can you please try to mount using '-o direct_io' fuse mount option and see if that
helps? I have been forced to add the use of direct I/O in many of the branches handling
compressed data, but I did not think it was needed also in the general case.

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 09:53:39

hasse69 · 2015-05-23T21:29:50Z

Currently, I'm creating RAR 2.9 format(legacy) archive for test now. I'll report when
test completed using that archive with -o direct_io and without it.

Original issue reported on code.google.com by jyhpsycho on 2014-01-30 09:59:03

hasse69 · 2015-05-23T21:29:54Z

Thanks. Looking forward to the result ;)

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 10:02:53

hasse69 · 2015-05-23T21:29:59Z

It failed both -o direct_io and without it.

I used mount option -o ro,allow_other by default that make sure of prevent any writes
to mounted filesystem and accessible for normal user. Is there any problem with that
options? I think that options doesn't affect decompression process...

cmp says such as:
(HDD path)/BDMV/STREAM/00000.m2ts and (rar2fs mounted path)/BDMV/STREAM/00000.m2ts
differ: byte 28653727745, line 104598404

It occurs at 28G in this case... this location varies when comparing multiple times.

Original issue reported on code.google.com by jyhpsycho on 2014-01-30 10:30:30

hasse69 · 2015-05-23T21:30:04Z

No, -o ro,allow_other has nothing to do with the decompression process. And I do not
have such big files to test on :( Since mounting using '-o ro,allow_other,direct_io'
does not work we can also conclude that the page cache has nothing to do with it since
it is disabled. Is it always at such huge offsets that it fails? Hard to tell where
the fault may be, in rar2fs, libunrar.so, FUSE or even something else? Can you build
rar2fs in debug mode (--enable-debug=1) to see if it spits out something?

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 13:52:24

hasse69 · 2015-05-23T21:30:08Z

(No text was entered with this change)

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 13:54:06

hasse69 · 2015-05-23T21:30:13Z

I will try to reproduce it using a 20GB file, compressed using RAR5.
Is your archive split in volumes or is it a plain archive?
Does it consist of several files or only one?
Something else you can think of that might be of interest when trying to reproduce
this issue?

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 14:00:44

hasse69 · 2015-05-23T21:30:18Z

Reproducing it was not that hard. In fact, it is rather interesting. In all my runs
a "pattern" is repeated and this looks like a off-by-one bug somewhere

  171814914  40  75
  171814915  66  40
  171814916  64  66
  171814917  12  64
  171814918  40  12
  171814922  57  40
  171814923  52  57
  171814925  40  52
  171814926 105  40
  171814927 156 105

As you can see, the data is not that different but due to the 1 byte skew the rest
of the entire file will differ! Finding the root cause of this might take some time
:( It can be anywhere. But I will start with inspecting the I/O buffer handling in
rar2fs to see if I can find something obvious. But it probably is not since the error
seems to show it self first after having processed a lot of data, a lot more than the
 size of the I/O buffer.

Can you verify if this off-by-pattern is also what you see (-l flag to cmp).

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 17:46:04

hasse69 · 2015-05-23T21:30:23Z

*sigh*

The current feedback I can give you is what I have been able to get out so far. Unfortunately
I am still clueless to what is going on :( Not even sure if the error is in rar2fs
or something outside. It looks really, really strange.

This is a log from rar2fs:

seq=333500    history access    offset=1366011903 size=1  op->pos=1366011904  split=0
size=1, chunk=1
seq=333501        next          offset=1366011904 size=4096  op->pos=1366011904

For some reason FUSE seems to call the read function for the same offset twice!?
op->pos point to were we left off in the previous read which means that offset 1366011903
has already been provided once!? Why would cmp try to read data twice?

Looking at the cmp log the off-by-n problem is obvious (note that cmp offsets are starting
at 1). At offset 1366011905 cmp expects 273, but rar2fs delivers 170 which is the value
of offset - 1?? But since cmp did not nag about 1366011904 it means rar2fs delivered
170 twice for two different offsets!!

 1366011905 273 170
 1366011906   0 273
 1366011908 110   0
 1366011909 154 110
 1366011910  72 154
 1366011911 250  72
 1366011912  17 250
 1366011913   1  17
 1366011914 106   1
 1366011915 100 106

And here is the hexdump of the relevant part of the file:

516baffc 374 006 376 170 273 000 000 110 154 072
516bb006

Funny thing is that it seems completely impossible to reproduce the problem using the
same file and version of rar2fs on a 32-bit machine! I can only get this error on my
x86_64 AMD platform :(

Original issue reported on code.google.com by hans.beckerus on 2014-01-30 23:48:34

hasse69 · 2015-05-23T21:30:27Z

The fact that it is not consistent suggests a possible threading issue to me.  What
if you mount it with the single threaded option?

Original issue reported on code.google.com by matthew.beechwoods on 2014-01-31 00:12:25

hasse69 · 2015-05-23T21:30:32Z

rar2fs is single threaded by default, it is internally mounted using -s.

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 00:14:25

hasse69 · 2015-05-23T21:30:37Z

But Matthew, you do have a point. This is not a threading issue, but it definitely has
to do with SMP concurrency! Using the rar2fs specific --no-smp option seems to completely
rectify the problem! The I/O buffer was written to be "lock free" and for SMP systems
there are (due to that reason) some memory barriers inserted in a few places. It might
actually be something in that area! I will try to instrument the I/O buffer and add
a few locks here and there to see if things will behave differently! But at least it
seems we have a viable workaround until I can tell a bit more what is going on.

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 00:35:58

hasse69 · 2015-05-23T21:30:41Z

Nah, seems to have avoided the issue on one machine and with one specific file but I
can still reproduce the error on a different setup :(

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 08:41:48

hasse69 · 2015-05-23T21:30:46Z

The combination of '--no-smp' and '-o direct_io' seems to be the workaround that eliminates
the problem for me. Using these options separately still cause problems. So there seems
to be both a concurrency and a page cache issue involved here :(
Trouble shooting will continue.

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 10:01:44

hasse69 · 2015-05-23T21:30:51Z

After running this through a comparison engine I can definitely see that the contents
of the I/O buffer looks ok, but the buffer returned to FUSE seems to return the wrong
thing (in my case off-by-one) compared to the original file. That could indicate that
this is a simple bug in the read logic, all I need to do is find it.

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 13:04:48

hasse69 · 2015-05-23T21:30:55Z

I'm back! ;-)

In my case, cmp -l doesn't read data...

 2149040129 353   0
 2149040130 241   0
 2149040131 367   0
 2149040132 201   0
 2149040133   7   0
 2149040135 230   0
 2149040136 146   0
 2149040137  75   0
 2149040138 114   0
 2149040139  67   0
 2149040140  53   0
 2149040141  25   0
 2149040142   3   0
 2149040143 212   0
 2149040144  25   0
 2149040145 253   0
 2149040146 233   0
 2149040147  62   0
 2149040148  33   0
 2149040149 166   0
         .
         .
         .

and so on. In this case it occurs ~2G.

Very strange... Test after one day term, diff doesn't report any error many times without
using --no-smp and direct_io option! But, cmp -l reports errors such as above. That
seems very hard to debug...

I tested -o direct_io and --no-smp option. It seems to work in few times of test, but
I doubt that it REALLY works - sometimes says no error, sometimes say differ in other
option set cases.

Original issue reported on code.google.com by jyhpsycho on 2014-01-31 13:48:50

hasse69 · 2015-05-23T21:31:00Z

Diff seems to have another access pattern! I do not know what it does but I do see some
strange offsets in the read callbacks from FUSE. The reason why you get all 0 (I got
it too sometimes) is most likely because cmp is trying to read at a *very* high offset
and that might not always be possible to provide since data might not be available
yet! In this case rar2fs return all 0 and it *will* be a diff. rar2fs tries its best
to wait for data but if the jump is too big it can not blindly skip it since it would
render the complete stream useless. This is the drawback with compressed data compared
to data in store mode. Things might go wrong! That is why I try to tell people compressed
data is delivered by best-effort. But for a simple file compare it should work provided
that the program is "nice" and reads using sequential access patterns. That is probably
what diff is doing and so it has less problems. Also I think that using --no-smp together
with -o direct_io is working. I have not yet seen one single run that fails to the
combination is avoiding some strange access patterns and it avoids old cached data
to be returned which might be corrupt. But there is some bug in the code somewhere
in addition to this. Getting an off-by-one error can not be explained by what I just
told you. Trouble shooting will continue...

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 15:03:10

hasse69 · 2015-05-23T21:31:05Z

Try to replace iobuffer.c with the attached file and recompile. It seems to solve all
my issues at least, without any special flags or mount options to fuse. Make sure you
clear the page cache before testing it since it might already be populated with garbage
from the previous runs. I need to investigate a bit more what is going on but this
should provide good feedback if the solution will work or not.

Original issue reported on code.google.com by hans.beckerus on 2014-01-31 19:24:05

- _Attachment: [iobuffer.c](https://storage.googleapis.com/google-code-attachments/rar2fs/issue-25/comment-18/iobuffer.c)_

hasse69 · 2015-05-23T21:31:10Z

There is now also a new version (r440) added to trunk that decrease the lock contention
from 10% to 5% compared to the attached file. Please, try both (or at least the one
in trunk) and report back here when the result is ready.

Original issue reported on code.google.com by hans.beckerus on 2014-02-01 00:07:04

hasse69 · 2015-05-23T21:31:19Z

I guess r440 seems to be work. I tested with single-volume RARv5 archive (-m5) and multi-volume
RAR legacy archive (-m3). There's no need to test attached version of iobuffer.c...



* Following comment is not directly related to this issue.

I have one question about mounting multi-volume archive. When using 1st volume of archive
set for mount, There's not exist some file that only exists on other volume. the only
way to full access to these files, It must be mounted by directory-based method...
Is that expected behavior?

Original issue reported on code.google.com by jyhpsycho on 2014-02-01 05:10:46

hasse69 · 2015-05-23T21:31:24Z

Thanks for testing. Regarding your last question. No. It is not expected behaviour unless
I completely misunderstood your description of it. Please, file a new issue report.

Case closed.

Original issue reported on code.google.com by hans.beckerus on 2014-02-01 08:37:44

hasse69 · 2015-05-23T21:31:28Z

There seems to be another issue here too. For some reason that I can not recall rar2fs
sets the keep_cache flag to 1 for compressed/encrypted archives. That has the effect
that the kernel cache is not flushed between open() calls. According to the comments
this is done to avoid getting an out-of-sync I/O context. But the drawback is also
that if something forces rar2fs to fake data returned in a read call, also the next
access to the file will return false information! I am starting to wonder if it was
such a bright idea to set keep_cache to 1. I think it should work without it. For raw
access in store mode archives I though see a point in using it to speed up the processing
since it would require less calls to user space. It is also safe to keep the cached
information since the contents may not change between accesses.

Original issue reported on code.google.com by hans.beckerus on 2014-02-03 11:09:12

hasse69 · 2015-05-23T21:31:33Z

I wonder that my experience is related to...

I tried to playback compressed m2ts file in archive. I know that it usually doesn't
work due to lacking full-random access with compressed stream. But, following steps
sometimes doesn't work too that should be work.

1. copy .m2ts file in archive to another path.
2. playback m2ts file in archive.

I used system that have 48GB RAM for test and m2ts file size is around 30GB. It means
all contents of that file exists on page cache and linux should return that data when
accessing file in archive. But, sometimes it sucessfully played with full seek support,
sometimes doesn't playback correctly! I'll investigate that behavior more precisely
when I can get some more time to test...

Original issue reported on code.google.com by jyhpsycho on 2014-02-06 18:09:15

hasse69 · 2015-05-23T21:31:38Z

What is the output from 'free -m' on your system after the copy?
I really doubt that you will fit all 30GB of data in the page cache without something
being flushed.

Original issue reported on code.google.com by hans.beckerus on 2014-02-06 19:14:12

hasse69 · 2015-05-23T21:31:42Z

..and from r445 the keep_cache flag is set to false, so at every open() the cache is
invalidated. Maybe it should be set to true after all? The problem is that I can not
exactly recall why it was set in the first place despite the comment :(

Original issue reported on code.google.com by hans.beckerus on 2014-02-06 19:39:31

hasse69 · 2015-05-23T21:31:47Z

I the logic is slightly wrong as it is right now.
Since this is a r/o file system and data basically can not change rar2fs should aim
at keeping the page cache intact as far as possible for all type of archives. The problem
with compressed archives is the case when it is forced to return bogus data due to
the read being completely off the charts. In this case the cache should be flushed
so that next read will not simply return the same information again without getting
a chance to fix it. But how to flush the page cache? The only way that I know of is
by forcing a flush of the cache at next open(). It is nothing I can do about the process
that actually populated the cache with wrong information which means it most likely
never can repair the damage it already caused and if the same file is opened while
that process still is processing dito then the chance is that it will continue to infect
the cache also for other processes.
The only way to close as many holes as possible is to bypass the cache completely using
direct I/O until the process that started to infect the cache is closing the file.
Then the cache may be enabled again. Another option is to always use direct_io for
compressed archives to avoid the cache issue. But that would also mean that your "workaround"
will never work :(
Speaking of which, that actually gave me an idea. rar2fs could populate the cache for
you. It could do so by processing the entire archive in test mode on-the-fly. It would
be a lot faster than copying to some temporary file system since it is completely performed
in-memory. But for a 30GB file that is still a lot of time having to be spent before
being able to use the file and there is a risk that the process trying to access the
file might time-out and throw an error.

Original issue reported on code.google.com by hans.beckerus on 2014-02-06 20:47:10

hasse69 · 2015-05-23T21:31:52Z

Hmm, why don't I use fsync(2) as soon as I am forced to infect the cache? That would
mean that I need not to worry about sub-sequent reads at all. Either they also require
a new fsync() or correct data will be returned in which cache it is not needed.

Original issue reported on code.google.com by hans.beckerus on 2014-02-06 20:58:53

hasse69 · 2015-05-23T21:31:57Z

That needs some well-designed test to check whether even that is rar2fs' issue or that
is just my mistake. I will test them - on this weekend I guess - and reply.

One thing that I can say this time, There's no need to caching entire file just for
me. I know most users does not need to handle very large stream such as that and does
not have sufficient RAM to cache that. but there's need to consider that once...



Following message is one of my idea.

When I run mplayer with file in mounted rar2fs directly, it seems that rar2fs decompresses
file completely; because rar2fs takes several minutes before mplayer responds(after
it prints "playing" message) and mplayer just throw some error.

Then, I think that it's possible to supports random-access for compressed data when
there's sufficient memory for caching decompressed data I think. That needs some time
to decompress(it's ok to return when it decompresses sufficient amount of data(few
times of requested data by read() call) and decompress remaining data at background),
that should not allocate memory explicitly for caching, and that needs some code which
checks validity of page cache for that file, though.

Original issue reported on code.google.com by jyhpsycho on 2014-02-07 01:17:31

hasse69 · 2015-05-23T21:32:01Z

No, no. rar2fs *never* decompress the whole file before starting playback. But, If mplayer
is performing an early access in a far offset rar2fs tries to figure out if this is
an request for index information or not. If not it will start to extract upto that
point to be able to "catch up" and return valid data. If this is on edge of the algorithm
somewhere it may be that the wrong decision is taken. This is simply the way it is,
it is very difficult to know the intent of the process performing the read. Best effort
is what applies here! It would be very interesting to know at what offset mplayer tries
to access data and and what read request number/sequence.
You will be able to tell if you compile using --enable-debug and start rar2fs in the
foreground.

Regarding the page cache. There is only one safe and deterministic way to handle compressed
archives and that is by flushing the cache at each open(). Having parts of the file
being accessed through the cache might render the entire stream useless.

Original issue reported on code.google.com by hans.beckerus on 2014-02-07 07:02:52

hasse69 · 2015-05-23T21:32:06Z

Also note that both the file in the underlying filesystem (the RAR file) and the actual
file being accessed through FUSE is cached by the kernel! So I really doubt you would
fit that kind of data volumes in the cache without it being at least partly flushed.
I think this is non-deterministic and nothing you can trust behaving the same every
time. Trying to be clever an populate the cache through some logic is also something
that is never going to be 100% accurate. Far from it I would say.

Original issue reported on code.google.com by hans.beckerus on 2014-02-07 07:08:12

hasse69 · 2015-05-23T21:32:11Z

I see. I will use 16GB data for test - sufficient to cache both RAR file and its contents,
remaining ~16GB of memory. and compile rar2fs with --enable-debug option and use that.
Is that right to do? 

I never use index features on rar2fs before because it supports .avi and .mkv file,
not .m2ts(MPEG-2 Transport Stream) file. Currently there's no more can do with that
unless mkr2i implements support for m2ts stream which not widely used normally(It's
widely used for HDTV broadcasting, Optical media such as Blu-ray movies)...

Original issue reported on code.google.com by jyhpsycho on 2014-02-07 08:01:09

hasse69 · 2015-05-23T21:32:15Z

Yes, --enable-debug=3 should be enough.
Also, you could play with the --save-eof flag to rar2fs. Actually, it will do something
similar to what I described below. At open it will read-in the entire file and dump
the last part of it to the local file system as an .r2i file. I have no experience
with m2ts file format, but if all the index stuff is in the end it might work. Try
it out. Note that it will take a while for the file to start playback since the whole
thing needs to be decompressed. But it should be a lot faster than manually copying
it.

Original issue reported on code.google.com by hans.beckerus on 2014-02-07 08:25:24

hasse69 · 2015-05-23T21:32:20Z

I'm sorry for too late; I will test that on this weekend... I'll report that when all
of that tests are completed.

Original issue reported on code.google.com by jyhpsycho on 2014-02-21 12:00:32

hasse69 · 2015-05-23T21:32:25Z

Test completed. I used ~9GiB archive and ~7.5GiB m2ts file in this case.

Before test, I run following commands to make sure any cached data to be invalidated
and frees memory as possible.
# echo 3 > /proc/sys/vm/drop_caches 
# free
             total       used       free     shared    buffers     cached
Mem:      49553488   21093724   28459764    4953488          0    5052700
-/+ buffers/cache:   16041024   33512464
Swap:            0          0          0

1) Mount archive with options : -o ro,allow_other,debug --save-eof
2) run dd to cache movie file data. of=/dev/null.

# free
             total       used       free     shared    buffers     cached
Mem:      49553488   38078784   11474704    4983348          0   22085840
-/+ buffers/cache:   15992944   33560544
Swap:            0          0          0

It seems to be succesfully loaded all data into page cache - decreased ~17GB of free
memory that similar at archive file size + movie file size.

3) play that movie using mplayer.

You're right. mplayer accesses nearly end region of m2ts file when seeking video using
cursor keys. But, It doesn't seems to be used preloaded data using dd before. When
accessing end of file, rar2fs hangs several minutes - It seems retrying to decompress
that data. And it tries to seek backwards sometimes, and finally it terminated with
error.

Full debug messages below : 

getattr /BDMV/STREAM/00000.m2ts
rar2_getattr2()   /BDMV/STREAM/00000.m2ts
   unique: 113, success, outsize: 120
unique: 114, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7740747776 flags: 0x8000
rar2_read()   size=4096, offset=7740747776, fh=140307121319504
PID 26770 calling lread_rar(), seq = 38, size=4096, offset=7740747776/4571136
lread_rar: RETURN 4096
   read[140307121319504] 4096 bytes from 7740747776
   unique: 114, success, outsize: 4112
unique: 115, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 16384 bytes from 7740751872 flags: 0x8000
rar2_read()   size=16384, offset=7740751872, fh=140307121319504
PID 26770 calling lread_rar(), seq = 39, size=16384, offset=7740751872/7740751872
lread_rar: RETURN 16384
   read[140307121319504] 16384 bytes from 7740751872
   unique: 115, success, outsize: 16400
unique: 116, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 32768 bytes from 7740768256 flags: 0x8000
rar2_read()   size=32768, offset=7740768256, fh=140307121319504
PID 26770 calling lread_rar(), seq = 40, size=32768, offset=7740768256/7740768256
lread_rar: RETURN 32768
   read[140307121319504] 32768 bytes from 7740768256
   unique: 116, success, outsize: 32784
unique: 117, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 65536 bytes from 7740801024 flags: 0x8000
rar2_read()   size=65536, offset=7740801024, fh=140307121319504
PID 26770 calling lread_rar(), seq = 41, size=65536, offset=7740801024/7740801024
lread_rar: RETURN 65536
   read[140307121319504] 65536 bytes from 7740801024
   unique: 117, success, outsize: 65552
unique: 118, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 73728 bytes from 7740866560 flags: 0x8000
rar2_read()   size=73728, offset=7740866560, fh=140307121319504
PID 26770 calling lread_rar(), seq = 42, size=73728, offset=7740866560/7740866560
lread_rar: RETURN 73728
   read[140307121319504] 73728 bytes from 7740866560
   unique: 118, success, outsize: 73744
unique: 119, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7736553472 flags: 0x8000
rar2_read()   size=4096, offset=7736553472, fh=140307121319504
PID 26770 calling lread_rar(), seq = 43, size=4096, offset=7736553472/7740940288
seq=43    history access    offset=7736553472 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7736553472  pos=7740940288
lread_rar: RETURN -5
   unique: 119, error: -5 (Input/output error), outsize: 16
unique: 120, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7736553472 flags: 0x8000
rar2_read()   size=4096, offset=7736553472, fh=140307121319504
PID 26770 calling lread_rar(), seq = 44, size=4096, offset=7736553472/7740940288
seq=44    history access    offset=7736553472 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7736553472  pos=7740940288
lread_rar: RETURN -5
   unique: 120, error: -5 (Input/output error), outsize: 16
unique: 121, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7736553472 flags: 0x8000
rar2_read()   size=4096, offset=7736553472, fh=140307121319504
PID 26770 calling lread_rar(), seq = 45, size=4096, offset=7736553472/7740940288
seq=45    history access    offset=7736553472 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7736553472  pos=7740940288
lread_rar: RETURN -5
   unique: 121, error: -5 (Input/output error), outsize: 16
unique: 122, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7728164864 flags: 0x8000
rar2_read()   size=4096, offset=7728164864, fh=140307121319504
PID 26770 calling lread_rar(), seq = 46, size=4096, offset=7728164864/7740940288
seq=46    history access    offset=7728164864 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7728164864  pos=7740940288
lread_rar: RETURN -5
   unique: 122, error: -5 (Input/output error), outsize: 16
unique: 123, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7728164864 flags: 0x8000
rar2_read()   size=4096, offset=7728164864, fh=140307121319504
PID 26770 calling lread_rar(), seq = 47, size=4096, offset=7728164864/7740940288
seq=47    history access    offset=7728164864 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7728164864  pos=7740940288
lread_rar: RETURN -5
   unique: 123, error: -5 (Input/output error), outsize: 16
unique: 124, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7728164864 flags: 0x8000
rar2_read()   size=4096, offset=7728164864, fh=140307121319504
PID 26770 calling lread_rar(), seq = 48, size=4096, offset=7728164864/7740940288
seq=48    history access    offset=7728164864 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7728164864  pos=7740940288
lread_rar: RETURN -5
   unique: 124, error: -5 (Input/output error), outsize: 16
unique: 125, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7711387648 flags: 0x8000
rar2_read()   size=4096, offset=7711387648, fh=140307121319504
PID 26770 calling lread_rar(), seq = 49, size=4096, offset=7711387648/7740940288
seq=49    history access    offset=7711387648 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7711387648  pos=7740940288
lread_rar: RETURN -5
   unique: 125, error: -5 (Input/output error), outsize: 16
unique: 126, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7711387648 flags: 0x8000
rar2_read()   size=4096, offset=7711387648, fh=140307121319504
PID 26770 calling lread_rar(), seq = 50, size=4096, offset=7711387648/7740940288
seq=50    history access    offset=7711387648 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7711387648  pos=7740940288
lread_rar: RETURN -5
   unique: 126, error: -5 (Input/output error), outsize: 16
unique: 127, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7711387648 flags: 0x8000
rar2_read()   size=4096, offset=7711387648, fh=140307121319504
PID 26770 calling lread_rar(), seq = 51, size=4096, offset=7711387648/7740940288
seq=51    history access    offset=7711387648 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7711387648  pos=7740940288
lread_rar: RETURN -5
   unique: 127, error: -5 (Input/output error), outsize: 16
unique: 128, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7677833216 flags: 0x8000
rar2_read()   size=4096, offset=7677833216, fh=140307121319504
PID 26770 calling lread_rar(), seq = 52, size=4096, offset=7677833216/7740940288
seq=52    history access    offset=7677833216 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7677833216  pos=7740940288
lread_rar: RETURN -5
   unique: 128, error: -5 (Input/output error), outsize: 16
unique: 129, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7677833216 flags: 0x8000
rar2_read()   size=4096, offset=7677833216, fh=140307121319504
PID 26770 calling lread_rar(), seq = 53, size=4096, offset=7677833216/7740940288
seq=53    history access    offset=7677833216 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7677833216  pos=7740940288
lread_rar: RETURN -5
   unique: 129, error: -5 (Input/output error), outsize: 16
unique: 130, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7677833216 flags: 0x8000
rar2_read()   size=4096, offset=7677833216, fh=140307121319504
PID 26770 calling lread_rar(), seq = 54, size=4096, offset=7677833216/7740940288
seq=54    history access    offset=7677833216 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7677833216  pos=7740940288
lread_rar: RETURN -5
   unique: 130, error: -5 (Input/output error), outsize: 16
unique: 131, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7610724352 flags: 0x8000
rar2_read()   size=4096, offset=7610724352, fh=140307121319504
PID 26770 calling lread_rar(), seq = 55, size=4096, offset=7610724352/7740940288
seq=55    history access    offset=7610724352 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7610724352  pos=7740940288
lread_rar: RETURN -5
   unique: 131, error: -5 (Input/output error), outsize: 16
unique: 132, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7610724352 flags: 0x8000
rar2_read()   size=4096, offset=7610724352, fh=140307121319504
PID 26770 calling lread_rar(), seq = 56, size=4096, offset=7610724352/7740940288
seq=56    history access    offset=7610724352 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7610724352  pos=7740940288
lread_rar: RETURN -5
   unique: 132, error: -5 (Input/output error), outsize: 16
unique: 133, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7610724352 flags: 0x8000
rar2_read()   size=4096, offset=7610724352, fh=140307121319504
PID 26770 calling lread_rar(), seq = 57, size=4096, offset=7610724352/7740940288
seq=57    history access    offset=7610724352 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7610724352  pos=7740940288
lread_rar: RETURN -5
   unique: 133, error: -5 (Input/output error), outsize: 16
unique: 134, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7476506624 flags: 0x8000
rar2_read()   size=4096, offset=7476506624, fh=140307121319504
PID 26770 calling lread_rar(), seq = 58, size=4096, offset=7476506624/7740940288
seq=58    history access    offset=7476506624 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7476506624  pos=7740940288
lread_rar: RETURN -5
   unique: 134, error: -5 (Input/output error), outsize: 16
unique: 135, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7476506624 flags: 0x8000
rar2_read()   size=4096, offset=7476506624, fh=140307121319504
PID 26770 calling lread_rar(), seq = 59, size=4096, offset=7476506624/7740940288
seq=59    history access    offset=7476506624 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7476506624  pos=7740940288
lread_rar: RETURN -5
   unique: 135, error: -5 (Input/output error), outsize: 16
unique: 136, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7476506624 flags: 0x8000
rar2_read()   size=4096, offset=7476506624, fh=140307121319504
PID 26770 calling lread_rar(), seq = 60, size=4096, offset=7476506624/7740940288
seq=60    history access    offset=7476506624 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7476506624  pos=7740940288
lread_rar: RETURN -5
   unique: 136, error: -5 (Input/output error), outsize: 16
unique: 137, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7208071168 flags: 0x8000
rar2_read()   size=4096, offset=7208071168, fh=140307121319504
PID 26770 calling lread_rar(), seq = 61, size=4096, offset=7208071168/7740940288
seq=61    history access    offset=7208071168 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7208071168  pos=7740940288
lread_rar: RETURN -5
   unique: 137, error: -5 (Input/output error), outsize: 16
unique: 138, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7208071168 flags: 0x8000
rar2_read()   size=4096, offset=7208071168, fh=140307121319504
PID 26770 calling lread_rar(), seq = 62, size=4096, offset=7208071168/7740940288
seq=62    history access    offset=7208071168 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7208071168  pos=7740940288
lread_rar: RETURN -5
   unique: 138, error: -5 (Input/output error), outsize: 16
unique: 139, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 7208071168 flags: 0x8000
rar2_read()   size=4096, offset=7208071168, fh=140307121319504
PID 26770 calling lread_rar(), seq = 63, size=4096, offset=7208071168/7740940288
seq=63    history access    offset=7208071168 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=7208071168  pos=7740940288
lread_rar: RETURN -5
   unique: 139, error: -5 (Input/output error), outsize: 16
unique: 140, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 6671200256 flags: 0x8000
rar2_read()   size=4096, offset=6671200256, fh=140307121319504
PID 26770 calling lread_rar(), seq = 64, size=4096, offset=6671200256/7740940288
seq=64    history access    offset=6671200256 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=6671200256  pos=7740940288
lread_rar: RETURN -5
   unique: 140, error: -5 (Input/output error), outsize: 16
unique: 141, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 6671200256 flags: 0x8000
rar2_read()   size=4096, offset=6671200256, fh=140307121319504
PID 26770 calling lread_rar(), seq = 65, size=4096, offset=6671200256/7740940288
seq=65    history access    offset=6671200256 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=6671200256  pos=7740940288
lread_rar: RETURN -5
   unique: 141, error: -5 (Input/output error), outsize: 16
unique: 142, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 6671200256 flags: 0x8000
rar2_read()   size=4096, offset=6671200256, fh=140307121319504
PID 26770 calling lread_rar(), seq = 66, size=4096, offset=6671200256/7740940288
seq=66    history access    offset=6671200256 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=6671200256  pos=7740940288
lread_rar: RETURN -5
   unique: 142, error: -5 (Input/output error), outsize: 16
unique: 143, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 5597458432 flags: 0x8000
rar2_read()   size=4096, offset=5597458432, fh=140307121319504
PID 26770 calling lread_rar(), seq = 67, size=4096, offset=5597458432/7740940288
seq=67    history access    offset=5597458432 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=5597458432  pos=7740940288
lread_rar: RETURN -5
   unique: 143, error: -5 (Input/output error), outsize: 16
unique: 144, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 5597458432 flags: 0x8000
rar2_read()   size=4096, offset=5597458432, fh=140307121319504
PID 26770 calling lread_rar(), seq = 68, size=4096, offset=5597458432/7740940288
seq=68    history access    offset=5597458432 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=5597458432  pos=7740940288
lread_rar: RETURN -5
   unique: 144, error: -5 (Input/output error), outsize: 16
unique: 145, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 5597458432 flags: 0x8000
rar2_read()   size=4096, offset=5597458432, fh=140307121319504
PID 26770 calling lread_rar(), seq = 69, size=4096, offset=5597458432/7740940288
seq=69    history access    offset=5597458432 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=5597458432  pos=7740940288
lread_rar: RETURN -5
   unique: 145, error: -5 (Input/output error), outsize: 16
unique: 146, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 3449974784 flags: 0x8000
rar2_read()   size=4096, offset=3449974784, fh=140307121319504
PID 26770 calling lread_rar(), seq = 70, size=4096, offset=3449974784/7740940288
seq=70    history access    offset=3449974784 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=3449974784  pos=7740940288
lread_rar: RETURN -5
   unique: 146, error: -5 (Input/output error), outsize: 16
unique: 147, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 3449974784 flags: 0x8000
rar2_read()   size=4096, offset=3449974784, fh=140307121319504
PID 26770 calling lread_rar(), seq = 71, size=4096, offset=3449974784/7740940288
seq=71    history access    offset=3449974784 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=3449974784  pos=7740940288
lread_rar: RETURN -5
   unique: 147, error: -5 (Input/output error), outsize: 16
unique: 148, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 3449974784 flags: 0x8000
rar2_read()   size=4096, offset=3449974784, fh=140307121319504
PID 26770 calling lread_rar(), seq = 72, size=4096, offset=3449974784/7740940288
seq=72    history access    offset=3449974784 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=3449974784  pos=7740940288
lread_rar: RETURN -5
   unique: 148, error: -5 (Input/output error), outsize: 16
unique: 149, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 131072 bytes from 4571136 flags: 0x8000
rar2_read()   size=131072, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 73, size=131072, offset=4571136/7740940288
seq=73    history access    offset=4571136 size=131072  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 149, error: -5 (Input/output error), outsize: 16
unique: 150, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 131072 bytes from 4702208 flags: 0x8000
rar2_read()   size=131072, offset=4702208, fh=140307121319504
PID 26770 calling lread_rar(), seq = 74, size=131072, offset=4702208/7740940288
seq=74    history access    offset=4702208 size=131072  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4702208  pos=7740940288
lread_rar: RETURN -5
   unique: 150, error: -5 (Input/output error), outsize: 16
unique: 151, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 75, size=4096, offset=4571136/7740940288
seq=75    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 151, error: -5 (Input/output error), outsize: 16
unique: 152, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 76, size=4096, offset=4571136/7740940288
seq=76    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 152, error: -5 (Input/output error), outsize: 16
unique: 153, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 77, size=4096, offset=4571136/7740940288
seq=77    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 153, error: -5 (Input/output error), outsize: 16
unique: 154, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 78, size=4096, offset=4571136/7740940288
seq=78    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 154, error: -5 (Input/output error), outsize: 16
unique: 155, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 79, size=4096, offset=4571136/7740940288
seq=79    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 155, error: -5 (Input/output error), outsize: 16
unique: 156, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 80, size=4096, offset=4571136/7740940288
seq=80    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 156, error: -5 (Input/output error), outsize: 16
unique: 157, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 81, size=4096, offset=4571136/7740940288
seq=81    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 157, error: -5 (Input/output error), outsize: 16
unique: 158, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 82, size=4096, offset=4571136/7740940288
seq=82    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 158, error: -5 (Input/output error), outsize: 16
unique: 159, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 83, size=4096, offset=4571136/7740940288
seq=83    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 159, error: -5 (Input/output error), outsize: 16
unique: 160, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 84, size=4096, offset=4571136/7740940288
seq=84    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 160, error: -5 (Input/output error), outsize: 16
unique: 161, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 85, size=4096, offset=4571136/7740940288
seq=85    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 161, error: -5 (Input/output error), outsize: 16
unique: 162, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 86, size=4096, offset=4571136/7740940288
seq=86    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 162, error: -5 (Input/output error), outsize: 16
unique: 163, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 87, size=4096, offset=4571136/7740940288
seq=87    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 163, error: -5 (Input/output error), outsize: 16
unique: 164, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 88, size=4096, offset=4571136/7740940288
seq=88    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 164, error: -5 (Input/output error), outsize: 16
unique: 165, opcode: READ (15), nodeid: 6, insize: 80, pid: 26805
read[140307121319504] 4096 bytes from 4571136 flags: 0x8000
rar2_read()   size=4096, offset=4571136, fh=140307121319504
PID 26770 calling lread_rar(), seq = 89, size=4096, offset=4571136/7740940288
seq=89    history access    offset=4571136 size=4096  op->pos=7740940288  split=0
lread_rar: Input/output error   offset=4571136  pos=7740940288
lread_rar: RETURN -5
   unique: 165, error: -5 (Input/output error), outsize: 16
unique: 166, opcode: FLUSH (25), nodeid: 6, insize: 64, pid: 26805
flush[140307121319504]
rar2_flush()   
(26770) FLUSH [0x7f9bcc08c540  ][called from 26805]
lflush()   
   unique: 166, success, outsize: 16
unique: 167, opcode: RELEASE (18), nodeid: 6, insize: 64, pid: 0
release[140307121319504] flags: 0x8000
rar2_release()   
(26770) RELEASE [0x7f9bcc202e50  ]
(26770) FREE [0x7f9bcc202e50  ]
   unique: 167, success, outsize: 16

Original issue reported on code.google.com by jyhpsycho on 2014-02-21 13:57:41

hasse69 · 2015-05-23T21:32:30Z

With 1.19.8, -o auto_cache option seems to work after readed file completely once. After
then I can seek to random location. But, it failed when playing file doesn't completely
readed before as same as without auto_cache option...

Original issue reported on code.google.com by jyhpsycho on 2014-02-21 14:54:06

hasse69 · 2015-05-23T21:32:35Z

There is not much that can be done here I am afraid. The --save-eof flag could be used
*instead* of 'dd' since it will decompress the entire file and save the last segment
to the file system. It will take a lot of time for a large archive, yes. That was expected.
But it should be faster than doing 'dd'. But, --save-eof is not an option in this case
since you need to populate the page cache every time rar2fs is restarted and --save-eof
will only do it once until a .r2i file is created.
Also, the page cache is not a deterministic animal. Things might be in there, things
might not and what and when data is added/flushed is not something a user can safely
rely on. It is simply a fact that compressed archives accessed through utilities that
perform random access (especially close to the end of file) can never be made to work
reliable.

Original issue reported on code.google.com by hans.beckerus on 2014-02-21 15:06:36

hasse69 · 2015-05-23T21:32:39Z

I see. page cache isn't reliable especially low memory environment.

But, why --save-eof doesn't change any behavior of that? I can't see any decompression
operation when using that option. I can't see any .r2i file, too. Am I missing something?

Original issue reported on code.google.com by jyhpsycho on 2014-02-21 15:38:05

hasse69 · 2015-05-23T21:32:44Z

It is not reliable in this context. Period. Even in high-end memory configurations you
can not always guarantee how it is utilized. The fuse mount option -o auto_cache is
probably your best bet here. Especially since rar2fs from latest release never enforces
keeping the cache at each open. The user can instead control this from the auto_cache
option instead.

The --save-eof is a simply a feature than at first open will decompress the entire
file and dump the few last percent of the file to an .r2i file which can later be used
if some utility tries to access far beyond current stream offset. Hard to say why you
do not get an .r2i file? But since you said it took several minutes for the playback
to start I would guess it did decompress it. Is you file system writable?
What does the debug output tell you? It should say something when the .r2i file is
being created.

Original issue reported on code.google.com by hans.beckerus on 2014-02-21 15:51:00

hasse69 · 2015-05-23T21:32:49Z

Also worth mentioning is that --save-eof can not be used as a replacement for 'dd'!
I just realized that there are two files being cached here, the actual archive and
the fake file presented by rar2fs. --save-eof will never cache information for the
fake inode, it will cache data for the real file. What you need here is populating
of the cache for the fake inode, something a tool outside of the file system (such
as dd) can assist you with.

Original issue reported on code.google.com by hans.beckerus on 2014-02-21 16:01:25

hasse69 · 2015-05-23T21:32:53Z

Hmm... Now I say what I understands;

--save-eof option does access "end block of file" when first access to file. For that,
compressed stream must be decompressed from start of that file. That behavior caches
"real data" of that file only, and last block saved to some cache file as ".r2i" file.
right?

If my understand is all right, following steps should be work with sufficient memory
condition.

1) Mount rar file with --save-eof option.
2) play some file.

Then, mplayer tries to read media file, then rar2fs reads all data of that file, and
creates .r2i file contains last block of file. But, I can't see any message such as
"r2i file created" in debug messages...

And, if mplayer requests block before current for seek operation and there's no memory
that keep all contents of that file - it means requested block doesn't exist in page
cache -, rar2fs should decompress from start and should returns correct data.
But, there's error -5 instead of that.

Original issue reported on code.google.com by jyhpsycho on 2014-02-21 16:45:11

hasse69 · 2015-05-23T21:32:58Z

--save-eof *does* access "end block of file" by extracting the contents in an archive,
yes. But, the archive it extracts from is located on your *real* file system and has
an inode that is cached on its own. It is that cache entry that --save-eof will populate!
But, in your case it is actually the inode (created by fuse) for the fake file you
wish to populate the cache for, not the one on your back-end fs. That is why 'dd' works
since it operates on the fuse provided inode *and* the archive itself. So, in the case
of --save-eof only the latter is updated.
So the answer is no, your steps as listed will not help in this case.

Why there is no .r2i file created I do not know. It could be because your file system
is write only or because the access pattern is not actually reading from the last 5%
of the file (this is the trigger for creating the .r2i). A --enable-debug=3 should
tell since it clearly dumps if there is an exceptional read-ahead detected.

Original issue reported on code.google.com by hans.beckerus on 2014-02-21 18:53:16

hasse69 · 2015-05-23T21:33:03Z

Hmm... It seems I misundestand something... Can you suggest some instructions what should
I do?

Original issue reported on code.google.com by jyhpsycho on 2014-02-22 07:35:01

hasse69 · 2015-05-23T21:33:07Z

Look at it this way. There are two (2) inodes in play here! One is the archive itself
and the other (virtual) one is the file as exposed by rarf2s. Both are cached! When
you access the file as exposed by rar2fs, it is the second one that is in effect. rar2fs
can not internally touch the latter. By using the --save-eof flag only the cache entry/inode
addressed by the archive itself is affected. Not the virtual inode!

There is no water proof solution to what you are trying to accomplish! The current
approach, that is using 'dd' in combination with "auto_cache", to populate the cache
before accessing it through eg. mplayer is most likely your best shot!

There is a theoretical possibility to support random access in a compressed RAR stream
by adding sync points and then save the current decompression state in between them.
But according to Eugene at RAR labs that is going to result in a RAM overhead that
is most likely not acceptable. It would also require post-processing of every archive
since the state at each sync point need to be determined and cached.

Original issue reported on code.google.com by hans.beckerus on 2014-02-22 23:28:34

hasse69 · 2015-05-23T21:33:12Z

You means --save-eof option can't handle virtually exposed file when decompression process
for accessing that terminated? I can understand all current behavior of rar2fs if that's
correct.

Hmm... what I want to is maximize page cache utilization, not fully random access for
compressed stream - That's impossible under insufficient memory environment - and fix
issue that is occured when performs random access.
Currently, rar2fs just fails when perform random access that "whole file contents"
not on page cache managed by kernel. I think that if there's some needs to read some
data not on page cache, rar2fs should redo decompress process for that file and returns
correct data. I know that's slow because that must be sequentially decompressed from
first and it may occur several times with very low free memory space, but that's better
than returns just read error currently.

Original issue reported on code.google.com by jyhpsycho on 2014-02-23 02:35:04

hasse69 · 2015-05-23T21:33:17Z

Correct. Internally rar2fs does not see the virtual inode.

It is not feasible that rar2fs should decompress/read-ahead the entire stream before
returning some data. That will most likely render a time-out by the client. For compressed
archives rar2fs provides data as "best-effort"! If a read is far outside the current
stream position the read buffer is filled with 0 unless there is an .r2i file that
covers the offset range.

Original issue reported on code.google.com by hans.beckerus on 2014-02-23 02:46:57

hasse69 · 2015-05-23T21:33:22Z

Difference still occurs with RARv5 multi-volume archive. It needs more fix...

Original issue reported on code.google.com by jyhpsycho on 2014-07-13 05:23:48

hasse69 · 2015-05-23T21:33:26Z

Please elaborate some more. Is this the off-by-one bug or a page-cache issue as discussed
previously?

Original issue reported on code.google.com by hans.beckerus on 2014-07-15 19:22:39

hasse69 · 2015-05-23T21:33:31Z

Tried to reproduce the issue using both 'cmp' and 'diff' for a compressed (best) RAR5
multi-part volume but did not encounter any problems.

Original issue reported on code.google.com by hans.beckerus on 2014-07-17 19:40:36

hasse69 · 2015-05-23T21:33:36Z

What I seen is off-by-one. I recently deleted archive set what that problem occurs,
thus I'll try reproduce it as soon as possible...

Original issue reported on code.google.com by jyhpsycho on 2014-07-21 12:13:18

hasse69 self-assigned this Mar 13, 2015

hasse69 added Defect Priority-Medium labels Mar 13, 2015

hasse69 closed this as completed Mar 13, 2015

hasse69 removed their assignment Mar 13, 2015

Nischi85 mentioned this issue Oct 9, 2022

stacked file system gets unmounted #177

Closed

read wrong data from large(?) compressed stream #25

read wrong data from large(?) compressed stream #25

Comments

hasse69 commented Mar 13, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015

hasse69 commented May 23, 2015