Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

File hash value changes, but hexdump seems unchange. #147

Closed
galaxy001 opened this issue Oct 18, 2017 · 16 comments
Closed

File hash value changes, but hexdump seems unchange. #147

galaxy001 opened this issue Oct 18, 2017 · 16 comments

Comments

@galaxy001
Copy link

galaxy001 commented Oct 18, 2017 •
edited
Loading 

gocryptfs -reverse /volume1/dsG /tmp/dsg
gocryptfs -ro /tmp/dsg /tmp/t
dd if=/dev/urandom of=/volume1/dsG/t.bin bs=1024 count=1024
cd /tmp/
shasum /volume1/dsG/t.bin /tmp/t/t.bin
hexdump -C /volume1/dsG/t.bin > 0.txt
hexdump -C /tmp/t/t.bin > 1.txt
diff 0.txt 1.txt && echo $?
diff -b /volume1/dsG/t.bin /tmp/t/t.bin

The SHA1 hash is different. diff says the two text files are the same, while saying the original binary files differ.

The bug will not appear on 00h filled files.

Both the Perl script shasum 5.88 and md5sum (GNU coreutils) 8.24 reveals different hash values as above. And diff (GNU diffutils) 3.3 also says Binary files /volume1/dsG/t.bin and /tmp/t/t.bin differ.

# ll -i /volume1/dsG/t.bin /tmp/t/t.bin
106070055 -rw-r--r-- 1 root root 1048576 Oct 18 18:35 /tmp/t/t.bin
106070055 -rw-r--r-- 1 root root 1048576 Oct 18 18:35 /volume1/dsG/t.bin

The minimal file with this bug FOR md5sum is 327681 bytes, 327680 bytes will be OK.
dd if=/dev/urandom of=/volume1/dsG/t.bin bs=1 count=327681

And 368k is OK for shasum while 369k leads to this bug.
@galaxy001
Copy link
Author

galaxy001 commented Oct 18, 2017 •
edited
Loading

I cannot repeat it on another Linux Server.
So, I provide logs.

# ll -i t/t.bin
106070055 -rw-r--r-- 1 root root 327681 Oct 18 19:29 t/t.bin

md5sum readling log (the error one):

2017/10/18 19:30:34 Dispatch 14: LOOKUP, NodeId: 1. names: [t.bin] 6 bytes
2017/10/18 19:30:34 Serialize 14: LOOKUP code: OK value: {NodeId: 3 Generation=0 EntryValid=1.000 AttrValid=1.000 Attr={M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:30:34 Dispatch 15: OPEN, NodeId: 3. data: {O_RDONLY,0x8000}
2017/10/18 19:30:34 Serialize 15: OPEN code: OK value: {Fh 2 }
2017/10/18 19:30:34 Dispatch 16: READ, NodeId: 3. data: {Fh 2 off 0 sz 65536  L 0 RDONLY,0x8000}
2017/10/18 19:30:34 Serialize 16: READ code: OK value:  65536 bytes data

2017/10/18 19:30:34 Dispatch 17: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:30:34 Serialize 17: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:30:34 Dispatch 18: READ, NodeId: 3. data: {Fh 2 off 65536 sz 131072  L 0 RDONLY,0x8000}
2017/10/18 19:30:34 Dispatch 19: READ, NodeId: 3. data: {Fh 2 off 196608 sz 135168  L 0 RDONLY,0x8000}
2017/10/18 19:30:34 Serialize 18: READ code: OK value:  131072 bytes data

2017/10/18 19:30:34 Dispatch 20: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:30:34 Serialize 20: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:30:34 Serialize 19: READ code: OK value:  131072 bytes data

2017/10/18 19:30:34 Dispatch 21: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:30:34 Serialize 21: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:30:34 Dispatch 22: FLUSH, NodeId: 3. data: {Fh 2}
2017/10/18 19:30:34 Serialize 22: FLUSH code: OK value:
2017/10/18 19:30:34 Dispatch 23: RELEASE, NodeId: 3. data: {Fh 2 0x8000  L0}
2017/10/18 19:30:34 Serialize 23: RELEASE code: OK value:

hexdump reading log (the correct one):

2017/10/18 19:31:12 Dispatch 24: LOOKUP, NodeId: 1. names: [t.bin] 6 bytes
2017/10/18 19:31:12 Serialize 24: LOOKUP code: OK value: {NodeId: 3 Generation=0 EntryValid=1.000 AttrValid=1.000 Attr={M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 25: OPEN, NodeId: 3. data: {O_RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 25: OPEN code: OK value: {Fh 2 }
2017/10/18 19:31:12 Dispatch 26: FLUSH, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 26: FLUSH code: OK value:
2017/10/18 19:31:12 Dispatch 27: READ, NodeId: 3. data: {Fh 2 off 0 sz 16384  L 0 RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 27: READ code: OK value:  16384 bytes data

2017/10/18 19:31:12 Dispatch 28: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 28: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 29: READ, NodeId: 3. data: {Fh 2 off 16384 sz 32768  L 0 RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 29: READ code: OK value:  32768 bytes data

2017/10/18 19:31:12 Dispatch 30: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 30: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 31: READ, NodeId: 3. data: {Fh 2 off 49152 sz 65536  L 0 RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 31: READ code: OK value:  65536 bytes data

2017/10/18 19:31:12 Dispatch 32: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 32: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 33: READ, NodeId: 3. data: {Fh 2 off 114688 sz 131072  L 0 RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 33: READ code: OK value:  131072 bytes data

2017/10/18 19:31:12 Dispatch 34: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 34: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 35: READ, NodeId: 3. data: {Fh 2 off 245760 sz 86016  L 0 RDONLY,0x8000}
2017/10/18 19:31:12 Serialize 35: READ code: OK value:  81921 bytes data

2017/10/18 19:31:12 Dispatch 36: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 36: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 0:0 B648*4096 i0:106070055 A 1508326224.968562473 M 1508326192.263672330 C 1508326192.263672330}}
2017/10/18 19:31:12 Dispatch 37: FLUSH, NodeId: 3. data: {Fh 2}
2017/10/18 19:31:12 Serialize 37: FLUSH code: OK value:
2017/10/18 19:31:12 Dispatch 38: RELEASE, NodeId: 3. data: {Fh 2 0x8000  L0}
2017/10/18 19:31:12 Serialize 38: RELEASE code: OK value:

@galaxy001
Copy link
Author

Log of md5sum readling on a 327680 byte file.

2017/10/18 19:38:31 Dispatch 88: LOOKUP, NodeId: 1. names: [t0.bin] 7 bytes
2017/10/18 19:38:31 Serialize 88: LOOKUP code: OK value: {NodeId: 4 Generation=0 EntryValid=1.000 AttrValid=1.000 Attr={M0100644 SZ=327680 L=1 0:0 B640*4096 i0:106070058 A 1508326542.641696646 M 1508326532.489046043 C 1508326532.489046043}}
2017/10/18 19:38:31 Dispatch 89: OPEN, NodeId: 4. data: {O_RDONLY,0x8000}
2017/10/18 19:38:31 Serialize 89: OPEN code: OK value: {Fh 2 }
2017/10/18 19:38:31 Dispatch 90: READ, NodeId: 4. data: {Fh 2 off 0 sz 65536  L 0 RDONLY,0x8000}
2017/10/18 19:38:31 Serialize 90: READ code: OK value:  65536 bytes data

2017/10/18 19:38:31 Dispatch 91: GETATTR, NodeId: 4. data: {Fh 2}
2017/10/18 19:38:31 Serialize 91: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327680 L=1 0:0 B640*4096 i0:106070058 A 1508326542.641696646 M 1508326532.489046043 C 1508326532.489046043}}
2017/10/18 19:38:31 Dispatch 92: READ, NodeId: 4. data: {Fh 2 off 65536 sz 131072  L 0 RDONLY,0x8000}
2017/10/18 19:38:31 Dispatch 93: READ, NodeId: 4. data: {Fh 2 off 196608 sz 131072  L 0 RDONLY,0x8000}
2017/10/18 19:38:31 Serialize 92: READ code: OK value:  131072 bytes data

2017/10/18 19:38:31 Dispatch 94: GETATTR, NodeId: 4. data: {Fh 2}
2017/10/18 19:38:31 Serialize 94: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327680 L=1 0:0 B640*4096 i0:106070058 A 1508326542.641696646 M 1508326532.489046043 C 1508326532.489046043}}
2017/10/18 19:38:31 Serialize 93: READ code: OK value:  131072 bytes data

2017/10/18 19:38:31 Dispatch 95: GETATTR, NodeId: 4. data: {Fh 2}
2017/10/18 19:38:31 Serialize 95: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327680 L=1 0:0 B640*4096 i0:106070058 A 1508326542.641696646 M 1508326532.489046043 C 1508326532.489046043}}
2017/10/18 19:38:31 Dispatch 96: READ, NodeId: 4. data: {Fh 2 off 327680 sz 4096  L 0 RDONLY,0x8000}
2017/10/18 19:38:31 Serialize 96: READ code: OK value:
2017/10/18 19:38:31 Dispatch 97: FLUSH, NodeId: 4. data: {Fh 2}
2017/10/18 19:38:31 Serialize 97: FLUSH code: OK value:
2017/10/18 19:38:31 Dispatch 98: RELEASE, NodeId: 4. data: {Fh 2 0x8000  L0}
2017/10/18 19:38:31 Serialize 98: RELEASE code: OK value:

The reading is correct.

@galaxy001
Copy link
Author

Seems like a bug brings by 3009ec9 .

I got the panic as on #145 with v1.4.1-19-g64e5906.

@rfjakob
Copy link
Owner

rfjakob commented Oct 18, 2017 •
edited
Loading

You see this issue on the NAS?

@rfjakob
Copy link
Owner

rfjakob commented Oct 18, 2017

Interesting: Summing up the READs for "md5sum readling log (the error one)" shows that 1 byte is missing:

octave:1> 65536+131072+131072
ans =  327680

@rfjakob
Copy link
Owner

rfjakob commented Oct 18, 2017

I tried this here but I cannot reproduce the problem. Can you post

$ cat /proc/version

from the machine you see this problem?

@galaxy001
Copy link
Author 

# cat /proc/version
Linux version 3.10.102 (root@build2) (gcc version 4.9.3 20150311 (prerelease) (crosstool-NG 1.20.0) ) #15152 SMP Fri Oct 6 18:13:48 CST 2017

I think you can set fuse.MAX_KERNEL_WRITE to 131072 to reproduce the problem.

@rfjakob
Copy link
Owner

rfjakob commented Oct 19, 2017

You mean something smaller? 131072 is the default [1].

[1] https://github.com/hanwen/go-fuse/blob/cfefa3d51b1a50eb7832e452164c175e5c16f35f/fuse/server.go#L22

@galaxy001
Copy link
Author

galaxy001 commented Oct 19, 2017 •
edited
Loading

I got the message of gocryptfs[10241]: doRead: truncating oversized read: 196608 to 131072 bytes, and it is from L150. Thus I am thinking about this.

Now, I tried a 327681 byte file on a CentOS7 server and find the log:

2017/10/19 15:33:32 Dispatch 49: LOOKUP, NodeId: 1. names: [t.bin] 6 bytes
2017/10/19 15:33:32 Serialize 49: LOOKUP code: OK value: {NodeId: 3 Generation=0 EntryValid=1.000 AttrValid=1.000 Attr={M0100644 SZ=327681 L=1 28983:894 B648*4096 i0:107375270425 A 1508398407.689265400 M 1508398401.005265285 C 1508398401.005265285}}
2017/10/19 15:33:32 Dispatch 50: OPEN, NodeId: 3. data: {O_RDONLY,0x8000}
2017/10/19 15:33:32 Serialize 50: OPEN code: OK value: {Fh 2 }
2017/10/19 15:33:32 Dispatch 51: READ, NodeId: 3. data: {Fh 2 off 0 sz 65536  L 0 RDONLY,0x8000}
2017/10/19 15:33:32 Serialize 51: READ code: OK value:  65536 bytes data

2017/10/19 15:33:32 Dispatch 52: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/19 15:33:32 Serialize 52: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 28983:894 B648*4096 i0:107375270425 A 1508398407.689265400 M 1508398401.005265285 C 1508398401.005265285}}
2017/10/19 15:33:32 Dispatch 53: READ, NodeId: 3. data: {Fh 2 off 65536 sz 131072  L 0 RDONLY,0x8000}
2017/10/19 15:33:32 Dispatch 54: READ, NodeId: 3. data: {Fh 2 off 196608 sz 131072  L 0 RDONLY,0x8000}
2017/10/19 15:33:32 Dispatch 55: READ, NodeId: 3. data: {Fh 2 off 327680 sz 4096  L 0 RDONLY,0x8000}
2017/10/19 15:33:32 Serialize 55: READ code: OK value:  1 bytes data

2017/10/19 15:33:32 Serialize 53: READ code: OK value:  131072 bytes data

2017/10/19 15:33:32 Serialize 54: READ code: OK value:  131072 bytes data

2017/10/19 15:33:32 Dispatch 56: GETATTR, NodeId: 3. data: {Fh 2}
2017/10/19 15:33:32 Serialize 56: GETATTR code: OK value: {A1.000000000 {M0100644 SZ=327681 L=1 28983:894 B648*4096 i0:107375270425 A 1508398407.689265400 M 1508398401.005265285 C 1508398401.005265285}}
2017/10/19 15:33:32 Dispatch 57: FLUSH, NodeId: 3. data: {Fh 2}
2017/10/19 15:33:32 Serialize 57: FLUSH code: OK value:
2017/10/19 15:33:32 Dispatch 58: RELEASE, NodeId: 3. data: {Fh 2 0x8000  L0}
2017/10/19 15:33:32 Serialize 58: RELEASE code: OK value:

It seems the Serialize 55: READ code: OK value: 1 bytes data is missing on my NAS.

And truncating oversized read is NOT happened on the CentOS7 Server.

Might be sth. wrong with multithreaded reading ? Which should happen when truncating oversized read.

@rfjakob
Copy link
Owner

rfjakob commented Oct 19, 2017

What is also missing on the NAS is this: The request from the kernel to read data after offset 327680:

Dispatch 55: READ, NodeId: 3. data: {Fh 2 off 327680 sz 4096  L 0 RDONLY,0x8000}

The truncating oversized read means we are returning less data than requested to the kernel. The kernel should continue reading.

I'll see if I can get a Linux 3.10 kernel to boot. Looks like it's still supported on https://www.kernel.org/ .

@rfjakob
Copy link
Owner

rfjakob commented Oct 19, 2017

I have tested this in a CentOS 7 VM that has kernel version 3.10.0-514.26.2.el7.x86_64, but could not reproduce this.

@rfjakob
Copy link
Owner

rfjakob commented Oct 19, 2017

Wow!

jakob@d8min:/tmp$ md5sum */t.bin
a9428e96449ecb2ff29a1eacc4d89c25  a/t.bin
a9428e96449ecb2ff29a1eacc4d89c25  c/t.bin
jakob@d8min:/tmp$ sha256sum */t.bin
d0482c45b8bba982c3ec6afa96ac9b931330565f91d1e9c9da30bf7e99f63355  a/t.bin
a53170dca91732bf490d9b5587dc49265eb2928148b5f793ab8cc116b659da5b  c/t.bin

$ uname -a
Linux d8min 3.10.107 #4 SMP Thu Oct 19 23:13:25 CEST 2017 x86_64 GNU/Linux

@rfjakob
Copy link
Owner

rfjakob commented Oct 19, 2017 •
edited
Loading

Problem seems to be in forward mode. I can copy the "-reverse" folder so it becomes a normal directory, mount it, and get the same effect.

@rfjakob
Copy link
Owner

rfjakob commented Oct 21, 2017

Also reproduced on Linux 4.13.8 with

#define FUSE_MAX_PAGES_PER_REQ 64

(default is 32 (ref))

/tmp/b$ sha256sum t.bin t.bin t.bin t.bin 
dc7cc048b588171aadb217873c673b18620dee284eef88a2cf655124bd3a8ec8  t.bin
2d6c7bbe95772ca8f5f4528d0db0d255a90fb8475cb7d49dbc460636e525940f  t.bin
2d6c7bbe95772ca8f5f4528d0db0d255a90fb8475cb7d49dbc460636e525940f  t.bin
dc7cc048b588171aadb217873c673b18620dee284eef88a2cf655124bd3a8ec8  t.bin

@rfjakob
Copy link
Owner

rfjakob commented Oct 21, 2017

Both the panic and the data corruption should be fixed now. Can you confirm?

The patch 3009ec9 was indeed wrong.

@galaxy001
Copy link
Author

The bug has been fixed on v1.4.1-29-g34547a6 .

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rfjakob @galaxy001