Uploaded image for project: 'Lustre'
  1. Lustre
  2. LU-4105

Failure on test suite racer test_1

    XMLWordPrintable

Details

    • Bug
    • Resolution: Duplicate
    • Blocker
    • None
    • Lustre 2.5.0, Lustre 2.7.0, Lustre 2.5.3
    • None
    • client and server: lustre-b2_5 RHEL6 build #2
    • 3
    • 11021

    Description

      This issue was created by maloo for sarah <sarah@whamcloud.com>

      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
      

      Attachments

        Issue Links

          Activity

            People

              wc-triage WC Triage
              maloo Maloo
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: