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

replay-dual test_16 ZFS MDS crash: osd_declare_destroy() ASSERTION(dt_object_exists)

Details

    • Bug
    • Resolution: Fixed
    • Minor
    • Lustre 2.16.0
    • None
    • None
    • 3
    • 9223372036854775807

    Description

      This issue was created by maloo for Andreas Dilger <adilger@whamcloud.com>

      This issue relates to the following test suite run: https://testing.whamcloud.com/test_sets/33a011e7-eb8f-4b7c-a3d7-b77e6350ffb6

      test_16 failed with the following crash on master 10 times out of 123 runs:

      trevis-24vm4 MDS crashed during replay-dual test_16
      
      [ 2046.669261] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports
      [ 2046.670797] Lustre: 77088:0:(genops.c:1579:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 95a79532-73af-49b8-a4c8-d22c598e5614@<unknown>
      [ 2046.673531] Lustre: lustre-MDT0000: disconnecting 1 stale clients
      [ 2046.676737] LustreError: 77088:0:(osd_object.c:765:osd_declare_destroy()) ASSERTION( dt_object_exists(dt) ) failed: 
      [ 2046.678755] LustreError: 77088:0:(osd_object.c:765:osd_declare_destroy()) LBUG
      [ 2046.680139] Pid: 77088, comm: tgt_recover_0 4.18.0-477.15.1.el8_lustre.x86_64 #1 SMP Tue Aug 1 06:59:39 UTC 2023
      [ 2046.682036] Call Trace TBD:
      [ 2046.682768] [<0>] libcfs_call_trace+0x6f/0xa0 [libcfs]
      [ 2046.683842] [<0>] lbug_with_loc+0x3f/0x70 [libcfs]
      [ 2046.684807] [<0>] osd_declare_destroy+0x313/0x470 [osd_zfs]
      [ 2046.685989] [<0>] out_destroy_add_exec+0x60/0x250 [ptlrpc]
      [ 2046.687594] [<0>] update_recovery_exec.isra.22+0x1017/0x1f00 [ptlrpc]
      [ 2046.688937] [<0>] distribute_txn_replay_handle+0x332/0xd60 [ptlrpc]
      [ 2046.690247] [<0>] replay_request_or_update.isra.32+0x3dc/0xa20 [ptlrpc]
      [ 2046.691612] [<0>] target_recovery_thread+0x742/0x1330 [ptlrpc]
      [ 2046.692838] [<0>] kthread+0x134/0x150
      

      Test session details:
      clients: https://build.whamcloud.com/job/lustre-master-next/729 - 4.18.0-372.32.1.el8_6.x86_64
      servers: https://build.whamcloud.com/job/lustre-master-next/729 - 4.18.0-372.32.1.el8_lustre.x86_64

      This started failing on 2023-08-30 after a large set of patch landings:

      40c404129b LU-17038 tests: remove unused compile.sh script
      57a671d991 LU-17038 tests: remove mlink utility
      a0d8023d07 LU-12678 lnet: discard lnet_kvaddr_to_page
      e16d5d7d6f LU-17043 enc: fix osd lookup cache for long encrypted names
      b01f58e3a9 LU-15367 llite: iotrace standardization
      a897803cc7 LU-17039 build: cleanup ib_dma_map_sg
      4774d1fab1 LU-17038 tests: remove munlink utility
      a52545afed LU-16510 build: check if CONFIG_FORTIFY_SOURCE is defined
      479f9585b0 LU-17036 utils: make sure resize option is legit
      f4c336ad93 LU-17031 build: fix refefine __compiletime_strlen error
      e40be98400 LU-17030 llite: allow setting max_cached_mb to a %
      b557fb21c8 LU-10885 docs: note flock now being enabled by default
      9758129177 LU-17015 gss: support large kerberos token on client
      7f60b2b558 LU-17006 lnet: set up routes for going across subnets
      8a9c503c00 LU-16766 obdclass: trim kernel thread names in jobids
      39df815cd6 LU-17020 kernel: update RHEL 9.2 [5.14.0-284.25.1.el9_2]
      b1739ba3fa LU-17013 lov: fill FIEMAP_EXTENT_LAST flag
      f75ac594a2 LU-17011 utils: monotonic clock in lfs mirror
      77b133766b LU-17009 tests: fix runtests to read file name with backslash
      1db59b7b60 LU-17000 lnet: remove redundant errno check in liblnetconfig.c
      8e53a0ea59 LU-16866 tests: Use wait_update to check LNet recovery state
      05b289450b LU-17000 misc: remove Coverity annotations
      3c0b1fbf34 LU-16984 tests: replay-dual/31 checks file from DIR2
      d684885098 LU-16961 clang: plugins and build system integration
      a1bc7a84ce LU-16605 lfs: Add -n option to fid2path
      74140e5df4 LU-16943 tests: fix replay-single/135 under hard failure mode
      0439aaadb1 LU-16936 auster: add --client-only option
      7ff1a88126 LU-16883 ldiskfs: update for ext4-delayed-iput for RHEL9.0
      b9ce342ee1 LU-16896 flr: resync should not change file size
      c9e752c141 LU-16906 build: Server for newer SUSE 15 SP3 kernels
      2f0ebff4ad LU-16477 ldiskfs: Add ext4-enc-flag patch for SUSE 15 SP5
      d6673e5456 LU-16821 llite: report 1MiB directory blocksize
      8d24aa6b8e LU-16816 obdclass: make import_event more robust
      99144a595b LU-16232 script: fix the argument parse
      88141538c4 LU-9859 libcfs: discard cfs_gettok and cfs_str2num_check
      8785f25b05 LU-16552 test: add new lnet test for Multi-Rail setups
      d0a722cb8f LU-16374 ldiskfs: implement security.encdata xattr
      fe5706e0c1 LU-16235 hsm: check CDT state before adding actions llog
      7270e16fcb LU-15526 mdt: enable remote PDO lock
      324aa79eb5 LU-13730 tests: add file mirroring to racer
      1288681bb8 LU-14361 statahead: add statahead advise IOCTL
      e656cccbdc LU-14156 utils: mirror split to check for last in-sync early
      e2738d294d LU-12645 llite: Move readahead debug before exit
      1f4151ba71 LU-6142 lov: cleanup unneeded macros from lov_request.c
      ef414ce6e7 LU-6142 ptlrpc: Fix style issues for layout.c
      017cb44d26 LU-6142 ptlrpc: Fix style issues for events.c
      00c74b245f LU-16847 ldiskfs: refactor code.
      afe5813a48 LU-16077 ptlrpc: Fix ptlrpc_body_v2 with pb_uid/pb_gid
      91a3b286ba LU-16827 obdfilter: Fix obdfilter-survery/1a
      5c59f8551a LU-11457 osd-ldiskfs: scrub FID reuse
      d69b511af6 LU-16097 tests: skip quota subtests in interop
      576928b2cd LU-13306 mgs: support large NID for mgs_write_log_osc_to_lov
      

      VVVVVVV DO NOT REMOVE LINES BELOW, Added by Maloo for auto-association VVVVVVV
      replay-dual test_16 - trevis-24vm4 crashed during replay-dual test_16

      Attachments

        Issue Links

          Activity

            [LU-17075] replay-dual test_16 ZFS MDS crash: osd_declare_destroy() ASSERTION(dt_object_exists)

            It looks like even though the tests were run recently, they had old parents w/o the patch - 2.15.58.96 and 2.15.58.187, while the patch was landed as 2.15.59.18 two months ago.

            adilger Andreas Dilger added a comment - It looks like even though the tests were run recently, they had old parents w/o the patch - 2.15.58.96 and 2.15.58.187, while the patch was landed as 2.15.59.18 two months ago.

            It looks like this crash is still hit on master:

            not sure how this is possible - there is no such an assertion in the code:

            762)  ENTRY;
            763) 
            764)  LASSERT(th != NULL);
            765)  if (unlikely(obj->oo_dn == NULL))
            766)          RETURN(-ENOENT);
            767) 
            768)  oh = container_of(th, struct osd_thandle, ot_super);
            769)  LASSERT(oh->ot_tx != NULL);
            770) 
            771)  dmu_tx_mark_netfree(oh->ot_tx);
            772) 
            773)  /* declare that we'll remove object from fid-dnode mapping */
            774)  zapid = osd_get_name_n_idx(env, osd, fid, NULL, 0, &dn);
            775)  osd_tx_hold_zap(oh->ot_tx, zapid, dn, FALSE, NULL);
            776) 
            777)  osd_declare_xattrs_destroy(env, obj, oh);
            
            
            bzzz Alex Zhuravlev added a comment - It looks like this crash is still hit on master: not sure how this is possible - there is no such an assertion in the code: 762) ENTRY; 763) 764) LASSERT(th != NULL); 765) if (unlikely(obj->oo_dn == NULL)) 766) RETURN(-ENOENT); 767) 768) oh = container_of(th, struct osd_thandle, ot_super); 769) LASSERT(oh->ot_tx != NULL); 770) 771) dmu_tx_mark_netfree(oh->ot_tx); 772) 773) /* declare that we'll remove object from fid-dnode mapping */ 774) zapid = osd_get_name_n_idx(env, osd, fid, NULL, 0, &dn); 775) osd_tx_hold_zap(oh->ot_tx, zapid, dn, FALSE, NULL); 776) 777) osd_declare_xattrs_destroy(env, obj, oh);
            adilger Andreas Dilger added a comment - It looks like this crash is still hit on master: https://testing.whamcloud.com/test_sets/6ed7a4d7-bdc8-4ec1-9c40-d153616b520e https://testing.whamcloud.com/test_sets/9d19737b-46e0-4b5e-8f09-a58c39713ae0
            pjones Peter Jones added a comment -

            Landed for 2.16

            pjones Peter Jones added a comment - Landed for 2.16

            "Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/52496/
            Subject: LU-17075 osd: destroy declare shouldn't panic
            Project: fs/lustre-release
            Branch: master
            Current Patch Set:
            Commit: fa370c0d724b5a90e2d739e5d3c67066facf550b

            gerrit Gerrit Updater added a comment - "Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/52496/ Subject: LU-17075 osd: destroy declare shouldn't panic Project: fs/lustre-release Branch: master Current Patch Set: Commit: fa370c0d724b5a90e2d739e5d3c67066facf550b

            Hit the same crash:

            [ 1560.700808] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports
            [ 1560.702249] Lustre: 85844:0:(genops.c:1481:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fb74e030-180b-4830-b914-49fe8734c041@<unknown>
            [ 1560.704865] Lustre: lustre-MDT0000: disconnecting 1 stale clients
            [ 1560.708933] LustreError: 85844:0:(osd_object.c:765:osd_declare_destroy()) ASSERTION( dt_object_exists(dt) ) failed: 
            [ 1560.710896] LustreError: 85844:0:(osd_object.c:765:osd_declare_destroy()) LBUG
            [ 1560.712243] Pid: 85844, comm: tgt_recover_0 4.18.0-477.21.1.el8_lustre.x86_64 #1 SMP Sat Sep 23 17:41:02 UTC 2023
            [ 1560.714111] Call Trace TBD:
            [ 1560.714734] [<0>] libcfs_call_trace+0x63/0x90 [libcfs]
            [ 1560.715734] [<0>] lbug_with_loc+0x3f/0x70 [libcfs]
            [ 1560.716641] [<0>] osd_declare_destroy+0x313/0x470 [osd_zfs]
            [ 1560.717711] [<0>] out_destroy_add_exec+0x64/0x260 [ptlrpc]
            [ 1560.718927] [<0>] update_recovery_exec.isra.22+0x1017/0x1f00 [ptlrpc]
            [ 1560.720204] [<0>] distribute_txn_replay_handle+0x332/0xd60 [ptlrpc]
            [ 1560.721441] [<0>] replay_request_or_update.isra.30+0x3d8/0xa50 [ptlrpc]
            [ 1560.722746] [<0>] target_recovery_thread+0x742/0x1340 [ptlrpc]
            [ 1560.723913] [<0>] kthread+0x134/0x150
            

            It makes me wonder if we should do something on the server to identify with OST/MDT target a thread is working on, to help debug issues like this? Currently we name threads like "mdt_io01_001" which is "svc_type_cpt_thr", so we are consuming 6 characters of the thread name for CPT identification, but it might be more useful to shrink the CPT identification (1-base64 char for CPT and 2-base64 char for thread number, using base64url_table) and change the thread name to include the target index or something, like "mdt_ioBAB0001"?

            I don't know if there is a cost to changing current->comm, but it might be more than just "snprintf(current->comm, ...)", as I see there are "_get_task_comm()" and "_set_task_comm". I'm not sure if there is something else we could do to get extra information printed into a stack trace? Possibly something in LASSERT/LBUG that could determine the current target, maybe print if the thread is holding a DLM lock, etc...

            adilger Andreas Dilger added a comment - Hit the same crash: [ 1560.700808] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1560.702249] Lustre: 85844:0:(genops.c:1481:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fb74e030-180b-4830-b914-49fe8734c041@<unknown> [ 1560.704865] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1560.708933] LustreError: 85844:0:(osd_object.c:765:osd_declare_destroy()) ASSERTION( dt_object_exists(dt) ) failed: [ 1560.710896] LustreError: 85844:0:(osd_object.c:765:osd_declare_destroy()) LBUG [ 1560.712243] Pid: 85844, comm: tgt_recover_0 4.18.0-477.21.1.el8_lustre.x86_64 #1 SMP Sat Sep 23 17:41:02 UTC 2023 [ 1560.714111] Call Trace TBD: [ 1560.714734] [<0>] libcfs_call_trace+0x63/0x90 [libcfs] [ 1560.715734] [<0>] lbug_with_loc+0x3f/0x70 [libcfs] [ 1560.716641] [<0>] osd_declare_destroy+0x313/0x470 [osd_zfs] [ 1560.717711] [<0>] out_destroy_add_exec+0x64/0x260 [ptlrpc] [ 1560.718927] [<0>] update_recovery_exec.isra.22+0x1017/0x1f00 [ptlrpc] [ 1560.720204] [<0>] distribute_txn_replay_handle+0x332/0xd60 [ptlrpc] [ 1560.721441] [<0>] replay_request_or_update.isra.30+0x3d8/0xa50 [ptlrpc] [ 1560.722746] [<0>] target_recovery_thread+0x742/0x1340 [ptlrpc] [ 1560.723913] [<0>] kthread+0x134/0x150 It makes me wonder if we should do something on the server to identify with OST/MDT target a thread is working on, to help debug issues like this? Currently we name threads like " mdt_io01_001 " which is " svc_type_cpt_thr ", so we are consuming 6 characters of the thread name for CPT identification, but it might be more useful to shrink the CPT identification (1-base64 char for CPT and 2-base64 char for thread number, using base64url_table ) and change the thread name to include the target index or something, like " mdt_ioBAB0001 "? I don't know if there is a cost to changing current->comm , but it might be more than just " snprintf(current->comm, ...) ", as I see there are " _ get_task_comm() " and " _set_task_comm ". I'm not sure if there is something else we could do to get extra information printed into a stack trace? Possibly something in LASSERT/LBUG that could determine the current target, maybe print if the thread is holding a DLM lock, etc...

            "Alex Zhuravlev <bzzz@whamcloud.com>" uploaded a new patch: https://review.whamcloud.com/c/fs/lustre-release/+/52496
            Subject: LU-17075 osd: destroy declare shouldn't panic
            Project: fs/lustre-release
            Branch: master
            Current Patch Set: 1
            Commit: 7fcefa44274dd3754053f1323695e4c6e6290ea4

            gerrit Gerrit Updater added a comment - "Alex Zhuravlev <bzzz@whamcloud.com>" uploaded a new patch: https://review.whamcloud.com/c/fs/lustre-release/+/52496 Subject: LU-17075 osd: destroy declare shouldn't panic Project: fs/lustre-release Branch: master Current Patch Set: 1 Commit: 7fcefa44274dd3754053f1323695e4c6e6290ea4
            laisiyao Lai Siyao added a comment -

            It may be directory created in earlier test, let's revert this change.

            laisiyao Lai Siyao added a comment - It may be directory created in earlier test, let's revert this change.
            laisiyao Lai Siyao added a comment -

            It's a bit weird: replay-dual test_16() doesn't create mkdir, and all the test files are located on MDT0, but the backtrace shows it's update log based replay.

            laisiyao Lai Siyao added a comment - It's a bit weird: replay-dual test_16() doesn't create mkdir, and all the test files are located on MDT0, but the backtrace shows it's update log based replay.

            I'm having a similar problem locally, bisected down to:

            7270e16fcb	5	3	0		LU-15526 mdt: enable remote PDO lock
            bzzz Alex Zhuravlev added a comment - I'm having a similar problem locally, bisected down to: 7270e16fcb 5 3 0 LU-15526 mdt: enable remote PDO lock

            People

              bzzz Alex Zhuravlev
              maloo Maloo
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: