read wrong data from large(?) compressed stream

[GoogleCodeExporter]

What steps will reproduce the problem?

1. Compress large data stream that not have good compression ratio.
   I used Blu-ray Image.
2. Mount archive to any path.
3. 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 <http://www.gnu.org/licenses/> 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 jyhpsy...@gmail.com on 30 Jan 2014 at 9:45

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 30 Jan 2014 at 9:53

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 30 Jan 2014 at 9:59

[GoogleCodeExporter]

Thanks. Looking forward to the result ;)

Original comment by hans.bec...@gmail.com on 30 Jan 2014 at 10:02

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 30 Jan 2014 at 10:30

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 30 Jan 2014 at 1:52

[GoogleCodeExporter]

Original comment by hans.bec...@gmail.com on 30 Jan 2014 at 1:54

• Changed state: Started

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 30 Jan 2014 at 2:00

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 30 Jan 2014 at 5:46

[GoogleCodeExporter]

*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 comment by hans.bec...@gmail.com on 30 Jan 2014 at 11:48

[GoogleCodeExporter]

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 comment by matthew....@gmail.com on 31 Jan 2014 at 12:12

[GoogleCodeExporter]

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

Original comment by hans.bec...@gmail.com on 31 Jan 2014 at 12:14

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 12:35

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 8:41

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 10:01

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 1:04

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 31 Jan 2014 at 1:48

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 3:03

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 31 Jan 2014 at 7:24

Attachments:

• iobuffer.c

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 1 Feb 2014 at 12:07

[GoogleCodeExporter]

Original comment by hans.bec...@gmail.com on 1 Feb 2014 at 12:43

• Changed state: Fixed

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 1 Feb 2014 at 5:10

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 1 Feb 2014 at 8:37

• Changed state: Verified

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 3 Feb 2014 at 11:09

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 6 Feb 2014 at 6:09

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 6 Feb 2014 at 7:14

[GoogleCodeExporter]

..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 comment by hans.bec...@gmail.com on 6 Feb 2014 at 7:39

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 6 Feb 2014 at 8:47

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 6 Feb 2014 at 8:58

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 7 Feb 2014 at 1:17

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 7 Feb 2014 at 7:02

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 7 Feb 2014 at 7:08

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 7 Feb 2014 at 8:01

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 7 Feb 2014 at 8:25

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Feb 2014 at 12:00

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Feb 2014 at 1:57

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Feb 2014 at 2:54

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 21 Feb 2014 at 3:06

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Feb 2014 at 3:38

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 21 Feb 2014 at 3:51

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 21 Feb 2014 at 4:01

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Feb 2014 at 4:45

[GoogleCodeExporter]

--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 comment by hans.bec...@gmail.com on 21 Feb 2014 at 6:53

[GoogleCodeExporter]

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

Original comment by jyhpsy...@gmail.com on 22 Feb 2014 at 7:35

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 22 Feb 2014 at 11:28

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 23 Feb 2014 at 2:35

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 23 Feb 2014 at 2:46

[GoogleCodeExporter]

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

Original comment by jyhpsy...@gmail.com on 13 Jul 2014 at 5:23

[GoogleCodeExporter]

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

Original comment by hans.bec...@gmail.com on 15 Jul 2014 at 7:22

[GoogleCodeExporter]

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 comment by hans.bec...@gmail.com on 17 Jul 2014 at 7:40

[GoogleCodeExporter]

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 comment by jyhpsy...@gmail.com on 21 Jul 2014 at 12:13