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.

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

after rsync'in some files on target host inaccessible at any way with xattr=sa (0.6.2 - 0.6.3 - current git) #2717

Closed
TioNisla opened this issue Sep 18, 2014 · 19 comments
Milestone

Comments

@TioNisla
Copy link

Short description: after "rsync -PSAXrltgoD" from remote host some files on target inaccessible at any way. Same host/pool as https://gist.github.com/anonymous/39e252399acb6912a16e

root@samba:~# getfacl test.file 
getfacl: test.file: Input/output error

root@samba:~# strace getfacl test.file
---8<---
lstat("test.file", {st_mode=S_IFREG|0775, st_size=462524, ...}) = 0
getxattr("test.file", "system.posix_acl_access", 0x7fff8e677fb0, 132) = -1 EIO (Input/output error)
---8<---

root@samba:~# ls -l test.file
ls: test.file: Input/output error
-rwxrwxr-x 1 samba samba 462524 авг 18  2011 test.file

root@samba:~# cat test.file > /dev/null
cat: test.file: Input/output error

root@samba:~# zfs get acltype,aclinherit,xattr storage/samba
NAME           PROPERTY    VALUE          SOURCE
storage/samba  acltype     posixacl       local
storage/samba  aclinherit  passthrough    local
storage/samba  xattr       sa             local

@dweeezil
Copy link
Contributor

See #2663, #2700 and one other that escapes my mind.

I've been trying to get information regarding those and, so far, haven't found a "smoking gun" but it's clear there's a problem caused by mixing posix ACLs and xattr=sa.

Could you please find the inode number of "test.file" (ls -di file) and then run zdb -dddddd <pool>/<fs> <inode_number> and post the output. Actually, I'm only interested in two things: First, does the "dnode flags" line show "SPILL_BLKPTR" and second, does it print out a "SA xattrs" section. My guess is yes to the first part and no to the second.

Also, what's the ashift of each top-level vdev in this pool? Are they all ashift=9 or ashift=12 or are their a mix of the 2?

@TioNisla
Copy link
Author

another host/pool, and a similar situation:

zfs - 52dd454

# zpool get ashift storage
NAME     PROPERTY  VALUE   SOURCE
storage  ashift    12      local

# zpool status storage
  pool: storage
 state: ONLINE
  scan: resilvered 144K in 0h0m with 0 errors on Mon Sep 15 10:28:57 2014
config:

    NAME                                        STATE     READ WRITE CKSUM
    storage                                     ONLINE       0     0     0
      mirror-0                                  ONLINE       0     0     0
        wwn-0x60060e80102d34f00511c6d700000018  ONLINE       0     0     0
        wwn-0x60060e80102d37f00511c70700000018  ONLINE       0     0     0

errors: No known data errors

# strace cat a.test.file > /dev/null
...
open("a.test.file", O_RDONLY)     = -1 EIO (Input/output error)
...

# ls -di a.test.file 
13852 a.test.file

# zdb -dddddd storage/home 13852
Dataset storage/home [ZPL], ID 141, cr_txg 94790, 1.23T, 1096897 objects, rootbp DVA[0]=<0:1467ad61000:1000> DVA[1]=<0:2105a0cf000:1000> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=149467L/149467P fill=1096897 cksum=164a835cbb:7532af31533:14b4af0de33bd:29862d5d92afe7

    Object  lvl   iblk   dblk  dsize  lsize   %full  type
     13852    2    16K   128K  9.20M  9.25M  100.00  ZFS plain file (K=inherit) (Z=inherit)
                                        196   bonus  System attributes
    dnode flags: USED_BYTES USERUSED_ACCOUNTED SPILL_BLKPTR
    dnode maxblkid: 73
    path    /<censored>/a.test.file
    uid     14
    gid     11
    atime   Tue Sep 16 15:58:43 2014
    mtime   Tue Sep 24 11:58:12 2013
    ctime   Fri Sep 19 08:56:31 2014
    crtime  Tue Sep 16 15:58:41 2014
    gen 95516
    mode    100666
    size    9639901
    parent  12389
    links   1
    pflags  40800000004
Indirect blocks:
               0 L1  0:5ec0a93000:1000 0:128136a7000:1000 4000L/e00P F=74 B=95516/95516
               0  L0 0:5ec0163000:20000 20000L/20000P F=1 B=95516/95516
           20000  L0 0:5ec0183000:20000 20000L/20000P F=1 B=95516/95516
           40000  L0 0:5ec01a3000:20000 20000L/20000P F=1 B=95516/95516
<---skip--->
          900000  L0 0:5ec0a63000:20000 20000L/20000P F=1 B=95516/95516
          920000  L0 0:5ec0a84000:f000 20000L/e800P F=1 B=95516/95516

        segment [0000000000000000, 0000000000940000) size 9.25M

P.S.
filesystem storage/home created with -o xattr=sa, so no mixtures xattr=on|sa here

P.P.S

rsync: get_acl: sys_acl_get_file(<censored>, ACL_TYPE_ACCESS): Input/output error (5)
rsync: set_acl: sys_acl_set_file(<censored>, ACL_TYPE_ACCESS): Bad address (14)
rsync: get_acl: sys_acl_get_file(<censored>, ACL_TYPE_ACCESS): Input/output error (5)
rsync: get_xattr_names: llistxattr(""/<censored>"",1024) failed: Bad address (14)

@dweeezil
Copy link
Contributor

Could you please build the latest https://github.com/dweeezil/zfs/tree/zdb and run the zdb with 7 -d's. You'll need a current spl master, too, to build it. There are a bunch of users having problems related to Posix ACL SA xattrs but I've yet to see a good dump on one of them that's corrupted. I think it would go a long way to helping track down the problem.

@TioNisla
Copy link
Author

spl - f9bde4f
zfs - 6d9036f

# ls -di a.test.file 
13852 a.test.file
root@ftp:/home# zdb -ddddddd storage/home 13852
Dataset storage/home [ZPL], ID 141, cr_txg 94790, 1.23T, 1096897 objects, rootbp DVA[0]=<0:1467adaa000:1000> DVA[1]=<0:2105a100000:1000> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=152848L/152848P fill=1096897 cksum=1a4722f915:87420c51f0d:178662ebe89ef:2ea6974b38f456

    Object  lvl   iblk   dblk  dsize  lsize   %full  type
     13852    2    16K   128K  9.20M  9.25M  100.00  ZFS plain file (K=inherit) (Z=inherit)
                                        196   bonus  System attributes
    dnode flags: USED_BYTES USERUSED_ACCOUNTED SPILL_BLKPTR
    dnode maxblkid: 73
    path    /a.test.file
    uid     14
    gid     11
    atime   Tue Sep 16 15:58:43 2014
    mtime   Tue Sep 24 11:58:12 2013
    ctime   Fri Sep 19 13:38:19 2014
    crtime  Tue Sep 16 15:58:41 2014
    gen 95516
    mode    100666
    size    9639901
    parent  4
    links   1
    pflags  40800000004
Indirect blocks:
               0 L1  0:5ec0a93000:1000 0:128136a7000:1000 4000L/e00P F=74 B=95516/95516
               0  L0 0:5ec0163000:20000 20000L/20000P F=1 B=95516/95516
           20000  L0 0:5ec0183000:20000 20000L/20000P F=1 B=95516/95516
           40000  L0 0:5ec01a3000:20000 20000L/20000P F=1 B=95516/95516
<---skip--->
          900000  L0 0:5ec0a63000:20000 20000L/20000P F=1 B=95516/95516
          920000  L0 0:5ec0a84000:f000 20000L/e800P F=1 B=95516/95516

        segment [0000000000000000, 0000000000940000) size 9.25M

@dweeezil
Copy link
Contributor

@TioNisla Your case is interesting in that the corruption is not on a directory. Unfortunately your zdb output above is not from my "zdb" branch (dweeezil/zfs@ce58fc1).

@TioNisla
Copy link
Author

TioNisla commented Oct 1, 2014

@dweeezil

zfs-ce58fc178bd5c6e8d462c21f1b8952685d2f852d

root@ftp:/home# ls -di a.test.file
13852 a.test.file
root@ftp:/home# zdb -ddddddd storage/home 13852
Dataset storage/home [ZPL], ID 141, cr_txg 94790, 1.74T, 1289346 objects, rootbp DVA[0]=<0:1f800037000:1000> DVA[1]=<0:2c800074000:1000> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=362851L/362851P fill=1289346 cksum=175f707f71:79ce4214e7d:158d4e7311d1d:2bb784b61a4f9e

    Object  lvl   iblk   dblk  dsize  lsize   %full  type
     13852    2    16K   128K  9.20M  9.25M  100.00  ZFS plain file (K=inherit) (Z=inherit)
                                        196   bonus  System attributes
    dnode flags: USED_BYTES USERUSED_ACCOUNTED SPILL_BLKPTR
    dnode maxblkid: 73

    Spill blkptr:
        0:5ec0161000:1000 0:128136a4000:1000 200L/200P F=1 B=95516/95516
    Spill blkptr dump: \010\000\000\000\000\000\000\000\010\013\140\057\000\000\000\000\010\000\000\000\000\000\000\000\040\265\011\224\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\002\007\054\200\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\034\165\001\000\000\000\000\000\001\000\000\000\000\000\000\000\040\230\122\274\007\000\000\000\174\073\015\025\106\003\000\000\240\350\053\317\035\265\000\000\043\230\117\143\071\235\032\000
    SA hdrsize 16
    SA layout 3
    path    /a.test.file
    uid     14
    gid     11
    atime   Tue Sep 16 15:58:43 2014
    mtime   Tue Sep 24 11:58:12 2013
    ctime   Fri Sep 19 13:38:19 2014
    crtime  Tue Sep 16 15:58:41 2014
    gen 95516
    mode    100666
    size    9639901
    parent  4
    links   1
    pflags  40800000004
    ndacl   3
    dump_znode_sa_xattr: sa_xattr_size=20 sa_size error=0
    SA packed dump sa_xattr_size=20: \001\001\000\000\000\000\000\000\000\000\000\001\000\000\000\000\010\000\000\000
    SA xattr dump:
    dump_znode_sa_xattr: nvlist_unpack error=14
Indirect blocks:
               0 L1  0:5ec0a93000:1000 0:128136a7000:1000 4000L/e00P F=74 B=95516/95516
               0  L0 0:5ec0163000:20000 20000L/20000P F=1 B=95516/95516
           20000  L0 0:5ec0183000:20000 20000L/20000P F=1 B=95516/95516
<---skip--->
          900000  L0 0:5ec0a63000:20000 20000L/20000P F=1 B=95516/95516
          920000  L0 0:5ec0a84000:f000 20000L/e800P F=1 B=95516/95516

        segment [0000000000000000, 0000000000940000) size 9.25M

root@ftp:/home# 

@TioNisla
Copy link
Author

TioNisla commented Oct 1, 2014

@dweeezil

other file on same filesystem (all OK):

root@ftp:/home# getfacl a.test.file2
# file: a.test.file2
# owner: ftp
# group: ftp
user::rwx
user:31302:rwx
user:49159:rwx
group::rwx
group:ftp:rwx
group:31302:rwx
group:49159:rwx
mask::rwx
other::rwx

root@ftp:/home# ls -di a.test.file2
3244035 a.test.file2
root@ftp:/home# zdb -ddddddd storage/home 3244035
Dataset storage/home [ZPL], ID 141, cr_txg 94790, 1.74T, 1289348 objects, rootbp DVA[0]=<0:1f8000c1000:1000> DVA[1]=<0:2c80014b000:1000> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=363618L/363618P fill=1289348 cksum=1aceb95a61:8c2eda4bf1b:190e845bb71c5:33716fd35a3aa9

    Object  lvl   iblk   dblk  dsize  lsize   %full  type
   3244035    1    16K  7.50K     4K  7.50K  100.00  ZFS plain file (K=inherit) (Z=inherit)
                                        316   bonus  System attributes
    dnode flags: USED_BYTES USERUSED_ACCOUNTED 
    dnode maxblkid: 0
    SA hdrsize 16
    SA layout 3
    path    /a.test.file2
    uid     14
    gid     11
    atime   Wed Oct  1 08:42:56 2014
    mtime   Wed Oct  1 08:42:57 2014
    ctime   Wed Oct  1 09:49:40 2014
    crtime  Wed Oct  1 09:49:40 2014
    gen 363618
    mode    100777
    size    7226
    parent  4
    links   1
    pflags  40800000004
    ndacl   3
    dump_znode_sa_xattr: sa_xattr_size=140 sa_size error=0
    SA packed dump sa_xattr_size=140: \001\001\000\000\000\000\000\000\000\000\000\001\000\000\000\170\000\000\000\170\000\000\000\027\163\171\163\164\145\155\056\160\157\163\151\170\137\141\143\154\137\141\143\143\145\163\163\000\000\000\000\012\000\000\000\114\002\000\000\000\001\000\007\000\377\377\377\377\002\000\007\000\106\172\000\000\002\000\007\000\007\300\000\000\004\000\007\000\377\377\377\377\010\000\007\000\013\000\000\000\010\000\007\000\106\172\000\000\010\000\007\000\007\300\000\000\020\000\007\000\377\377\377\377\040\000\007\000\377\377\377\377\000\000\000\000\000\000\000\000
    SA xattr dump:
                system.posix_acl_access[0]: 2
                system.posix_acl_access[1]: 0
                system.posix_acl_access[2]: 0
                system.posix_acl_access[3]: 0
                system.posix_acl_access[4]: 1
                system.posix_acl_access[5]: 0
                system.posix_acl_access[6]: 7
                system.posix_acl_access[7]: 0
                system.posix_acl_access[8]: 255
                system.posix_acl_access[9]: 255
                system.posix_acl_access[10]: 255
                system.posix_acl_access[11]: 255
                system.posix_acl_access[12]: 2
                system.posix_acl_access[13]: 0
                system.posix_acl_access[14]: 7
                system.posix_acl_access[15]: 0
                system.posix_acl_access[16]: 70
                system.posix_acl_access[17]: 122
                system.posix_acl_access[18]: 0
                system.posix_acl_access[19]: 0
                system.posix_acl_access[20]: 2
                system.posix_acl_access[21]: 0
                system.posix_acl_access[22]: 7
                system.posix_acl_access[23]: 0
                system.posix_acl_access[24]: 7
                system.posix_acl_access[25]: 192
                system.posix_acl_access[26]: 0
                system.posix_acl_access[27]: 0
                system.posix_acl_access[28]: 4
                system.posix_acl_access[29]: 0
                system.posix_acl_access[30]: 7
                system.posix_acl_access[31]: 0
                system.posix_acl_access[32]: 255
                system.posix_acl_access[33]: 255
                system.posix_acl_access[34]: 255
                system.posix_acl_access[35]: 255
                system.posix_acl_access[36]: 8
                system.posix_acl_access[37]: 0
                system.posix_acl_access[38]: 7
                system.posix_acl_access[39]: 0
                system.posix_acl_access[40]: 11
                system.posix_acl_access[41]: 0
                system.posix_acl_access[42]: 0
                system.posix_acl_access[43]: 0
                system.posix_acl_access[44]: 8
                system.posix_acl_access[45]: 0
                system.posix_acl_access[46]: 7
                system.posix_acl_access[47]: 0
                system.posix_acl_access[48]: 70
                system.posix_acl_access[49]: 122
                system.posix_acl_access[50]: 0
                system.posix_acl_access[51]: 0
                system.posix_acl_access[52]: 8
                system.posix_acl_access[53]: 0
                system.posix_acl_access[54]: 7
                system.posix_acl_access[55]: 0
                system.posix_acl_access[56]: 7
                system.posix_acl_access[57]: 192
                system.posix_acl_access[58]: 0
                system.posix_acl_access[59]: 0
                system.posix_acl_access[60]: 16
                system.posix_acl_access[61]: 0
                system.posix_acl_access[62]: 7
                system.posix_acl_access[63]: 0
                system.posix_acl_access[64]: 255
                system.posix_acl_access[65]: 255
                system.posix_acl_access[66]: 255
                system.posix_acl_access[67]: 255
                system.posix_acl_access[68]: 32
                system.posix_acl_access[69]: 0
                system.posix_acl_access[70]: 7
                system.posix_acl_access[71]: 0
                system.posix_acl_access[72]: 255
                system.posix_acl_access[73]: 255
                system.posix_acl_access[74]: 255
                system.posix_acl_access[75]: 255
    SA xattrs: 140 bytes, 1 entries

        system.posix_acl_access = \002\000\000\000\001\000\007\000\377\377\377\377\002\000\007\000Fz\000\000\002\000\007\000\007\300\000\000\004\000\007\000\377\377\377\377\010\000\007\000\013\000\000\000\010\000\007\000Fz\000\000\010\000\007\000\007\300\000\000\020\000\007\000\377\377\377\377 \000\007\000\377\377\377\377
Indirect blocks:
               0 L0 0:1f8000b5000:1000 1e00L/800P F=1 B=363618/363618

        segment [0000000000000000, 0000000000001e00) size 7.50K

@TioNisla
Copy link
Author

TioNisla commented Oct 1, 2014

@dweeezil

a.test.file  - 196 bonus System attributes - SPILL_BLKPTR - sa_xattr_size=20
a.test.file2 - 316 bonus System attributes -    <none>    - sa_xattr_size=140

316 - 140 = 176
196 - 20  = 176
---------------
120 bytes missing from "sa_xattr_size" of "a.test.file" (SA truncated @20 bytes)?

P.S.
There is no "Spill blkptr" processing in "dump_znode_sa_xattr" ?

@dweeezil
Copy link
Contributor

dweeezil commented Oct 2, 2014

@TioNisla Thanks for the additional information. I'll continue to look into this issue shortly. I've been totally sidetracked for the past week with my company's office moving and also chasing down hangs caused by echo 2 > /proc/sys/vm/drop_caches.

@dweeezil
Copy link
Contributor

dweeezil commented Oct 4, 2014

@TioNisla I'm finally able to get back to these issues this weekend. The problem with "a.test.file" is, as I suspected, a corrupted dnode. Given that the dumped spill blockptr looks OK and that the recorded bonus size of 196 is on the small side, the problem is that the layout is wrong which causes the whole thing to be parsed incorrectly. Could you please confirm that the spill block actually contains the SA xattr by running zdb -R storage 0:5ec0161000:1000 0:128136a4000:1000 and posting the output.

This is exactly the same problem as we're seeing in #2700.

Can you reliably reproduce this problem?

@TioNisla
Copy link
Author

TioNisla commented Oct 5, 2014

@dweeezil
Unfortunately, this problem is hard to reproduce
Output: https://gist.github.com/TioNisla/a3fa17d4aebb17291969

@dweeezil
Copy link
Contributor

dweeezil commented Oct 5, 2014

@TioNisla Thanks. The spill block you dumped had a perfectly valid SA xattr for a posix acl:

# file: blah
# owner: 14
# group: 11
user::rw-
user:31302:rwx  #effective:---
user:33137:rwx  #effective:---
user:49159:rwx  #effective:---
group::rwx      #effective:---
group:11:rwx    #effective:---
group:31302:rwx #effective:---
group:48104:rwx #effective:---
group:49159:rwx #effective:---
mask::---
other::---

One other question comes to mind: When you were running the rsync which caused the corruption, was there any other concurrent activity on the target filesystem? If so, what kind (normal filesystem access, read, write, zfs operations such as snapshot or destroy, etc.)?

@dweeezil
Copy link
Contributor

dweeezil commented Oct 5, 2014

@TioNisla Does this system have ECC memory? You mentioned the problem is hard to reproduce but have you ever been able to reproduce it?

@dweeezil
Copy link
Contributor

dweeezil commented Oct 5, 2014

@TioNisla Sorry, but as I look into this further, more questions arise. Did the directory in which the corrupted "a.test.file" was created have a default ACL? If so, does the ACL I showed above precisely match the default ACL? The reason I ask is that the code path through which xattr is set is quite different between the two cases.

@TioNisla
Copy link
Author

TioNisla commented Oct 6, 2014

@dweeezil

One other question comes to mind: When you were running the rsync which caused the
corruption, was there any other concurrent activity on the target filesystem?

No activity at all (exclude `rsync' from remote host). This is fresh installation and newly created zpool.

Does this system have ECC memory?

This is virtual machine @ vmware esxi 5.1 hv, running on HP ProLiant DL980 G7 hardware, of couse all memory ECC.

There is another file and it's parent dir - ls',zdb', `getfacl' outs here: https://gist.github.com/TioNisla/ea073dcbad9a1be8106c

@TioNisla
Copy link
Author

TioNisla commented Oct 6, 2014

@dweeezil

You mentioned the problem is hard to reproduce but have you ever been able to reproduce it?

These damages are mostly random, on different files from time to time. Need run full rsync and some files (~3-5%) get corrupted SA.

@TioNisla
Copy link
Author

TioNisla commented Oct 6, 2014

@dweeezil

And now, after removal of some files, there is a new problem:

root@ftp:~# dmesg
...
[    1.106680] SPL: Loaded module v0.6.3-1
[    1.134348] znvpair: module license 'CDDL' taints kernel.
[    1.134357] Disabling lock debugging due to kernel taint
[    1.161407] ZFS: Loaded module v0.6.3-1, ZFS pool version 5000, ZFS filesystem version 5
[    1.310019] tsc: Refined TSC clocksource calibration: 1862.000 MHz
[    1.410156] random: nonblocking pool is initialized
[    1.512841] BUG: unable to handle kernel paging request at ffffffffa01f4038
[    1.513321] IP: [<ffffffffa0135c74>] zio_data_buf_alloc+0xc/0x19 [zfs]
[    1.513326] PGD 1617067 PUD 1618063 PMD 1b8305067 PTE 0
[    1.513332] Oops: 0000 [#1] 
[    1.513337] Modules linked in: zfs(PO) zunicode(PO) zavl(PO) zcommon(PO) znvpair(PO) spl(O) zlib_inflate zlib_deflate vmxnet3 rtc_cmos
[    1.513343] CPU: 0 PID: 135 Comm: zpool Tainted: P           O  3.16.2 #1
[    1.513348] task: ffff8800ba907720 ti: ffff8800bb468000 task.ti: ffff8800bb468000
[    1.513353] RIP: 0010:[<ffffffffa0135c74>]  [<ffffffffa0135c74>] zio_data_buf_alloc+0xc/0x19 [zfs]
[    1.513359] RSP: 0018:ffff8800bb46b540  EFLAGS: 00010217
[    1.513364] RAX: 0000000000000050 RBX: 0000000002000000 RCX: ffff8800bb46b628
[    1.513369] RDX: ffff8801b53fb580 RSI: 0000000000000230 RDI: 000000000000ffff
[    1.513375] RBP: ffff8800ba880730 R08: ffff8801b53fb400 R09: ffff8801b620a7f0
[    1.513380] R10: 0000000000000000 R11: ffff8801b53fbd00 R12: ffff8801b620a7f0
[    1.513385] R13: ffff8800bb46b628 R14: ffff8800ba880000 R15: ffff8801b53fb580
[    1.513391] FS:  00007fb7c0799b80(0000) GS:ffffffff81623000(0000) knlGS:0000000000000000
[    1.513396] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[    1.513402] CR2: ffffffffa01f4038 CR3: 00000000bb45a000 CR4: 00000000000007b0
[    1.513407] Stack:
[    1.513412]  ffffffffa00ee539 ffffffff8103c8ef 0000000000000000 0000000300000001
[    1.513418]  ffff8801b52e1c18 ffffffffa016b000 ffffffffa0031d2a ffff8801b5c0a600
[    1.513423]  ffff8800bb46b628 ffff8801b53fb580 00000000003149ba ffff8801b52e9580
[    1.513428] Call Trace:
[    1.513439]  [<ffffffffa00ee539>] ? spa_load_verify_cb+0x96/0x16a [zfs]
[    1.513450]  [<ffffffff8103c8ef>] ? __wake_up+0x36/0x43
[    1.513461]  [<ffffffffa0031d2a>] ? cv_wait_common+0xfc/0x16e [spl]
[    1.513477]  [<ffffffffa00ca8e7>] ? traverse_visitbp+0x2d9/0x6d9 [zfs]
[    1.513488]  [<ffffffffa00b64c4>] ? arc_buf_remove_ref+0xd4/0xd4 [zfs]
[    1.513498]  [<ffffffffa00b6ca4>] ? arc_read+0x788/0x79b [zfs]
[    1.513509]  [<ffffffffa01373df>] ? zio_nowait+0x108/0x11c [zfs]
[    1.513520]  [<ffffffffa00cb30a>] ? traverse_dnode+0x97/0xa4 [zfs]
[    1.513531]  [<ffffffffa00cab8e>] ? traverse_visitbp+0x580/0x6d9 [zfs]
[    1.513541]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513552]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513563]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513574]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513584]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513595]  [<ffffffffa00caa58>] ? traverse_visitbp+0x44a/0x6d9 [zfs]
[    1.513606]  [<ffffffffa00cb2ca>] ? traverse_dnode+0x57/0xa4 [zfs]
[    1.513616]  [<ffffffffa00cac65>] ? traverse_visitbp+0x657/0x6d9 [zfs]
[    1.513627]  [<ffffffffa00caf63>] ? traverse_impl+0x27c/0x33b [zfs]
[    1.513638]  [<ffffffffa00ee4a3>] ? spa_async_suspend+0x67/0x67 [zfs]
[    1.513649]  [<ffffffffa00cb05d>] ? traverse_dataset+0x3b/0x40 [zfs]
[    1.513659]  [<ffffffffa00ee4a3>] ? spa_async_suspend+0x67/0x67 [zfs]
[    1.513670]  [<ffffffffa00cb169>] ? traverse_pool+0x107/0x157 [zfs]
[    1.513681]  [<ffffffffa00ee4a3>] ? spa_async_suspend+0x67/0x67 [zfs]
[    1.513692]  [<ffffffffa00f3965>] ? spa_load+0x1450/0x17eb [zfs]
[    1.513702]  [<ffffffffa00ff6a7>] ? txg_list_create+0x1b/0x4a [zfs]
[    1.513713]  [<ffffffffa00f30c8>] ? spa_load+0xbb3/0x17eb [zfs]
[    1.513724]  [<ffffffffa00edeac>] ? spa_activate+0x346/0x355 [zfs]
[    1.513735]  [<ffffffffa00f3d69>] ? spa_load_best+0x69/0x234 [zfs]
[    1.513745]  [<ffffffffa0042c11>] ? zpool_get_rewind_policy+0x47/0x138 [zcommon]
[    1.513756]  [<ffffffffa00f4023>] ? spa_open_common+0xef/0x302 [zfs]
[    1.513767]  [<ffffffffa00f4278>] ? spa_get_stats+0x33/0x24e [zfs]
[    1.513778]  [<ffffffffa011a0e5>] ? zfs_ioc_pool_stats+0x1c/0x4e [zfs]
[    1.513788]  [<ffffffffa011e5a0>] ? zfsdev_ioctl+0x30f/0x3ca [zfs]
[    1.513799]  [<ffffffff81093b89>] ? do_vfs_ioctl+0x336/0x3fd
[    1.513810]  [<ffffffff81081183>] ? kmem_cache_free+0x27/0x6d
[    1.513821]  [<ffffffff81093c83>] ? SyS_ioctl+0x33/0x58
[    1.513831]  [<ffffffff8122b790>] ? system_call_fastpath+0x16/0x1b
[    1.513837] Code: 45 37 40 74 10 83 7b 40 03 75 0a c7 83 68 02 00 00 82 01 21 00 5b b8 00 01 00 00 5d 41 5c c3 48 ff cf be 30 02 00 00 48 c1 ef 09 <48> 8b 3c fd 40 40 17 a0 e9 a1 49 ef ff 48 8d 46 ff 48 89 fa 48 
[    1.513842] RIP  [<ffffffffa0135c74>] zio_data_buf_alloc+0xc/0x19 [zfs]
[    1.513847]  RSP <ffff8800bb46b540>
[    1.513853] CR2: ffffffffa01f4038
[    1.513858] ---[ end trace 51f8f7451fdeeab6 ]---
[    1.514534] udevd[57]: '/sbin/zpool list' [135] terminated by signal 9 (Killed)
[    2.310147] Switched to clocksource tsc
...

root@ftp:~# zpool list
<hung>

@dweeezil
Copy link
Contributor

dweeezil commented Oct 6, 2014

@TioNisla since you seem to be able to reproduce it, could you build your spl and zfs with - - enable-debug and retry the rsync? I'm beginning to think that #2718 might be causing this but I can't prove it. I've continued working on fixing that issue but unfortunately the original approach I outlined isn't going to work well. I'm hoping to get a working patch within the next week. In the mean time, could you also do a ls -ld or a stat in the source directory on the corrupted file and the directory in which it is contained.

@TioNisla
Copy link
Author

TioNisla commented Oct 7, 2014

@dweeezil
Entire pool broken, I created new pool, build a custom UP kernel and spl/zfs modules with debugging turned on. I suspect that the problem is appear in a zpool "mirror" configuration. Start some testing.

spl-81857a34
zfs-ce58fc178

@behlendorf behlendorf added this to the 0.6.4 milestone Nov 17, 2014
ryao pushed a commit to ryao/zfs that referenced this issue Nov 29, 2014
If a spill block's dbuf hasn't yet been written when a spill block is
freed, the unwritten version will still be written.  This patch handles
the case in which a spill block's dbuf is freed and undirties it to
prevent it from being written.

The most common case in which this could happen is when xattr=sa is being
used and a long xattr is immediately replaced by a short xattr as in:

	setfattr -n user.test -v very_very_very..._long_value  <file>
	setfattr -n user.test -v short_value  <file>

The first value must be sufficiently long that a spill block is generated
and the second value must be short enough to not require a spill block.
In practice, this would typically happen due to internal xattr operations
as a result of setting acltype=posixacl.

Signed-off-by: Tim Chase <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes openzfs#2663
Closes openzfs#2700
Closes openzfs#2701
Closes openzfs#2717
Closes openzfs#2863
Closes openzfs#2884

Conflicts:
	module/zfs/dbuf.c
behlendorf pushed a commit that referenced this issue Dec 23, 2014
If a spill block's dbuf hasn't yet been written when a spill block is
freed, the unwritten version will still be written.  This patch handles
the case in which a spill block's dbuf is freed and undirties it to
prevent it from being written.

The most common case in which this could happen is when xattr=sa is being
used and a long xattr is immediately replaced by a short xattr as in:

	setfattr -n user.test -v very_very_very..._long_value  <file>
	setfattr -n user.test -v short_value  <file>

The first value must be sufficiently long that a spill block is generated
and the second value must be short enough to not require a spill block.
In practice, this would typically happen due to internal xattr operations
as a result of setting acltype=posixacl.

Signed-off-by: Tim Chase <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes #2663
Closes #2700
Closes #2701
Closes #2717
Closes #2863
Closes #2884
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants