[LU-4105] Failure on test suite racer test_1

• Type: Bug
• Resolution: Duplicate
• Priority: Blocker
• Affects Version/s: Lustre 2.5.0, Lustre 2.7.0, Lustre 2.5.3
• Environment: client and server: lustre-b2_5 RHEL6 build #2
• Severity: 3
• Assignee: WC Triage
• Reporter: Maloo

Description

This issue was created by maloo for sarah <[e-mail]>

This issue relates to the following test suite run: http://maloo.whamcloud.com/test_sets/758c2064-3456-11e3-9356-52540035b04c.

The sub-test test_1 failed with the following error:

test failed to respond and timed out

client console shows:

08:50:18:Lustre: DEBUG MARKER: == racer test 1: racer on clients: client-13vm1.lab.whamcloud.com,client-13vm2 DURATION=900 == 08:49:53 (1381592993)
08:50:18:Lustre: DEBUG MARKER: DURATION=900 MDSCOUNT=1 				   /usr/lib64/lustre/tests/racer/racer.sh /mnt/lustre/racer 
08:50:19:Lustre: DEBUG MARKER: DURATION=900 MDSCOUNT=1 				   /usr/lib64/lustre/tests/racer/racer.sh /mnt/lustre2/racer 
08:54:39:Lustre: lustre-OST0004-osc-ffff880032581c00: Connection to lustre-OST0004 (at 10.10.4.212@tcp) was lost; in progress operations using this service will wait for recovery to complete
08:54:42:LustreError: 11-0: lustre-OST0004-osc-ffff880032581c00: Communicating with 10.10.4.212@tcp, operation ldlm_enqueue failed with -107.
08:54:44:LustreError: 167-0: lustre-OST0004-osc-ffff880032581c00: This client was evicted by lustre-OST0004; in progress operations using this service will fail.
08:54:44:Lustre: 26160:0:(llite_lib.c:2484:ll_dirty_page_discard_warn()) lustre: dirty page discard: 10.10.4.211@tcp:/lustre/fid: [0x200000403:0x158b:0x0]/ may get corrupted (rc -108)
08:54:45:Lustre: 26161:0:(llite_lib.c:2484:ll_dirty_page_discard_warn()) lustre: dirty page discard: 10.10.4.211@tcp:/lustre/fid: [0x200000402:0x185b:0x0]//racer/11/11/11 may get corrupted (rc -108)
08:54:45:Lustre: lustre-OST0004-osc-ffff880032581c00: Connection restored to lustre-OST0004 (at 10.10.4.212@tcp)
09:01:24:INFO: task dir_create.sh:7007 blocked for more than 120 seconds.
09:01:25:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:01:26:dir_create.sh D 0000000000000000     0  7007   6999 0x00000080
09:01:27: ffff880029a7fbd8 0000000000000086 525971bf00000000 0000000000057b80
09:01:27: 00001b5f00000000 00000d1d00000000 ffff880029a7fc38 ffffffffa08e9d3d
09:01:27: ffff88004badf098 ffff880029a7ffd8 000000000000fb88 ffff88004badf098
09:01:27:Call Trace:
09:01:27: [<ffffffffa08e9d3d>] ? ll_revalidate_it+0x48d/0x1b20 [lustre]
09:01:27: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:01:27: [<ffffffff8119af58>] ? __d_lookup+0xd8/0x150
09:01:27: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:01:28: [<ffffffff811907ab>] do_lookup+0x11b/0x230
09:01:28: [<ffffffff81190acd>] __link_path_walk+0x20d/0x1030
09:01:28: [<ffffffff81191b7a>] path_walk+0x6a/0xe0
09:01:28: [<ffffffff81192d91>] do_filp_open+0x201/0xdc0
09:01:29: [<ffffffff8104759c>] ? __do_page_fault+0x1ec/0x480
09:01:30: [<ffffffff81014f79>] ? init_fpu+0x59/0xc0
09:01:30: [<ffffffff8119f922>] ? alloc_fd+0x92/0x160
09:01:30: [<ffffffff8117e249>] do_sys_open+0x69/0x140
09:01:31: [<ffffffff8117e360>] sys_open+0x20/0x30
09:01:31: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:01:31:INFO: task dir_create.sh:7016 blocked for more than 120 seconds.
09:01:31:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:01:32:dir_create.sh D 0000000000000000     0  7016   6999 0x00000080
09:01:32: ffff88007cdefbd8 0000000000000086 525971bf00000000 000000000009639c
09:01:32: 00001b6800000000 00000d1d00000000 ffff88007cdefc38 ffffffffa08e9d3d
09:01:32: ffff88007cdedab8 ffff88007cdeffd8 000000000000fb88 ffff88007cdedab8
09:01:32:Call Trace:
09:01:32: [<ffffffffa08e9d3d>] ? ll_revalidate_it+0x48d/0x1b20 [lustre]
09:01:33: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:01:34: [<ffffffff8119af58>] ? __d_lookup+0xd8/0x150
09:01:34: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:01:35: [<ffffffff811907ab>] do_lookup+0x11b/0x230
09:01:35: [<ffffffff81190acd>] __link_path_walk+0x20d/0x1030
09:01:35: [<ffffffff81191b7a>] path_walk+0x6a/0xe0
09:01:36: [<ffffffff81192d91>] do_filp_open+0x201/0xdc0
09:01:36: [<ffffffff8104759c>] ? __do_page_fault+0x1ec/0x480
09:01:36: [<ffffffff81014f79>] ? init_fpu+0x59/0xc0
09:01:38: [<ffffffff8119f922>] ? alloc_fd+0x92/0x160
09:01:38: [<ffffffff8117e249>] do_sys_open+0x69/0x140
09:01:39: [<ffffffff8117e360>] sys_open+0x20/0x30
09:01:39: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:01:39:INFO: task rm:14589 blocked for more than 120 seconds.
09:01:39:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:01:39:rm            D 0000000000000000     0 14589   7055 0x00000080
09:01:40: ffff880068037e08 0000000000000086 ffff8800103e4040 ffff8800103e4040
09:01:40: ffff8800103e4040 ffff880068169040 ffff8800103e4040 0000001000000286
09:01:40: ffff8800103e45f8 ffff880068037fd8 000000000000fb88 ffff8800103e45f8
09:01:40:Call Trace:
09:01:40: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:01:41: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:01:41: [<ffffffff81192367>] do_rmdir+0xb7/0x120
09:01:42: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:01:43: [<ffffffff811923fd>] sys_unlinkat+0x2d/0x40
09:01:43: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:01:43:INFO: task mv:14594 blocked for more than 120 seconds.
09:01:44:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:01:46:mv            D 0000000000000000     0 14594   7009 0x00000080
09:01:46: ffff8800376c7d08 0000000000000082 ffff8800376c7d18 ffffffff81190a15
09:01:47: 0000003f1ec64000 ffffea00016d5268 ffff8800376c7d08 ffff880018523540
09:01:47: ffff880018523af8 ffff8800376c7fd8 000000000000fb88 ffff880018523af8
09:01:47:Call Trace:
09:01:47: [<ffffffff81190a15>] ? __link_path_walk+0x155/0x1030
09:01:50: [<ffffffff811a20d0>] ? mntput_no_expire+0x30/0x110
09:01:50: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:01:50: [<ffffffff8118f541>] ? path_put+0x31/0x40
09:01:51: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:01:51: [<ffffffff8118e9b3>] lock_rename+0x63/0xe0
09:01:51: [<ffffffff81191f9f>] sys_renameat+0x11f/0x240
09:01:52: [<ffffffff81186b64>] ? cp_new_stat+0xe4/0x100
09:01:53: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:01:53: [<ffffffff811920db>] sys_rename+0x1b/0x20
09:01:53: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:01:53:INFO: task mv:14603 blocked for more than 120 seconds.
09:01:54:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:01:54:mv            D 0000000000000000     0 14603   7038 0x00000080
09:01:54: ffff88005fc1dd08 0000000000000082 ffff88005fc1dd18 ffffffff81190a15
09:01:54: 0000003f1ec64000 ffffea00016d5268 ffff88005fc1dd08 ffff88002d8d4040
09:01:54: ffff88002d8d45f8 ffff88005fc1dfd8 000000000000fb88 ffff88002d8d45f8
09:01:54:Call Trace:
09:01:55: [<ffffffff81190a15>] ? __link_path_walk+0x155/0x1030
09:01:56: [<ffffffff811a20d0>] ? mntput_no_expire+0x30/0x110
09:01:57: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:01:57: [<ffffffff8118f541>] ? path_put+0x31/0x40
09:01:58: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:01:58: [<ffffffff8118e98f>] lock_rename+0x3f/0xe0
09:01:58: [<ffffffff81191f9f>] sys_renameat+0x11f/0x240
09:01:58: [<ffffffff81186b64>] ? cp_new_stat+0xe4/0x100
09:01:58: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:01:58: [<ffffffff811920db>] sys_rename+0x1b/0x20
09:01:59: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:01:59:INFO: task ln:14613 blocked for more than 120 seconds.
09:02:00:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:02:01:ln            D 0000000000000000     0 14613   7011 0x00000080
09:02:02: ffff88005c457dd8 0000000000000082 ffff88005e721bb8 0000000000000000
09:02:02: ffff88005c457d88 ffff88007c2f4ae0 ffff88007c2f4ae0 ffff88007c2f4ae0
09:02:03: ffff88007c2f5098 ffff88005c457fd8 000000000000fb88 ffff88007c2f5098
09:02:03:Call Trace:
09:02:03: [<ffffffff811a20d0>] ? mntput_no_expire+0x30/0x110
09:02:03: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:02:03: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:02:03: [<ffffffff8118ebb0>] lookup_create+0x30/0xd0
09:02:04: [<ffffffff811928d9>] sys_symlinkat+0x99/0x120
09:02:05: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:02:07: [<ffffffff81192976>] sys_symlink+0x16/0x20
09:02:07: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:02:08:INFO: task rm:14615 blocked for more than 120 seconds.
09:02:08:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:02:09:rm            D 0000000000000000     0 14615   7046 0x00000080
09:02:09: ffff88006088de08 0000000000000086 ffff880019cb7540 ffff880019cb7540
09:02:10: ffff880019cb7540 ffff88005dd3c1b8 ffff880019cb7540 000000108119cfaf
09:02:11: ffff880019cb7af8 ffff88006088dfd8 000000000000fb88 ffff880019cb7af8
09:02:12:Call Trace:
09:02:13: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:02:13: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:02:14: [<ffffffff81192367>] do_rmdir+0xb7/0x120
09:02:14: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:02:15: [<ffffffff811923fd>] sys_unlinkat+0x2d/0x40
09:02:15: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:02:15:INFO: task rm:14625 blocked for more than 120 seconds.
09:02:16:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:02:16:rm            D 0000000000000000     0 14625   7026 0x00000080
09:02:17: ffff8800376c5e08 0000000000000086 ffff88005e07f500 ffff88005e07f500
09:02:17: ffff88005e07f500 ffff8800102690c0 ffff88005e07f500 0000001000000286
09:02:17: ffff88005e07fab8 ffff8800376c5fd8 000000000000fb88 ffff88005e07fab8
09:02:17:Call Trace:
09:02:19: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:02:20: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:02:20: [<ffffffff81192367>] do_rmdir+0xb7/0x120
09:02:20: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:02:20: [<ffffffff811923fd>] sys_unlinkat+0x2d/0x40
09:02:20: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:02:21:INFO: task mv:14630 blocked for more than 120 seconds.
09:02:21:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:02:22:mv            D 0000000000000000     0 14630   7018 0x00000080
09:02:24: ffff8800670b5d08 0000000000000082 ffff8800670b5d18 ffffffff81190a15
09:02:25: 0000003f1ec64000 ffffea00016d5268 ffff8800670b5c98 ffff8800103dd540
09:02:25: ffff8800103ddaf8 ffff8800670b5fd8 000000000000fb88 ffff8800103ddaf8
09:02:26:Call Trace:
09:02:26: [<ffffffff81190a15>] ? __link_path_walk+0x155/0x1030
09:02:26: [<ffffffff811a20d0>] ? mntput_no_expire+0x30/0x110
09:02:28: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:02:29: [<ffffffff8118f541>] ? path_put+0x31/0x40
09:02:30: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:02:30: [<ffffffff8118e98f>] lock_rename+0x3f/0xe0
09:02:30: [<ffffffff81191f9f>] sys_renameat+0x11f/0x240
09:02:30: [<ffffffff81186b64>] ? cp_new_stat+0xe4/0x100
09:02:30: [<ffffffff81186e3e>] ? vfs_lstat+0x1e/0x20
09:02:30: [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
09:02:31: [<ffffffff811920db>] sys_rename+0x1b/0x20
09:02:31: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:02:32:INFO: task ls:14643 blocked for more than 120 seconds.
09:02:33:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
09:02:34:ls            D 0000000000000000     0 14643   7031 0x00000080
09:02:34: ffff88005d631748 0000000000000086 ffff88005d631728 ffffffffa0807116
09:02:34: 0000000000000000 ffffffffa086b240 ffff88005f9e6400 ffffffffa07e04c0
09:02:35: ffff88007a273058 ffff88005d631fd8 000000000000fb88 ffff88007a273058
09:02:35:Call Trace:
09:02:35: [<ffffffffa0807116>] ? __req_capsule_get+0x166/0x710 [ptlrpc]
09:02:35: [<ffffffffa07e04c0>] ? lustre_msg_string+0x0/0x290 [ptlrpc]
09:02:36: [<ffffffff8150f78e>] __mutex_lock_slowpath+0x13e/0x180
09:02:36: [<ffffffffa0493167>] ? mdc_open_pack+0x247/0x260 [mdc]
09:02:37: [<ffffffff8150f62b>] mutex_lock+0x2b/0x50
09:02:38: [<ffffffffa0497a7d>] mdc_enqueue+0x22d/0x1a10 [mdc]
09:02:38: [<ffffffffa049945d>] mdc_intent_lock+0x1fd/0x64a [mdc]
09:02:39: [<ffffffffa0932740>] ? ll_md_blocking_ast+0x0/0x790 [lustre]
09:02:39: [<ffffffffa07bf520>] ? ldlm_completion_ast+0x0/0x920 [ptlrpc]
09:02:39: [<ffffffffa0495d71>] ? mdc_lock_match+0xb1/0x160 [mdc]
09:02:39: [<ffffffffa03d85a3>] lmv_intent_open+0x213/0x8d0 [lmv]
09:02:41: [<ffffffffa0932740>] ? ll_md_blocking_ast+0x0/0x790 [lustre]
09:02:42: [<ffffffffa03be7cb>] ? lmv_lock_match+0x1bb/0x470 [lmv]
09:02:42: [<ffffffffa062ba15>] ? class_handle2object+0x95/0x190 [obdclass]
09:02:42: [<ffffffffa03d8f1b>] lmv_intent_lock+0x2bb/0x380 [lmv]
09:02:42: [<ffffffffa0932740>] ? ll_md_blocking_ast+0x0/0x790 [lustre]
09:02:42: [<ffffffffa0931e8d>] ? ll_i2gids+0x3d/0xd0 [lustre]
09:02:42: [<ffffffffa0918c9d>] ? ll_prep_md_op_data+0x10d/0x3b0 [lustre]
09:02:43: [<ffffffffa08e9b25>] ll_revalidate_it+0x275/0x1b20 [lustre]
09:02:43: [<ffffffffa0932740>] ? ll_md_blocking_ast+0x0/0x790 [lustre]
09:02:43: [<ffffffffa08eb503>] ll_revalidate_nd+0x133/0x3e0 [lustre]
09:02:43: [<ffffffff811906f6>] do_lookup+0x66/0x230
09:02:44: [<ffffffff81190ff4>] __link_path_walk+0x734/0x1030
09:02:44: [<ffffffffa03c511d>] ? lmv_clear_open_replay_data+0x2ad/0x6d0 [lmv]
09:02:45: [<ffffffffa07d06b0>] ? ptlrpc_req_finished+0x10/0x20 [ptlrpc]
09:02:45: [<ffffffff81191b7a>] path_walk+0x6a/0xe0
09:02:45: [<ffffffff81191d4b>] do_path_lookup+0x5b/0xa0
09:02:45: [<ffffffff81182830>] ? get_empty_filp+0xa0/0x180
09:02:46: [<ffffffff81192c8b>] do_filp_open+0xfb/0xdc0
09:02:46: [<ffffffff811a20d0>] ? mntput_no_expire+0x30/0x110
09:02:46: [<ffffffff8119f922>] ? alloc_fd+0x92/0x160
09:02:46: [<ffffffff8117e249>] do_sys_open+0x69/0x140
09:02:46: [<ffffffff8100c535>] ? math_state_restore+0x45/0x60
09:02:46: [<ffffffff8117e360>] sys_open+0x20/0x30
09:02:47: [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
09:02:47:Lustre: lustre-MDT0000-mdc-ffff880032581c00: Connection to lustre-MDT0000 (at 10.10.4.211@tcp) was lost; in progress operations using this service will wait for recovery to complete
09:02:47:LustreError: 14642:0:(ldlm_request.c:134:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1381593535, 200s ago), entering recovery for lustre-MDT0000_UUID@10.10.4.211@tcp ns: lustre-MDT0000-mdc-ffff880032581c00 lock: ffff880067089b40/0x19bd7e0c7fd16370 lrc: 4/1,0 mode: --/PR res: [0x200000400:0x1:0x0].0 bits 0x2 rrc: 2 type: IBT flags: 0x0 nid: local remote: 0x31861536cea3e045 expref: -99 pid: 14642 timeout: 0 lvb_type: 0

Issue Links

• is related to: LU-5144 rename vs link deadlock