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

Client GPF, null pointer & LBUG using FIEMAP

Details

    • Bug
    • Resolution: Fixed
    • Blocker
    • Lustre 2.6.0, Lustre 2.5.2
    • Lustre 2.4.0, Lustre 2.4.1, Lustre 2.5.0, Lustre 2.6.0
    • 3
    • 12644

    Description

      When attempting to run a simple code designed to exercise the fiemap ioctl on master client (from 140211)/master server(slightly older) on CentOS 6.4, we see the following failures (code will be attached to this ticket) (all of them are replicated by the same code, it seems to be more or less random which we get):

      1) Null pointer dereference in cl_object_top

      2)

       <0>LustreError: 1752:0:(mdc_request.c:913:mdc_close()) ASSERTION( mod->mod_open_req != NULL && mod->mod_open_req->rq_type != LI_POISON ) failed: POISONED open (null)!
      <0>LustreError: 1752:0:(mdc_request.c:913:mdc_close()) LBUG
      

      3) GPF in mdc_close trying to print a debug message.

      Running the code a few times (5-10, the included 'runit' script does this; it sometimes needs to be run twice to crash a client) consistently crashes my client with one of these errors.

      Also, after crashing the client, something is corrupted in the fiemap directory containing the code, and I have to delete it and replace it with a copy from elsewhere before I can run the code again. (The fiemap code also sometimes reports errors related to incorrect behavior before the client crashes.)

      Here are the full stack traces for those bugs.

      Full stack trace from 1) above:

      <1>BUG: unable to handle kernel NULL pointer dereference at 0000000000000080
      <1>IP: [<ffffffffa040b3de>] cl_object_top+0xe/0x150 [obdclass]
      <4>PGD 374fb067 PUD 7d5d9067 PMD 0
      <4>Oops: 0000 [#1] SMP
      <4>last sysfs file: /sys/devices/virtual/block/dm-1/dm/name
      <4>CPU 1
      <4>Modules linked in: osc(U) lmv(U) mgc(U) nfs lockd fscache auth_rpcgss nfs_acl lustre(U) lov(U) mdc(U) fid(U) fld(U) ksocklnd(U) ptlrpc(U) obdclass(U) lnet(U) sha512_generic sha256_generic crc32c_intel libcfs(U) sunrpc ipv6 ppdev parport_pc parport e1000 vmware_balloon sg i2c_piix4 i2c_core shpchp ext4 jbd2 mbcache sd_mod crc_t10dif sr_mod cdrom mptspi mptscsih mptbase scsi_transport_spi pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
      <4>
      <4>Pid: 1614, comm: flush-lustre-1 Not tainted 2.6.32.358.18.1.el6_lustre #4 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
      <4>RIP: 0010:[<ffffffffa040b3de>]  [<ffffffffa040b3de>] cl_object_top+0xe/0x150 [obdclass]
      <4>RSP: 0018:ffff88007c9319d0  EFLAGS: 00010282
      <4>RAX: ffff88007c916800 RBX: ffff88007d62f488 RCX: 0000000000000080
      <4>RDX: ffff880079b3f400 RSI: ffffffffa04676a0 RDI: 0000000000000080
      <4>RBP: ffff88007c9319e0 R08: 0000000000000001 R09: 0000000000000000
      <4>R10: 0000000000000000 R11: 0000000000000000 R12: ffff88007d62ba10
      <4>R13: 0000000000000004 R14: 0000000000000080 R15: ffff88007c916800
      <4>FS:  0000000000000000(0000) GS:ffff880002280000(0000) knlGS:0000000000000000
      <4>CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
      <4>CR2: 0000000000000080 CR3: 000000007b4ac000 CR4: 00000000000007e0
      <4>DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
      <4>DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
      <4>Process flush-lustre-1 (pid: 1614, threadinfo ffff88007c930000, task ffff88007cea6ae0)
      <4>Stack:
      <4> ffff88007c9319e0 ffff88007d62f488 ffff88007c931a20 ffffffffa041abed
      <4><d> 0000000000000000 ffff88007b4b34c0 ffff88007d62b9b8 0000000000000000
      <4><d> ffff88007be6a608 ffff88007d6d2898 ffff88007c931a80 ffffffffa08de9fb
      <4>Call Trace:
      <4> [<ffffffffa041abed>] cl_io_sub_init+0x3d/0xc0 [obdclass]
      <4> [<ffffffffa08de9fb>] lov_sub_get+0x22b/0x690 [lov]
      <4> [<ffffffffa08e1376>] lov_io_iter_init+0xd6/0x480 [lov]
      <4> [<ffffffffa0417dcd>] cl_io_iter_init+0x5d/0x110 [obdclass]
      <4> [<ffffffffa041bdac>] cl_io_loop+0x4c/0x1b0 [obdclass]
      <4> [<ffffffffa0968d1b>] cl_sync_file_range+0x31b/0x500 [lustre]
      <4> [<ffffffffa0993e5b>] ll_writepages+0x8b/0x1c0 [lustre]
      <4> [<ffffffff8112e181>] do_writepages+0x21/0x40
      <4> [<ffffffff811aca6d>] writeback_single_inode+0xdd/0x290
      <4> [<ffffffff811ace7e>] writeback_sb_inodes+0xce/0x180
      <4> [<ffffffff811ad242>] wb_writeback+0x162/0x3f0
      <4> [<ffffffff8150e570>] ? thread_return+0x4e/0x76e
      <4> [<ffffffff81081be2>] ? del_timer_sync+0x22/0x30
      <4> [<ffffffff811ad58b>] wb_do_writeback+0xbb/0x240
      <4> [<ffffffff811ad773>] bdi_writeback_task+0x63/0x1b0
      <4> [<ffffffff81096c67>] ? bit_waitqueue+0x17/0xd0
      <4> [<ffffffff8113cc20>] ? bdi_start_fn+0x0/0x100
      <4> [<ffffffff8113cca6>] bdi_start_fn+0x86/0x100
      <4> [<ffffffff8113cc20>] ? bdi_start_fn+0x0/0x100
      <4> [<ffffffff81096a36>] kthread+0x96/0xa0
      <4> [<ffffffff8100c0ca>] child_rip+0xa/0x20
      <4> [<ffffffff810969a0>] ? kthread+0x0/0xa0
      <4> [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
      <4>Code: 48 89 df e8 85 e0 d5 e0 48 c7 c3 f4 ff ff ff e9 2a ff ff ff 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 53 48 83 ec 08 0f 1f 44 00 00 <48> 8b 07 0f 1f 80 00 00 00 00 48 89 c2 48 8b 40 70 48 85 c0 75
      <1>RIP  [<ffffffffa040b3de>] cl_object_top+0xe/0x150 [obdclass]
      <4> RSP <ffff88007c9319d0>
      <4>CR2: 0000000000000080
      

      Full trace from 2 above:

      <0>LustreError: 1752:0:(mdc_request.c:913:mdc_close()) ASSERTION( mod->mod_open_req != NULL && mod->mod_open_req->rq_type != LI_POISON ) failed: POISONED open (null)!
      <0>LustreError: 1752:0:(mdc_request.c:913:mdc_close()) LBUG
      <4>Pid: 1752, comm: rm
      <4>
      <4>Call Trace:
      <4> [<ffffffffa0297895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
      <4> [<ffffffffa0297e97>] lbug_with_loc+0x47/0xb0 [libcfs]
      <4> [<ffffffffa08a1ec5>] mdc_close+0x845/0xa50 [mdc]
      <4> [<ffffffffa099beb9>] ? ll_i2suppgid+0x19/0x30 [lustre]
      <4> [<ffffffffa059f626>] lmv_close+0x2c6/0x530 [lmv]
      <4> [<ffffffffa096da67>] ll_close_inode_openhandle+0x2f7/0x10b0 [lustre]
      <4> [<ffffffffa096e9cc>] ll_md_real_close+0x1ac/0x220 [lustre]
      <4> [<ffffffffa099e48d>] ll_md_blocking_ast+0x39d/0x7d0 [lustre]
      <4> [<ffffffffa03e0bed>] ? class_handle_unhash_nolock+0x2d/0x150 [obdclass]
      <4> [<ffffffffa03e111c>] ? class_handle_unhash+0x3c/0x50 [obdclass]
      <4> [<ffffffffa05ece9c>] ldlm_cancel_callback+0x6c/0x1a0 [ptlrpc]
      <4> [<ffffffffa0606b8a>] ldlm_cli_cancel_local+0x8a/0x470 [ptlrpc]
      <4> [<ffffffffa0609e8e>] ldlm_cli_cancel_list_local+0xee/0x290 [ptlrpc]
      <4> [<ffffffffa060a1c3>] ldlm_cancel_resource_local+0x193/0x290 [ptlrpc]
      <4> [<ffffffffa08a49ee>] mdc_resource_get_unused+0x14e/0x2c0 [mdc]
      <4> [<ffffffffa08a5e0d>] mdc_unlink+0x3ad/0x500 [mdc]
      <4> [<ffffffffa059c18b>] lmv_unlink+0x1db/0x7a0 [lmv]
      <4> [<ffffffffa0982858>] ? ll_prep_md_op_data+0x1a8/0x4a0 [lustre]
      <4> [<ffffffffa09a2678>] ll_unlink+0x158/0x610 [lustre]
      <4> [<ffffffff8118fe90>] vfs_unlink+0xa0/0xf0
      <4> [<ffffffff8118ebca>] ? lookup_hash+0x3a/0x50
      <4> [<ffffffff81192235>] do_unlinkat+0xf5/0x1b0
      <4> [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
      <4> [<ffffffff81192452>] sys_unlinkat+0x22/0x40
      <4> [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
      

      Full trace from 3 above:

      <4>general protection fault: 0000 [#1] SMP
      <4>last sysfs file: /sys/module/ptlrpc/initstate
      <4>CPU 1
      <4>Modules linked in: osc(U) lmv(U) mgc(U) nfs lockd fscache auth_rpcgss nfs_acl lustre(U) lov(U) mdc(U) fid(U) fld(U) ksocklnd(U) ptlrpc(U) obdclass(U) lnet(U) sha512_generic sha256_generic crc32c_intel libcfs(U) sunrpc ipv6 ppdev parport_pc parport e1000 vmware_balloon sg i2c_piix4 i2c_core shpchp ext4 jbd2 mbcache sd_mod crc_t10dif sr_mod cdrom mptspi mptscsih mptbase scsi_transport_spi pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
      <4>
      <4>Pid: 1858, comm: rm Not tainted 2.6.32.358.18.1.el6_lustre #4 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
      <4>RIP: 0010:[<ffffffff8128389f>]  [<ffffffff8128389f>] memcpy+0x9f/0x120
      <4>RSP: 0018:ffff88007ae4b4f0  EFLAGS: 00010202
      <4>RAX: db73880000000601 RBX: db73880000000601 RCX: 0000000000000011
      <4>RDX: 0000000000000011 RSI: ffffffffa08b274f RDI: db73880000000601
      <4>RBP: ffff88007ae4b588 R08: 6374616d20404040 R09: 6e65706f20646568
      <4>R10: 686374616d204040 R11: 206e65706f206465 R12: ffffffffa08b2760
      <4>R13: ffffffffa08b274f R14: ffff88007ae4b678 R15: db73880000001000
      <4>FS:  00007f2f14f58700(0000) GS:ffff880002280000(0000) knlGS:0000000000000000
      <4>CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
      <4>CR2: 00000000004073b0 CR3: 000000007bd98000 CR4: 00000000000007e0
      <4>DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
      <4>DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
      <4>Process rm (pid: 1858, threadinfo ffff88007ae4a000, task ffff88007b377500)
      <4>Stack:
      <4> ffffffff81281826 00000000ffffffff ffff88007ae4b558 ffffffffa08b7080
      <4><d> 0000000000000000 0000000000000011 00000601810a15fa 00000000000009ff
      <4><d> db73880000000601 0000000000000000 0000000000000000 0000000000000000
      <4>Call Trace:
      <4> [<ffffffff81281826>] ? vsnprintf+0x336/0x5e0
      <4> [<ffffffffa029727b>] ? cfs_set_ptldebug_header+0x2b/0xc0 [libcfs]
      <4> [<ffffffffa02a717a>] libcfs_debug_vmsg2+0x2ea/0xbb0 [libcfs]
      <4> [<ffffffff81281708>] ? vsnprintf+0x218/0x5e0
      <4> [<ffffffffa02a37e5>] ? libcfs_nid2str+0x155/0x160 [libcfs]
      <4> [<ffffffffa0639034>] _debug_req+0x454/0x680 [ptlrpc]
      <4> [<ffffffffa08a1c89>] mdc_close+0x609/0xa50 [mdc]
      <4> [<ffffffffa099beb9>] ? ll_i2suppgid+0x19/0x30 [lustre]
      <4> [<ffffffffa059f626>] lmv_close+0x2c6/0x530 [lmv]
      <4> [<ffffffffa096da67>] ll_close_inode_openhandle+0x2f7/0x10b0 [lustre]
      <4> [<ffffffffa096e9cc>] ll_md_real_close+0x1ac/0x220 [lustre]
      <4> [<ffffffffa099e48d>] ll_md_blocking_ast+0x39d/0x7d0 [lustre]
      <4> [<ffffffffa03e0bed>] ? class_handle_unhash_nolock+0x2d/0x150 [obdclass]
      <4> [<ffffffffa03e111c>] ? class_handle_unhash+0x3c/0x50 [obdclass]
      <4> [<ffffffffa05ece9c>] ldlm_cancel_callback+0x6c/0x1a0 [ptlrpc]
      <4> [<ffffffffa0606b8a>] ldlm_cli_cancel_local+0x8a/0x470 [ptlrpc]
      <4> [<ffffffffa0609e8e>] ldlm_cli_cancel_list_local+0xee/0x290 [ptlrpc]
      <4> [<ffffffffa060a1c3>] ldlm_cancel_resource_local+0x193/0x290 [ptlrpc]
      <4> [<ffffffffa08a49ee>] mdc_resource_get_unused+0x14e/0x2c0 [mdc]
      <4> [<ffffffffa08a5e0d>] mdc_unlink+0x3ad/0x500 [mdc]
      <4> [<ffffffffa059c18b>] lmv_unlink+0x1db/0x7a0 [lmv]
      <4> [<ffffffffa0982858>] ? ll_prep_md_op_data+0x1a8/0x4a0 [lustre]
      <4> [<ffffffffa09a2678>] ll_unlink+0x158/0x610 [lustre]
      <4> [<ffffffff8118fe90>] vfs_unlink+0xa0/0xf0
      <4> [<ffffffff8118ebca>] ? lookup_hash+0x3a/0x50
      <4> [<ffffffff81192235>] do_unlinkat+0xf5/0x1b0
      <4> [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
      <4> [<ffffffff81192452>] sys_unlinkat+0x22/0x40
      <4> [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
      

      Attachments

        Activity

          [LU-4619] Client GPF, null pointer & LBUG using FIEMAP

          Ah, thank you - With that flag set, the test case works.

          paf Patrick Farrell (Inactive) added a comment - Ah, thank you - With that flag set, the test case works.
          bobijam Zhenyu Xu added a comment -

          The application need to set FIEMAP_FLAG_DEVICE_ORDER flag when calls fiemap upon striped files,

          #define FIEMAP_FLAG_DEVICE_ORDER 0x40000000 /* return device ordered mapping */
          

          by setting this flag it indicates that the application understand the extent returns has a little different meaning from a normal extent.

          normal fiemap_extent structure
          struct fiemap_extent {
                  __u64 fe_logical;  /* logical offset in bytes for the start of
                                      * the extent from the beginning of the file */
                  __u64 fe_physical; /* physical offset in bytes for the start
                                      * of the extent from the beginning of the disk */
                  __u64 fe_length;   /* length in bytes for this extent */
                  __u64 fe_reserved64[2];
                  __u32 fe_flags;    /* FIEMAP_EXTENT_* flags for this extent */
                  __u32 fe_reserved[3];
          };
          
          Lustre fiemap_extent structure
          struct ll_fiemap_extent {
                  __u64 fe_logical;  /* logical offset in bytes for the start of
                                      * the extent from the beginning of the file */
                  __u64 fe_physical; /* physical offset in bytes for the start
                                      * of the extent from the beginning of the disk */
                  __u64 fe_length;   /* length in bytes for this extent */
                  __u64 fe_reserved64[2];
                  __u32 fe_flags;    /* FIEMAP_EXTENT_* flags for this extent */
                  __u32 fe_device;   /* device number for this extent */
                  __u32 fe_reserved[2];
          };
          

          The fe_device member is actually the normal fe_reserved[0] member, and it is the OST index the extent resides, and its fe_logical/fe_physical is measured upon this OST device.

          bobijam Zhenyu Xu added a comment - The application need to set FIEMAP_FLAG_DEVICE_ORDER flag when calls fiemap upon striped files, #define FIEMAP_FLAG_DEVICE_ORDER 0x40000000 /* return device ordered mapping */ by setting this flag it indicates that the application understand the extent returns has a little different meaning from a normal extent. normal fiemap_extent structure struct fiemap_extent { __u64 fe_logical; /* logical offset in bytes for the start of * the extent from the beginning of the file */ __u64 fe_physical; /* physical offset in bytes for the start * of the extent from the beginning of the disk */ __u64 fe_length; /* length in bytes for this extent */ __u64 fe_reserved64[2]; __u32 fe_flags; /* FIEMAP_EXTENT_* flags for this extent */ __u32 fe_reserved[3]; }; Lustre fiemap_extent structure struct ll_fiemap_extent { __u64 fe_logical; /* logical offset in bytes for the start of * the extent from the beginning of the file */ __u64 fe_physical; /* physical offset in bytes for the start * of the extent from the beginning of the disk */ __u64 fe_length; /* length in bytes for this extent */ __u64 fe_reserved64[2]; __u32 fe_flags; /* FIEMAP_EXTENT_* flags for this extent */ __u32 fe_device; /* device number for this extent */ __u32 fe_reserved[2]; }; The fe_device member is actually the normal fe_reserved [0] member, and it is the OST index the extent resides, and its fe_logical/fe_physical is measured upon this OST device.

          Yes, this does appear to fix the issue with out of bound writes...

          A question for you. When I run my test case [attached to the ticket] on a directory with striping set (I tried stripe counts of 2, and of -1, which is 16 on my system) I get -ENOTSUP:

          "before ioctl(FS_IOC_FIEMAP=0xc020660b)
          fiemap ioctl() failed Operation not supported fm_flags=0x0"

          Is this expected? I thought fiemap was supported for striped files.

          These are my e2fsprogs versions, in case that's relevant:
          e2fsprogs-libs-1.42.7.wc2-7.el6.x86_64
          e2fsprogs-devel-1.42.7.wc2-7.el6.x86_64
          e2fsprogs-1.42.7.wc2-7.el6.x86_64

          That seems to be the latest released versions.

          paf Patrick Farrell (Inactive) added a comment - Yes, this does appear to fix the issue with out of bound writes... A question for you. When I run my test case [attached to the ticket] on a directory with striping set (I tried stripe counts of 2, and of -1, which is 16 on my system) I get -ENOTSUP: "before ioctl(FS_IOC_FIEMAP=0xc020660b) fiemap ioctl() failed Operation not supported fm_flags=0x0" Is this expected? I thought fiemap was supported for striped files. These are my e2fsprogs versions, in case that's relevant: e2fsprogs-libs-1.42.7.wc2-7.el6.x86_64 e2fsprogs-devel-1.42.7.wc2-7.el6.x86_64 e2fsprogs-1.42.7.wc2-7.el6.x86_64 That seems to be the latest released versions.
          bobijam Zhenyu Xu added a comment -

          revised the patch that I think solves the memory out of bound write issue.

          bobijam Zhenyu Xu added a comment - revised the patch that I think solves the memory out of bound write issue.
          bobijam Zhenyu Xu added a comment -

          fiemap path must have some bugs there, I can reproduce it with random memory corruption even with #9834 patch version.

          test result matrix

          fiemap on pwrite.dat on result
          Lustre Ext3 passed
          Ext3 Lustre Random memory corruption
          bobijam Zhenyu Xu added a comment - fiemap path must have some bugs there, I can reproduce it with random memory corruption even with #9834 patch version. test result matrix fiemap on pwrite.dat on result Lustre Ext3 passed Ext3 Lustre Random memory corruption
          bobijam Zhenyu Xu added a comment -

          fiemap path must have some bugs there, I can reproduce it with random memory corruption even with #9834 patch version.

          bobijam Zhenyu Xu added a comment - fiemap path must have some bugs there, I can reproduce it with random memory corruption even with #9834 patch version.
          bobijam Zhenyu Xu added a comment -

          http://review.whamcloud.com/9834

          lov_fiemap() does not take consider its @vallen parameter, which is the max buffer size the caller can hold for the fiemap extents. This patch fixes this and limits the max mapped fiemap extent count to fit in the preallocted buffer.

          bobijam Zhenyu Xu added a comment - http://review.whamcloud.com/9834 lov_fiemap() does not take consider its @vallen parameter, which is the max buffer size the caller can hold for the fiemap extents. This patch fixes this and limits the max mapped fiemap extent count to fit in the preallocted buffer.
          pjones Peter Jones added a comment -

          Bobijam

          Could you please look into this one?

          Thanks

          Peter

          pjones Peter Jones added a comment - Bobijam Could you please look into this one? Thanks Peter
          green Oleg Drokin added a comment -

          I gave your test a try. Apparently there are several problems at hand that only happen when the file is big enough (and our testing only tests small files).

          So problem #1: we overrun the allocated buffer for fiemap:

          <3>[  151.755242] slab error in verify_redzone_free(): cache `size-32': memory outside object was overwritten
          <4>[  151.757314] Pid: 3567, comm: fiemap Not tainted 2.6.32-rhe6.4-debug2 #1
          <4>[  151.758493] Call Trace:
          <4>[  151.759116]  [<ffffffff811658f9>] ? __slab_error+0x29/0x30
          <4>[  151.759116]  [<ffffffff811669a8>] ? cache_free_debugcheck+0x338/0x360
          <4>[  151.759116]  [<ffffffff81169975>] ? kfree+0xd5/0x2b0
          <4>[  151.759116]  [<ffffffffa0ee5535>] ? ll_fiemap+0x3a5/0x570 [lustre]
          <4>[  151.759116]  [<ffffffff811963e6>] ? do_vfs_ioctl+0x566/0x5e0
          <4>[  151.759116]  [<ffffffff81181922>] ? vfs_write+0x132/0x1a0
          <4>[  151.759116]  [<ffffffff811964e1>] ? sys_ioctl+0x81/0xa0
          <4>[  151.759116]  [<ffffffff8100b0b2>] ? system_call_fastpath+0x16/0x1b
          <3>[  151.759116] ffff88007b609338: redzone 1:0xd84156c5635688c0, redzone 2:0x0.
          

          Problem #2: We somehow attach already freeed buffer to a request:

          <4>[  151.795222] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
          <4>[  151.797383] last sysfs file: /sys/devices/system/cpu/possible
          <4>[  151.797818] CPU 5 
          <4>[  151.797818] Modules linked in: lustre ofd osp lod ost mdt mdd mgs nodemap osd_ldiskfs ldiskfs exportfs lquota lfsck jbd obdecho mgc lov osc mdc lmv fid fld ptlrpc obdclass ksocklnd lnet sha512_generic sha256_generic libcfs ext4 jbd2 mbcache virtio_balloon virtio_console i2c_piix4 i2c_core virtio_blk virtio_net virtio_pci virtio_ring virtio pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod nfs lockd fscache auth_rpcgss nfs_acl sunrpc be2iscsi bnx2i cnic uio ipv6 cxgb3i libcxgbi cxgb3 mdio libiscsi_tcp qla4xxx iscsi_boot_sysfs libiscsi scsi_transport_iscsi [last unloaded: speedstep_lib]
          <4>[  151.797818] 
          <4>[  151.797818] Pid: 3569, comm: fiemap Not tainted 2.6.32-rhe6.4-debug2 #1 Red Hat KVM
          <4>[  151.797818] RIP: 0010:[<ffffffff81281888>]  [<ffffffff81281888>] memcpy+0x68/0x120
          <4>[  151.797818] RSP: 0018:ffff88007c041740  EFLAGS: 00010283
          <4>[  151.797818] RAX: db7388000000004d RBX: db7388000000004d RCX: 0000000000000029
          <4>[  151.797818] RDX: ffffffffffffffe9 RSI: ffffffffa08688f9 RDI: db73880000000076
          <4>[  151.797818] RBP: ffff88007c0417d8 R08: 2063706f3a64696e R09: 3a6469783a646970
          <4>[  151.797818] R10: 3a646975756c633a R11: 656d616e70204350 R12: ffffffffa0868919
          <4>[  151.797818] R13: ffffffffa08688f0 R14: ffff88007c0418c8 R15: db73880000001000
          <4>[  151.797818] FS:  00007f27a5f28700(0000) GS:ffff880006340000(0000) knlGS:0000000000000000
          <4>[  151.797818] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
          <4>[  151.797818] CR2: 00007f27a5acfb40 CR3: 000000007c1b4000 CR4: 00000000000006e0
          <4>[  151.797818] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
          <4>[  151.797818] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
          <4>[  151.797818] Process fiemap (pid: 3569, threadinfo ffff88007c040000, task ffff8800b404a4c0)
          <4>[  151.797818] Stack:
          <4>[  151.797818]  ffffffff8127f846 ffff88007c041858 ffff88007c0417a8 ffffffffa08c2480
          <4>[  151.797818] <d> 0000000000000000 0000000000000029 0000004d8109fbfa 0000000000000fb3
          <4>[  151.797818] <d> db7388000000004d 0000000000000000 0000000000000000 0000000000000000
          <4>[  151.797818] Call Trace:
          <4>[  151.797818]  [<ffffffff8127f846>] ? vsnprintf+0x336/0x5e0
          <4>[  151.797818]  [<ffffffffa040627b>] ? cfs_set_ptldebug_header+0x2b/0xc0 [libcfs]
          <4>[  151.797818]  [<ffffffffa04161ae>] libcfs_debug_vmsg2+0x2de/0xbb0 [libcfs]
          <4>[  151.797818]  [<ffffffff8127fb94>] ? snprintf+0x34/0x40
          <4>[  151.797818]  [<ffffffffa0416ac1>] libcfs_debug_msg+0x41/0x50 [libcfs]
          <4>[  151.797818]  [<ffffffffa07cad9a>] ptlrpc_send_new_req+0x44a/0x7c0 [ptlrpc]
          <4>[  151.797818]  [<ffffffffa07d060e>] ptlrpc_set_wait+0x5ce/0x830 [ptlrpc]
          <4>[  151.797818]  [<ffffffffa056ae5c>] ? lustre_get_jobid+0xcc/0x380 [obdclass]
          <4>[  151.797818]  [<ffffffffa07da536>] ? lustre_msg_set_jobid+0xb6/0x140 [ptlrpc]
          <4>[  151.797818]  [<ffffffffa07d08f7>] ptlrpc_queue_wait+0x87/0x220 [ptlrpc]
          <4>[  151.797818]  [<ffffffffa0a85797>] osc_get_info+0x2a7/0x970 [osc]
          <4>[  151.797818]  [<ffffffffa0b1a034>] ? lov_get_info+0x954/0x1bc0 [lov]
          <4>[  151.797818]  [<ffffffffa0b26286>] ? lov_stripe_intersects+0x56/0x130 [lov]
          <4>[  151.797818]  [<ffffffffa0b26086>] ? lov_size_to_stripe+0x106/0x150 [lov]
          <4>[  151.797818]  [<ffffffffa0b1a5e7>] lov_get_info+0xf07/0x1bc0 [lov]
          <4>[  151.797818]  [<ffffffff811192a9>] ? filemap_fault+0xe9/0x530
          <4>[  151.797818]  [<ffffffff814fd6d9>] ? down_read+0x29/0x40
          <4>[  151.797818]  [<ffffffffa0eda27a>] ll_do_fiemap+0x40a/0x680 [lustre]
          <4>[  151.797818]  [<ffffffffa0ee52a7>] ll_fiemap+0x117/0x570 [lustre]
          <4>[  151.797818]  [<ffffffff811963e6>] do_vfs_ioctl+0x566/0x5e0
          <4>[  151.797818]  [<ffffffff81181922>] ? vfs_write+0x132/0x1a0
          <4>[  151.797818]  [<ffffffff811964e1>] sys_ioctl+0x81/0xa0
          <4>[  151.797818]  [<ffffffff8100b0b2>] system_call_fastpath+0x16/0x1b
          <4>[  151.797818] Code: 20 73 d4 48 83 c2 20 eb 42 48 01 d6 48 01 d7 48 83 ea 20 48 83 ea 20 4c 8b 46 f8 4c 8b 4e f0 4c 8b 56 e8 4c 8b 5e e0 48 8d 76 e0 <4c> 89 47 f8 4c 89 4f f0 4c 89 57 e8 4c 89 5f e0 48 8d 7f e0 73 
          <1>[  151.797818] RIP  [<ffffffff81281888>] memcpy+0x68/0x120
          <4>[  151.797818]  RSP <ffff88007c041740>
          
          green Oleg Drokin added a comment - I gave your test a try. Apparently there are several problems at hand that only happen when the file is big enough (and our testing only tests small files). So problem #1: we overrun the allocated buffer for fiemap: <3>[ 151.755242] slab error in verify_redzone_free(): cache `size-32': memory outside object was overwritten <4>[ 151.757314] Pid: 3567, comm: fiemap Not tainted 2.6.32-rhe6.4-debug2 #1 <4>[ 151.758493] Call Trace: <4>[ 151.759116] [<ffffffff811658f9>] ? __slab_error+0x29/0x30 <4>[ 151.759116] [<ffffffff811669a8>] ? cache_free_debugcheck+0x338/0x360 <4>[ 151.759116] [<ffffffff81169975>] ? kfree+0xd5/0x2b0 <4>[ 151.759116] [<ffffffffa0ee5535>] ? ll_fiemap+0x3a5/0x570 [lustre] <4>[ 151.759116] [<ffffffff811963e6>] ? do_vfs_ioctl+0x566/0x5e0 <4>[ 151.759116] [<ffffffff81181922>] ? vfs_write+0x132/0x1a0 <4>[ 151.759116] [<ffffffff811964e1>] ? sys_ioctl+0x81/0xa0 <4>[ 151.759116] [<ffffffff8100b0b2>] ? system_call_fastpath+0x16/0x1b <3>[ 151.759116] ffff88007b609338: redzone 1:0xd84156c5635688c0, redzone 2:0x0. Problem #2: We somehow attach already freeed buffer to a request: <4>[ 151.795222] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC <4>[ 151.797383] last sysfs file: /sys/devices/system/cpu/possible <4>[ 151.797818] CPU 5 <4>[ 151.797818] Modules linked in: lustre ofd osp lod ost mdt mdd mgs nodemap osd_ldiskfs ldiskfs exportfs lquota lfsck jbd obdecho mgc lov osc mdc lmv fid fld ptlrpc obdclass ksocklnd lnet sha512_generic sha256_generic libcfs ext4 jbd2 mbcache virtio_balloon virtio_console i2c_piix4 i2c_core virtio_blk virtio_net virtio_pci virtio_ring virtio pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod nfs lockd fscache auth_rpcgss nfs_acl sunrpc be2iscsi bnx2i cnic uio ipv6 cxgb3i libcxgbi cxgb3 mdio libiscsi_tcp qla4xxx iscsi_boot_sysfs libiscsi scsi_transport_iscsi [last unloaded: speedstep_lib] <4>[ 151.797818] <4>[ 151.797818] Pid: 3569, comm: fiemap Not tainted 2.6.32-rhe6.4-debug2 #1 Red Hat KVM <4>[ 151.797818] RIP: 0010:[<ffffffff81281888>] [<ffffffff81281888>] memcpy+0x68/0x120 <4>[ 151.797818] RSP: 0018:ffff88007c041740 EFLAGS: 00010283 <4>[ 151.797818] RAX: db7388000000004d RBX: db7388000000004d RCX: 0000000000000029 <4>[ 151.797818] RDX: ffffffffffffffe9 RSI: ffffffffa08688f9 RDI: db73880000000076 <4>[ 151.797818] RBP: ffff88007c0417d8 R08: 2063706f3a64696e R09: 3a6469783a646970 <4>[ 151.797818] R10: 3a646975756c633a R11: 656d616e70204350 R12: ffffffffa0868919 <4>[ 151.797818] R13: ffffffffa08688f0 R14: ffff88007c0418c8 R15: db73880000001000 <4>[ 151.797818] FS: 00007f27a5f28700(0000) GS:ffff880006340000(0000) knlGS:0000000000000000 <4>[ 151.797818] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 151.797818] CR2: 00007f27a5acfb40 CR3: 000000007c1b4000 CR4: 00000000000006e0 <4>[ 151.797818] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 <4>[ 151.797818] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 <4>[ 151.797818] Process fiemap (pid: 3569, threadinfo ffff88007c040000, task ffff8800b404a4c0) <4>[ 151.797818] Stack: <4>[ 151.797818] ffffffff8127f846 ffff88007c041858 ffff88007c0417a8 ffffffffa08c2480 <4>[ 151.797818] <d> 0000000000000000 0000000000000029 0000004d8109fbfa 0000000000000fb3 <4>[ 151.797818] <d> db7388000000004d 0000000000000000 0000000000000000 0000000000000000 <4>[ 151.797818] Call Trace: <4>[ 151.797818] [<ffffffff8127f846>] ? vsnprintf+0x336/0x5e0 <4>[ 151.797818] [<ffffffffa040627b>] ? cfs_set_ptldebug_header+0x2b/0xc0 [libcfs] <4>[ 151.797818] [<ffffffffa04161ae>] libcfs_debug_vmsg2+0x2de/0xbb0 [libcfs] <4>[ 151.797818] [<ffffffff8127fb94>] ? snprintf+0x34/0x40 <4>[ 151.797818] [<ffffffffa0416ac1>] libcfs_debug_msg+0x41/0x50 [libcfs] <4>[ 151.797818] [<ffffffffa07cad9a>] ptlrpc_send_new_req+0x44a/0x7c0 [ptlrpc] <4>[ 151.797818] [<ffffffffa07d060e>] ptlrpc_set_wait+0x5ce/0x830 [ptlrpc] <4>[ 151.797818] [<ffffffffa056ae5c>] ? lustre_get_jobid+0xcc/0x380 [obdclass] <4>[ 151.797818] [<ffffffffa07da536>] ? lustre_msg_set_jobid+0xb6/0x140 [ptlrpc] <4>[ 151.797818] [<ffffffffa07d08f7>] ptlrpc_queue_wait+0x87/0x220 [ptlrpc] <4>[ 151.797818] [<ffffffffa0a85797>] osc_get_info+0x2a7/0x970 [osc] <4>[ 151.797818] [<ffffffffa0b1a034>] ? lov_get_info+0x954/0x1bc0 [lov] <4>[ 151.797818] [<ffffffffa0b26286>] ? lov_stripe_intersects+0x56/0x130 [lov] <4>[ 151.797818] [<ffffffffa0b26086>] ? lov_size_to_stripe+0x106/0x150 [lov] <4>[ 151.797818] [<ffffffffa0b1a5e7>] lov_get_info+0xf07/0x1bc0 [lov] <4>[ 151.797818] [<ffffffff811192a9>] ? filemap_fault+0xe9/0x530 <4>[ 151.797818] [<ffffffff814fd6d9>] ? down_read+0x29/0x40 <4>[ 151.797818] [<ffffffffa0eda27a>] ll_do_fiemap+0x40a/0x680 [lustre] <4>[ 151.797818] [<ffffffffa0ee52a7>] ll_fiemap+0x117/0x570 [lustre] <4>[ 151.797818] [<ffffffff811963e6>] do_vfs_ioctl+0x566/0x5e0 <4>[ 151.797818] [<ffffffff81181922>] ? vfs_write+0x132/0x1a0 <4>[ 151.797818] [<ffffffff811964e1>] sys_ioctl+0x81/0xa0 <4>[ 151.797818] [<ffffffff8100b0b2>] system_call_fastpath+0x16/0x1b <4>[ 151.797818] Code: 20 73 d4 48 83 c2 20 eb 42 48 01 d6 48 01 d7 48 83 ea 20 48 83 ea 20 4c 8b 46 f8 4c 8b 4e f0 4c 8b 56 e8 4c 8b 5e e0 48 8d 76 e0 <4c> 89 47 f8 4c 89 4f f0 4c 89 57 e8 4c 89 5f e0 48 8d 7f e0 73 <1>[ 151.797818] RIP [<ffffffff81281888>] memcpy+0x68/0x120 <4>[ 151.797818] RSP <ffff88007c041740>

          We've also replicated these issues on Cray 2.4.0, 2.4.1, and 2.5. I have not tested any Intel versions other than master, but I would think the bug is present in some of those versions as well.

          One further note - The debug message for 2 above is corrupted.

          Here's a clean one, from a different occurrence (this was on a 2.4 derivative, so the line # is different):

          > 10:58:37 LustreError: 11076:0:(mdc_request.c:854:mdc_close()) ASSERTION( mod->mod_open_req != NULL && mod->mod_open_req->rq_type != LI_POISON ) failed: POISONED open (null)!
          > 10:58:37 LustreError: 11076:0:(mdc_request.c:854:mdc_close()) LBUG
          > 10:58:37 Pid: 11076, comm: fiemap
          > 10:58:37 Call Trace:
          > 10:58:37 [<ffffffff81005db9>] try_stack_unwind+0x169/0x1b0
          > 10:58:37 [<ffffffff81004849>] dump_trace+0x89/0x450
          > 10:58:37 [<ffffffffa02e28d7>] libcfs_debug_dumpstack+0x57/0x80 [libcfs]
          > 10:58:37 [<ffffffffa02e2e37>] lbug_with_loc+0x47/0xc0 [libcfs]
          > 10:58:37 [<ffffffffa07c1b77>] mdc_close+0x727/0x970 [mdc]
          > 10:58:37 [<ffffffffa0a34520>] lmv_close+0x280/0x5e0 [lmv]
          > 10:58:37 [<ffffffffa091dd35>] ll_close_inode_openhandle+0x305/0x1080 [lustre]
          > 10:58:37 [<ffffffffa091eb5e>] ll_md_real_close+0xae/0x210 [lustre]
          > 10:58:37 [<ffffffffa091eed9>] ll_md_close+0x219/0x6a0 [lustre]
          > 10:58:37 [<ffffffffa091f467>] ll_file_release+0x107/0x3d0 [lustre]
          > 10:58:37 [<ffffffff8113bad2>] fput+0xe2/0x200
          > 10:58:37 [<ffffffff81137ca3>] filp_close+0x63/0x90
          > 10:58:37 [<ffffffff81137d82>] sys_close+0xb2/0x100
          > 10:58:38 [<ffffffff814d02ab>] system_call_fastpath+0x16/0x1b
          > 10:58:38 [<0000000000430da0>] 0x430da0
          > 10:58:38 Kernel panic - not syncing: LBUG

          paf Patrick Farrell (Inactive) added a comment - We've also replicated these issues on Cray 2.4.0, 2.4.1, and 2.5. I have not tested any Intel versions other than master, but I would think the bug is present in some of those versions as well. One further note - The debug message for 2 above is corrupted. Here's a clean one, from a different occurrence (this was on a 2.4 derivative, so the line # is different): > 10:58:37 LustreError: 11076:0:(mdc_request.c:854:mdc_close()) ASSERTION( mod->mod_open_req != NULL && mod->mod_open_req->rq_type != LI_POISON ) failed: POISONED open (null)! > 10:58:37 LustreError: 11076:0:(mdc_request.c:854:mdc_close()) LBUG > 10:58:37 Pid: 11076, comm: fiemap > 10:58:37 Call Trace: > 10:58:37 [<ffffffff81005db9>] try_stack_unwind+0x169/0x1b0 > 10:58:37 [<ffffffff81004849>] dump_trace+0x89/0x450 > 10:58:37 [<ffffffffa02e28d7>] libcfs_debug_dumpstack+0x57/0x80 [libcfs] > 10:58:37 [<ffffffffa02e2e37>] lbug_with_loc+0x47/0xc0 [libcfs] > 10:58:37 [<ffffffffa07c1b77>] mdc_close+0x727/0x970 [mdc] > 10:58:37 [<ffffffffa0a34520>] lmv_close+0x280/0x5e0 [lmv] > 10:58:37 [<ffffffffa091dd35>] ll_close_inode_openhandle+0x305/0x1080 [lustre] > 10:58:37 [<ffffffffa091eb5e>] ll_md_real_close+0xae/0x210 [lustre] > 10:58:37 [<ffffffffa091eed9>] ll_md_close+0x219/0x6a0 [lustre] > 10:58:37 [<ffffffffa091f467>] ll_file_release+0x107/0x3d0 [lustre] > 10:58:37 [<ffffffff8113bad2>] fput+0xe2/0x200 > 10:58:37 [<ffffffff81137ca3>] filp_close+0x63/0x90 > 10:58:37 [<ffffffff81137d82>] sys_close+0xb2/0x100 > 10:58:38 [<ffffffff814d02ab>] system_call_fastpath+0x16/0x1b > 10:58:38 [<0000000000430da0>] 0x430da0 > 10:58:38 Kernel panic - not syncing: LBUG

          Uploading dump of cl_lock_top null pointer dereference with -1 debug to ftp.whamcloud.com uploads/LU-4619/LU-4619-140212_again.tar.gz

          Note there is also a file LU-4619-140212.tar.gz. This transfer failed and the file is incomplete.

          paf Patrick Farrell (Inactive) added a comment - Uploading dump of cl_lock_top null pointer dereference with -1 debug to ftp.whamcloud.com uploads/ LU-4619 / LU-4619 -140212_again.tar.gz Note there is also a file LU-4619 -140212.tar.gz. This transfer failed and the file is incomplete.

          People

            bobijam Zhenyu Xu
            paf Patrick Farrell (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: