Bug 202029

Summary: mdadm cannot assemble raid5 aray with write journal
Product: IO/Storage Reporter: Tomasz Wiśniewski (tomiw69)
Component: MDAssignee: io_md
Status: NEW ---    
Severity: high CC: tomiw69
Priority: P1    
Hardware: Intel   
OS: Linux   
Kernel Version: 4.20.0-rc7 Subsystem:
Regression: No Bisected commit-id:

Description Tomasz Wiśniewski 2018-12-19 10:36:03 UTC
OS: ubuntu 16.04
mdadm version 4.1, same behaviour with mdadm-4.1-rc1
kernel: vanilla 4.20.0-rc7, same behaviour on kernels: 4.17.2-xanmod3, 4.18.4-xanmod3 

After reboot mdadm cannot assemble raid5  array with write journal, md0_raid5 process hung at 100% cpu


########
top - 11:27:43 up  1:01,  1 user,  load average: 2.00, 2.00, 1.99
Tasks: 245 total,   2 running, 147 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us, 12.5 sy,  0.0 ni, 87.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 16356268 total, 14490400 free,   741160 used,  1124708 buff/cache
KiB Swap:  4194300 total,  4194300 free,        0 used. 15165612 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  778 root      20   0       0      0      0 R  99.7  0.0  50:31.22 md0_raid5

####

ps -ef | grep mdadm | grep -v grep
root       771     1 15 10:26 ?        00:10:27 /sbin/mdadm --incremental --export /dev/md1 --offroot /dev/disk/by-id/md-name-ub-nas:1 /dev/disk/by-id/md-uuid-45435382:becadffe:aedeb5ab:11313f27
root      1841     1  0 10:29 ?        00:00:00 /sbin/mdadm --monitor --scan

###

cat /proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4]
md0 : active raid5 md1[6](J) sdd1[2] sdc1[1] sde1[5] sdf1[4]
      5860509696 blocks super 1.2 level 5, 64k chunk, algorithm 2 [4/4] [UUUU]

md1 : active raid1 nvme0n1p4[1]
      10476544 blocks super 1.2 [1/1] [U]
####
mdadm -D /dev/md0

/dev/md0:
           Version : 1.2
     Creation Time : Wed Nov 21 16:03:49 2018
        Raid Level : raid5
     Used Dev Size : 1953503232 (1863.01 GiB 2000.39 GB)
      Raid Devices : 4
     Total Devices : 5
       Persistence : Superblock is persistent

       Update Time : Wed Dec 19 10:26:30 2018
             State : active, Not Started
    Active Devices : 4
   Working Devices : 5
    Failed Devices : 0
     Spare Devices : 0

            Layout : left-symmetric
        Chunk Size : 64K

Consistency Policy : journal

              Name : ub-nas:0  (local to host ub-nas)
              UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
            Events : 3522

    Number   Major   Minor   RaidDevice State
       1       8       33        0      active sync   /dev/sdc1
       2       8       49        1      active sync   /dev/sdd1
       5       8       65        2      active sync   /dev/sde1
       4       8       81        3      active sync   /dev/sdf1

       6       9        1        -      journal   /dev/md1


###
md0 creation command:
 mdadm -C /dev/md0 -l5 -n4 -c64K --write-journal=/dev/md1 --bitmap=none --consistency-policy=journal  /dev/sd[c-f]1


###
dmesg errors
[  649.767590] md/raid:md0: recovering 832 data-only stripes and 31102 data-parity stripes
[  861.273876] INFO: task mdadm:771 blocked for more than 120 seconds.
[  861.274319]       Not tainted 4.20.0-rc7 #1
[  861.274613] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  861.275172] mdadm           D    0   771      1 0x00000004
[  861.275173] Call Trace:
[  861.275179]  ? __schedule+0x404/0x8f0
[  861.275181]  schedule+0x39/0x90
[  861.275186]  r5l_start+0x1282/0x1340 [raid456]
[  861.275189]  ? wait_woken+0x80/0x80
[  861.275191]  md_start+0x3b/0x60
[  861.275195]  do_md_run+0x4b/0xb0
[  861.275197]  md_ioctl+0x19da/0x1e80
[  861.275200]  ? current_time+0x4d/0x90
[  861.275203]  ? shmem_truncate_range+0x1e/0x40
[  861.275207]  ? fsnotify_grab_connector+0x3c/0x60
[  861.275209]  ? fsnotify_destroy_marks+0x22/0x110
[  861.275212]  blkdev_ioctl+0x967/0x9f0
[  861.275214]  ? dentry_kill+0x4d/0x1a0
[  861.275215]  block_ioctl+0x39/0x40
[  861.275218]  do_vfs_ioctl+0xa1/0x620
[  861.275222]  ksys_ioctl+0x66/0x70
[  861.275224]  __x64_sys_ioctl+0x16/0x20
[  861.275226]  do_syscall_64+0x55/0x100
[  861.275229]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  861.275231] RIP: 0033:0x7f23a49baf47
[  861.275235] Code: Bad RIP value.
[  861.275235] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  861.275237] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[  861.275237] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[  861.275238] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[  861.275238] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[  861.275239] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[  984.153444] INFO: task mdadm:771 blocked for more than 120 seconds.
[  984.153887]       Not tainted 4.20.0-rc7 #1
[  984.154180] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  984.154737] mdadm           D    0   771      1 0x00000004
[  984.154740] Call Trace:
[  984.154745]  ? __schedule+0x404/0x8f0
[  984.154747]  schedule+0x39/0x90
[  984.154753]  r5l_start+0x1282/0x1340 [raid456]
[  984.154757]  ? wait_woken+0x80/0x80
[  984.154759]  md_start+0x3b/0x60
[  984.154762]  do_md_run+0x4b/0xb0
[  984.154763]  md_ioctl+0x19da/0x1e80
[  984.154766]  ? current_time+0x4d/0x90
[  984.154769]  ? shmem_truncate_range+0x1e/0x40
[  984.154772]  ? fsnotify_grab_connector+0x3c/0x60
[  984.154774]  ? fsnotify_destroy_marks+0x22/0x110
[  984.154776]  blkdev_ioctl+0x967/0x9f0
[  984.154780]  ? dentry_kill+0x4d/0x1a0
[  984.154782]  block_ioctl+0x39/0x40
[  984.154784]  do_vfs_ioctl+0xa1/0x620
[  984.154786]  ksys_ioctl+0x66/0x70
[  984.154787]  __x64_sys_ioctl+0x16/0x20
[  984.154789]  do_syscall_64+0x55/0x100
[  984.154791]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  984.154792] RIP: 0033:0x7f23a49baf47
[  984.154795] Code: Bad RIP value.
[  984.154795] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  984.154796] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[  984.154796] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[  984.154797] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[  984.154798] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[  984.154798] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1107.033385] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1107.033827]       Not tainted 4.20.0-rc7 #1
[ 1107.034121] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1107.034679] mdadm           D    0   771      1 0x00000004
[ 1107.034681] Call Trace:
[ 1107.034686]  ? __schedule+0x404/0x8f0
[ 1107.034688]  schedule+0x39/0x90
[ 1107.034693]  r5l_start+0x1282/0x1340 [raid456]
[ 1107.034699]  ? wait_woken+0x80/0x80
[ 1107.034701]  md_start+0x3b/0x60
[ 1107.034703]  do_md_run+0x4b/0xb0
[ 1107.034705]  md_ioctl+0x19da/0x1e80
[ 1107.034708]  ? current_time+0x4d/0x90
[ 1107.034711]  ? shmem_truncate_range+0x1e/0x40
[ 1107.034713]  ? fsnotify_grab_connector+0x3c/0x60
[ 1107.034714]  ? fsnotify_destroy_marks+0x22/0x110
[ 1107.034717]  blkdev_ioctl+0x967/0x9f0
[ 1107.034719]  ? dentry_kill+0x4d/0x1a0
[ 1107.034720]  block_ioctl+0x39/0x40
[ 1107.034722]  do_vfs_ioctl+0xa1/0x620
[ 1107.034723]  ksys_ioctl+0x66/0x70
[ 1107.034725]  __x64_sys_ioctl+0x16/0x20
[ 1107.034727]  do_syscall_64+0x55/0x100
[ 1107.034728]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1107.034730] RIP: 0033:0x7f23a49baf47
[ 1107.034732] Code: Bad RIP value.
[ 1107.034732] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1107.034733] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1107.034734] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1107.034734] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1107.034735] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1107.034735] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1229.913468] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1229.913468]       Not tainted 4.20.0-rc7 #1
[ 1229.913469] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1229.913469] mdadm           D    0   771      1 0x00000004
[ 1229.913470] Call Trace:
[ 1229.913475]  ? __schedule+0x404/0x8f0
[ 1229.914767]  schedule+0x39/0x90
[ 1229.914772]  r5l_start+0x1282/0x1340 [raid456]
[ 1229.914776]  ? wait_woken+0x80/0x80
[ 1229.914777]  md_start+0x3b/0x60
[ 1229.914779]  do_md_run+0x4b/0xb0
[ 1229.914780]  md_ioctl+0x19da/0x1e80
[ 1229.914783]  ? current_time+0x4d/0x90
[ 1229.914786]  ? shmem_truncate_range+0x1e/0x40
[ 1229.914789]  ? fsnotify_grab_connector+0x3c/0x60
[ 1229.914790]  ? fsnotify_destroy_marks+0x22/0x110
[ 1229.914793]  blkdev_ioctl+0x967/0x9f0
[ 1229.914794]  ? dentry_kill+0x4d/0x1a0
[ 1229.914796]  block_ioctl+0x39/0x40
[ 1229.914798]  do_vfs_ioctl+0xa1/0x620
[ 1229.914801]  ksys_ioctl+0x66/0x70
[ 1229.914803]  __x64_sys_ioctl+0x16/0x20
[ 1229.914806]  do_syscall_64+0x55/0x100
[ 1229.914809]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1229.914812] RIP: 0033:0x7f23a49baf47
[ 1229.914816] Code: Bad RIP value.
[ 1229.914816] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1229.914818] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1229.914819] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1229.914819] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1229.914820] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1229.914821] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1352.793311] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1352.793753]       Not tainted 4.20.0-rc7 #1
[ 1352.794047] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1352.794602] mdadm           D    0   771      1 0x00000004
[ 1352.794605] Call Trace:
[ 1352.794611]  ? __schedule+0x404/0x8f0
[ 1352.794612]  schedule+0x39/0x90
[ 1352.794617]  r5l_start+0x1282/0x1340 [raid456]
[ 1352.794621]  ? wait_woken+0x80/0x80
[ 1352.794624]  md_start+0x3b/0x60
[ 1352.794626]  do_md_run+0x4b/0xb0
[ 1352.794628]  md_ioctl+0x19da/0x1e80
[ 1352.794632]  ? current_time+0x4d/0x90
[ 1352.794634]  ? shmem_truncate_range+0x1e/0x40
[ 1352.794637]  ? fsnotify_grab_connector+0x3c/0x60
[ 1352.794639]  ? fsnotify_destroy_marks+0x22/0x110
[ 1352.794641]  blkdev_ioctl+0x967/0x9f0
[ 1352.794644]  ? dentry_kill+0x4d/0x1a0
[ 1352.794646]  block_ioctl+0x39/0x40
[ 1352.794649]  do_vfs_ioctl+0xa1/0x620
[ 1352.794651]  ksys_ioctl+0x66/0x70
[ 1352.794653]  __x64_sys_ioctl+0x16/0x20
[ 1352.794655]  do_syscall_64+0x55/0x100
[ 1352.794657]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1352.794658] RIP: 0033:0x7f23a49baf47
[ 1352.794660] Code: Bad RIP value.
[ 1352.794661] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1352.794661] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1352.794662] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1352.794663] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1352.794663] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1352.794663] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1475.673012] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1475.673454]       Not tainted 4.20.0-rc7 #1
[ 1475.673748] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1475.674303] mdadm           D    0   771      1 0x00000004
[ 1475.674306] Call Trace:
[ 1475.674311]  ? __schedule+0x404/0x8f0
[ 1475.674313]  schedule+0x39/0x90
[ 1475.674317]  r5l_start+0x1282/0x1340 [raid456]
[ 1475.674321]  ? wait_woken+0x80/0x80
[ 1475.674324]  md_start+0x3b/0x60
[ 1475.674327]  do_md_run+0x4b/0xb0
[ 1475.674329]  md_ioctl+0x19da/0x1e80
[ 1475.674331]  ? current_time+0x4d/0x90
[ 1475.674335]  ? shmem_truncate_range+0x1e/0x40
[ 1475.674337]  ? fsnotify_grab_connector+0x3c/0x60
[ 1475.674338]  ? fsnotify_destroy_marks+0x22/0x110
[ 1475.674341]  blkdev_ioctl+0x967/0x9f0
[ 1475.674344]  ? dentry_kill+0x4d/0x1a0
[ 1475.674346]  block_ioctl+0x39/0x40
[ 1475.674348]  do_vfs_ioctl+0xa1/0x620
[ 1475.674351]  ksys_ioctl+0x66/0x70
[ 1475.674352]  __x64_sys_ioctl+0x16/0x20
[ 1475.674354]  do_syscall_64+0x55/0x100
[ 1475.674355]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1475.674357] RIP: 0033:0x7f23a49baf47
[ 1475.674359] Code: Bad RIP value.
[ 1475.674360] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1475.674360] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1475.674361] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1475.674361] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1475.674362] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1475.674362] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1598.552621] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1598.553064]       Not tainted 4.20.0-rc7 #1
[ 1598.564058] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1598.586747] mdadm           D    0   771      1 0x00000004
[ 1598.586749] Call Trace:
[ 1598.586753]  ? __schedule+0x404/0x8f0
[ 1598.586754]  schedule+0x39/0x90
[ 1598.586758]  r5l_start+0x1282/0x1340 [raid456]
[ 1598.586761]  ? wait_woken+0x80/0x80
[ 1598.586762]  md_start+0x3b/0x60
[ 1598.586764]  do_md_run+0x4b/0xb0
[ 1598.586766]  md_ioctl+0x19da/0x1e80
[ 1598.586768]  ? current_time+0x4d/0x90
[ 1598.586770]  ? shmem_truncate_range+0x1e/0x40
[ 1598.586772]  ? fsnotify_grab_connector+0x3c/0x60
[ 1598.586772]  ? fsnotify_destroy_marks+0x22/0x110
[ 1598.586774]  blkdev_ioctl+0x967/0x9f0
[ 1598.586775]  ? dentry_kill+0x4d/0x1a0
[ 1598.586776]  block_ioctl+0x39/0x40
[ 1598.586778]  do_vfs_ioctl+0xa1/0x620
[ 1598.586780]  ksys_ioctl+0x66/0x70
[ 1598.586781]  __x64_sys_ioctl+0x16/0x20
[ 1598.586783]  do_syscall_64+0x55/0x100
[ 1598.586784]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1598.586785] RIP: 0033:0x7f23a49baf47
[ 1598.586787] Code: Bad RIP value.
[ 1598.586788] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1598.586789] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1598.586789] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1598.586789] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1598.586790] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1598.586790] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1721.432173] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1721.443790]       Not tainted 4.20.0-rc7 #1
[ 1721.455184] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1721.478346] mdadm           D    0   771      1 0x00000004
[ 1721.478348] Call Trace:
[ 1721.478353]  ? __schedule+0x404/0x8f0
[ 1721.478354]  schedule+0x39/0x90
[ 1721.478359]  r5l_start+0x1282/0x1340 [raid456]
[ 1721.478361]  ? wait_woken+0x80/0x80
[ 1721.478364]  md_start+0x3b/0x60
[ 1721.478365]  do_md_run+0x4b/0xb0
[ 1721.478366]  md_ioctl+0x19da/0x1e80
[ 1721.478368]  ? current_time+0x4d/0x90
[ 1721.478371]  ? shmem_truncate_range+0x1e/0x40
[ 1721.478373]  ? fsnotify_grab_connector+0x3c/0x60
[ 1721.478374]  ? fsnotify_destroy_marks+0x22/0x110
[ 1721.478376]  blkdev_ioctl+0x967/0x9f0
[ 1721.478377]  ? dentry_kill+0x4d/0x1a0
[ 1721.478378]  block_ioctl+0x39/0x40
[ 1721.478380]  do_vfs_ioctl+0xa1/0x620
[ 1721.478382]  ksys_ioctl+0x66/0x70
[ 1721.478383]  __x64_sys_ioctl+0x16/0x20
[ 1721.478385]  do_syscall_64+0x55/0x100
[ 1721.478386]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1721.478387] RIP: 0033:0x7f23a49baf47
[ 1721.478389] Code: Bad RIP value.
[ 1721.478390] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1721.478391] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1721.478391] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1721.478392] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1721.478392] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1721.478392] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1844.311693] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1844.323404]       Not tainted 4.20.0-rc7 #1
[ 1844.334923] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1844.358138] mdadm           D    0   771      1 0x00000004
[ 1844.358139] Call Trace:
[ 1844.358144]  ? __schedule+0x404/0x8f0
[ 1844.358145]  schedule+0x39/0x90
[ 1844.358149]  r5l_start+0x1282/0x1340 [raid456]
[ 1844.358152]  ? wait_woken+0x80/0x80
[ 1844.358154]  md_start+0x3b/0x60
[ 1844.358155]  do_md_run+0x4b/0xb0
[ 1844.358157]  md_ioctl+0x19da/0x1e80
[ 1844.358158]  ? current_time+0x4d/0x90
[ 1844.358160]  ? shmem_truncate_range+0x1e/0x40
[ 1844.358161]  ? fsnotify_grab_connector+0x3c/0x60
[ 1844.358162]  ? fsnotify_destroy_marks+0x22/0x110
[ 1844.358164]  blkdev_ioctl+0x967/0x9f0
[ 1844.358165]  ? dentry_kill+0x4d/0x1a0
[ 1844.358166]  block_ioctl+0x39/0x40
[ 1844.358168]  do_vfs_ioctl+0xa1/0x620
[ 1844.358170]  ksys_ioctl+0x66/0x70
[ 1844.358171]  __x64_sys_ioctl+0x16/0x20
[ 1844.358173]  do_syscall_64+0x55/0x100
[ 1844.358175]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1844.358176] RIP: 0033:0x7f23a49baf47
[ 1844.358178] Code: Bad RIP value.
[ 1844.358179] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1844.358180] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1844.358180] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1844.358181] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1844.358181] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1844.358181] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
[ 1967.191195] INFO: task mdadm:771 blocked for more than 120 seconds.
[ 1967.202927]       Not tainted 4.20.0-rc7 #1
[ 1967.214478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1967.237754] mdadm           D    0   771      1 0x00000004
[ 1967.237756] Call Trace:
[ 1967.237760]  ? __schedule+0x404/0x8f0
[ 1967.237761]  schedule+0x39/0x90
[ 1967.237765]  r5l_start+0x1282/0x1340 [raid456]
[ 1967.237768]  ? wait_woken+0x80/0x80
[ 1967.237770]  md_start+0x3b/0x60
[ 1967.237772]  do_md_run+0x4b/0xb0
[ 1967.237773]  md_ioctl+0x19da/0x1e80
[ 1967.237775]  ? current_time+0x4d/0x90
[ 1967.237777]  ? shmem_truncate_range+0x1e/0x40
[ 1967.237779]  ? fsnotify_grab_connector+0x3c/0x60
[ 1967.237779]  ? fsnotify_destroy_marks+0x22/0x110
[ 1967.237781]  blkdev_ioctl+0x967/0x9f0
[ 1967.237782]  ? dentry_kill+0x4d/0x1a0
[ 1967.237783]  block_ioctl+0x39/0x40
[ 1967.237785]  do_vfs_ioctl+0xa1/0x620
[ 1967.237787]  ksys_ioctl+0x66/0x70
[ 1967.237788]  __x64_sys_ioctl+0x16/0x20
[ 1967.237790]  do_syscall_64+0x55/0x100
[ 1967.237792]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1967.237793] RIP: 0033:0x7f23a49baf47
[ 1967.237795] Code: Bad RIP value.
[ 1967.237796] RSP: 002b:00007ffd29c98ca8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1967.237797] RAX: ffffffffffffffda RBX: 00007ffd29c9ac76 RCX: 00007f23a49baf47
[ 1967.237797] RDX: 0000000000000000 RSI: 00000000400c0930 RDI: 0000000000000004
[ 1967.237798] RBP: 00000000017d1670 R08: 0000000000000000 R09: 0000000000000000
[ 1967.237798] R10: 0000000000000003 R11: 0000000000000246 R12: 00000000017d5370
[ 1967.237799] R13: 00000000017d1640 R14: 00007ffd29c99b50 R15: 0000000000000004
Comment 1 Tomasz Wiśniewski 2018-12-19 10:42:29 UTC
I tried also manul assemble after igonorig md0 array in mdadm.conf:

mdadm --assemble /dev/md0 -Rf  /dev/sdc1 /dev/sdd1 /dev/sde1 /dev/sdf1 /dev/md1

Result was the same.


#####
 mdadm --examine /dev/sd[cdef]1 /dev/md1
/dev/sdc1:
          Magic : a92b4efc
        Version : 1.2
    Feature Map : 0x200
     Array UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
           Name : ub-nas:0  (local to host ub-nas)
  Creation Time : Wed Nov 21 16:03:49 2018
     Raid Level : raid5
   Raid Devices : 4

 Avail Dev Size : 3907006464 (1863.01 GiB 2000.39 GB)
     Array Size : 5860509696 (5589.02 GiB 6001.16 GB)
    Data Offset : 18432 sectors
   Super Offset : 8 sectors
   Unused Space : before=18152 sectors, after=0 sectors
          State : clean
    Device UUID : 9379b48b:d7b567da:99536bf7:e9ef283e

    Update Time : Wed Dec 19 10:26:30 2018
  Bad Block Log : 512 entries available at offset 264 sectors
       Checksum : e38e23e3 - correct
         Events : 3522

         Layout : left-symmetric
     Chunk Size : 64K

   Device Role : Active device 0
   Array State : AAAA ('A' == active, '.' == missing, 'R' == replacing)
/dev/sdd1:
          Magic : a92b4efc
        Version : 1.2
    Feature Map : 0x200
     Array UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
           Name : ub-nas:0  (local to host ub-nas)
  Creation Time : Wed Nov 21 16:03:49 2018
     Raid Level : raid5
   Raid Devices : 4

 Avail Dev Size : 3907006464 (1863.01 GiB 2000.39 GB)
     Array Size : 5860509696 (5589.02 GiB 6001.16 GB)
    Data Offset : 18432 sectors
   Super Offset : 8 sectors
   Unused Space : before=18152 sectors, after=0 sectors
          State : clean
    Device UUID : ed4668e3:d38826c1:22bdb927:2bca59ea

    Update Time : Wed Dec 19 10:26:30 2018
  Bad Block Log : 512 entries available at offset 264 sectors
       Checksum : fe800805 - correct
         Events : 3522

         Layout : left-symmetric
     Chunk Size : 64K

   Device Role : Active device 1
   Array State : AAAA ('A' == active, '.' == missing, 'R' == replacing)
/dev/sde1:
          Magic : a92b4efc
        Version : 1.2
    Feature Map : 0x200
     Array UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
           Name : ub-nas:0  (local to host ub-nas)
  Creation Time : Wed Nov 21 16:03:49 2018
     Raid Level : raid5
   Raid Devices : 4

 Avail Dev Size : 3907006464 (1863.01 GiB 2000.39 GB)
     Array Size : 5860509696 (5589.02 GiB 6001.16 GB)
    Data Offset : 18432 sectors
   Super Offset : 8 sectors
   Unused Space : before=18152 sectors, after=0 sectors
          State : clean
    Device UUID : c8f2c9f5:abe7bdee:729edcfb:f6c348e8

    Update Time : Wed Dec 19 10:26:30 2018
  Bad Block Log : 512 entries available at offset 264 sectors
       Checksum : 108aedd8 - correct
         Events : 3522

         Layout : left-symmetric
     Chunk Size : 64K

   Device Role : Active device 2
   Array State : AAAA ('A' == active, '.' == missing, 'R' == replacing)
/dev/sdf1:
          Magic : a92b4efc
        Version : 1.2
    Feature Map : 0x200
     Array UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
           Name : ub-nas:0  (local to host ub-nas)
  Creation Time : Wed Nov 21 16:03:49 2018
     Raid Level : raid5
   Raid Devices : 4

 Avail Dev Size : 3907006464 (1863.01 GiB 2000.39 GB)
     Array Size : 5860509696 (5589.02 GiB 6001.16 GB)
    Data Offset : 18432 sectors
   Super Offset : 8 sectors
   Unused Space : before=18152 sectors, after=0 sectors
          State : clean
    Device UUID : f5f10a7a:03c57c0c:2ed04407:46346fd0

    Update Time : Wed Dec 19 10:26:30 2018
  Bad Block Log : 512 entries available at offset 264 sectors
       Checksum : a6196c65 - correct
         Events : 3522

         Layout : left-symmetric
     Chunk Size : 64K

   Device Role : Active device 3
   Array State : AAAA ('A' == active, '.' == missing, 'R' == replacing)
/dev/md1:
          Magic : a92b4efc
        Version : 1.2
    Feature Map : 0x200
     Array UUID : 9094396e:3e5b1d19:54861ff8:7fd9f9f6
           Name : ub-nas:0  (local to host ub-nas)
  Creation Time : Wed Nov 21 16:03:49 2018
     Raid Level : raid5
   Raid Devices : 4

 Avail Dev Size : 20934656 (9.98 GiB 10.72 GB)
     Array Size : 5860509696 (5589.02 GiB 6001.16 GB)
  Used Dev Size : 3907006464 (1863.01 GiB 2000.39 GB)
    Data Offset : 18432 sectors
   Super Offset : 8 sectors
   Unused Space : before=18152 sectors, after=0 sectors
          State : clean
    Device UUID : c3f48936:91d2e7fb:27b6c078:c7f771c2

    Update Time : Wed Dec 19 10:26:30 2018
  Bad Block Log : 512 entries available at offset 264 sectors
       Checksum : cea65d7d - correct
         Events : 3522

         Layout : left-symmetric
     Chunk Size : 64K

   Device Role : Journal
   Array State : AAAA ('A' == active, '.' == missing, 'R' == replacing)