Skip to content
This repository has been archived by the owner on May 3, 2024. It is now read-only.

"mero" string is visible in test name and results. #15

Closed
imvenkip opened this issue Sep 6, 2020 · 3 comments
Closed

"mero" string is visible in test name and results. #15

imvenkip opened this issue Sep 6, 2020 · 3 comments

Comments

@imvenkip
Copy link
Contributor

imvenkip commented Sep 6, 2020

mero-single-node.28motr-sys-kvs-test.test (from xperior)

http://eos-jenkins.colo.seagate.com/job/Release_Engineering/job/github-work/job/GitHub%20Multibranch%20Jobs/job/motr-multibranch/job/PR-318/5/testReport/junit/mero-single-node/28motr-sys-kvs-test/test/

temp-1
temp-2
@stale
Copy link

stale bot commented Sep 10, 2020

This issue/pull request has been marked as needs attention as it has been left pending without new activity for 4 days. Tagging @huanghua78 @mukundkanekar for appropriate assignment. Sorry for the delay & Thank you for contributing to CORTX. We will get back to you as soon as possible.

1 similar comment
@stale
Copy link

stale bot commented Sep 14, 2020

This issue/pull request has been marked as needs attention as it has been left pending without new activity for 4 days. Tagging @huanghua78 @mukundkanekar for appropriate assignment. Sorry for the delay & Thank you for contributing to CORTX. We will get back to you as soon as possible.

@gauravchaudhari02 gauravchaudhari02 transferred this issue from another repository Sep 22, 2020
@madhavemuri
Copy link
Contributor

This issue is fixed, Thanks to @bansisoni and @gowthamchinna .

madhavemuri added a commit that referenced this issue Sep 22, 2020
@madhavemuri
EOS-8618 conf/rconfc: fix issues in multi confd restart
6c8865e 
Following crash occured occured in multi confd configuration
during restart/failure of a confd m0d, when initialisation is
in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalisation issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised"
flag.

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
@madhavemuri madhavemuri mentioned this issue Sep 22, 2020
Closed
madhavemuri added a commit that referenced this issue Oct 3, 2020
@madhavemuri
EOS-8618 conf/rconfc: fix issues in multi confd restart
1f7b6ad 
Following crash occured occured in multi confd configuration
during restart/failure of a confd m0d, when initialisation is
in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalisation issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised"
flag.

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
@madhavemuri madhavemuri mentioned this issue Oct 3, 2020
Merged
madhavemuri added a commit that referenced this issue Oct 5, 2020
@madhavemuri
EOS-13878 scripts: use MOTR_M0D_IOS_BESEG_SIZE for ioservice
615fc54 
Currently be seg size MOTR_M0D_IOS_BESEG_SIZE from /etc/sysconfig/motr
not being used and default value of 8GB is used due to a bug in
motr-server script, which checks for "^ios" regex in systemd unit file,
which is no longer used with hare based cluster.
The following crash is observed,

 #3  0x00007fca296780b4 in m0_panic (ctx=ctx@entry=0x7fca29a72020 <__pctx.8247>) at lib/assert.c:52
 #4  0x00007fca295bdf20 in mem_alloc (zonemask=2, size=<optimized out>, tx=0x7fc84c2266b8, btree=0x40000015f210) at be/btree.c:127
 #5  btree_save (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8, op=op@entry=0x7fc92bffe460,
    key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0, anchor=anchor@entry=0x0, optype=optype@entry=BTREE_SAVE_INSERT,
    zonemask=zonemask@entry=2) at be/btree.c:1453
 #6  0x00007fca295bdfe8 in be_btree_insert (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8,
    op=op@entry=0x7fc92bffe460, key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0, anchor=anchor@entry=0x0,
    zonemask=zonemask@entry=2) at be/btree.c:1907
 #7  0x00007fca295bf018 in m0_be_btree_insert (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8,
    op=op@entry=0x7fc92bffe460, key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0) at be/btree.c:1938
 #8  0x00007fca295f7931 in cob_table_insert (tree=0x40000015f210, tx=tx@entry=0x7fc84c2266b8, key=key@entry=0x7fc92bffe6d0,
    val=val@entry=0x7fc92bffe6e0) at cob/cob.c:721
 #9  0x00007fca295fa5cf in m0_cob_name_add (cob=cob@entry=0x7fc9241ffc50, nskey=nskey@entry=0x7fc9241ffdc0,
    nsrec=nsrec@entry=0x7fc92bffe8e0, tx=tx@entry=0x7fc84c2266b8) at cob/cob.c:1640
 #10 0x00007fca295fa85a in m0_cob_create (cob=0x7fc9241ffc50, nskey=0x7fc9241ffdc0, nsrec=nsrec@entry=0x7fc92bffe8e0,
    fabrec=fabrec@entry=0x0, omgrec=omgrec@entry=0x0, tx=tx@entry=0x7fc84c2266b8) at cob/cob.c:1428
 #11 0x00007fca2966b097 in m0_cc_cob_setup (cc=cc@entry=0x7fc84c2265d0, cdom=<optimized out>, attr=attr@entry=0x7fc92bffec20,
    ctx=ctx@entry=0x7fc84c2266b8) at ioservice/cob_foms.c:1058
 #12 0x00007fca2966b275 in cc_cob_create (attr=0x7fc92bffec20, cc=0x7fc84c2265d0, fom=0x7fc84c2265f0) at ioservice/cob_foms.c:1016
 #13 cob_stob_create (fom=fom@entry=0x7fc84c2265f0, attr=attr@entry=0x7fc92bffec20) at ioservice/cob_foms.c:517
 #14 0x00007fca2966c40b in cob_ops_fom_tick (fom=0x7fc84c2265f0) at ioservice/cob_foms.c:767
 #15 0x00007fca2964c24b in fom_exec (fom=0x7fc84c2265f0) at fop/fom.c:785
 #16 loc_handler_thread (th=0x1b5c1e0) at fop/fom.c:925
 #17 0x00007fca2967e50e in m0_thread_trampoline (arg=arg@entry=0x1b5c1e8) at lib/thread.c:117
 #18 0x00007fca2968875d in uthread_trampoline (arg=0x1b5c1e8) at lib/user_space/uthread.c:98
 #19 0x00007fca28e36ea5 in start_thread () from /lib64/libpthread.so.0
 #20 0x00007fca27f278cd in clone () from /lib64/libc.so.6

So for LDR R1, as LVM paths are passed only for ioservices, at the
same place be seg size is applied.

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
@madhavemuri madhavemuri mentioned this issue Oct 5, 2020
Merged
madhavemuri added a commit that referenced this issue Oct 5, 2020
@madhavemuri
EOS-13878 scripts: use MOTR_M0D_IOS_BESEG_SIZE for ioservice (#88)
0bef5c7 
Currently be seg size MOTR_M0D_IOS_BESEG_SIZE from /etc/sysconfig/motr
not being used and default value of 8GB is used due to a bug in
motr-server script, which checks for "^ios" regex in systemd unit file,
which is no longer used with hare based cluster.
The following crash is observed,

 #3  0x00007fca296780b4 in m0_panic (ctx=ctx@entry=0x7fca29a72020 <__pctx.8247>) at lib/assert.c:52
 #4  0x00007fca295bdf20 in mem_alloc (zonemask=2, size=<optimized out>, tx=0x7fc84c2266b8, btree=0x40000015f210) at be/btree.c:127
 #5  btree_save (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8, op=op@entry=0x7fc92bffe460,
    key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0, anchor=anchor@entry=0x0, optype=optype@entry=BTREE_SAVE_INSERT,
    zonemask=zonemask@entry=2) at be/btree.c:1453
 #6  0x00007fca295bdfe8 in be_btree_insert (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8,
    op=op@entry=0x7fc92bffe460, key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0, anchor=anchor@entry=0x0,
    zonemask=zonemask@entry=2) at be/btree.c:1907
 #7  0x00007fca295bf018 in m0_be_btree_insert (tree=tree@entry=0x40000015f210, tx=tx@entry=0x7fc84c2266b8,
    op=op@entry=0x7fc92bffe460, key=key@entry=0x7fc92bffe6d0, val=val@entry=0x7fc92bffe6e0) at be/btree.c:1938
 #8  0x00007fca295f7931 in cob_table_insert (tree=0x40000015f210, tx=tx@entry=0x7fc84c2266b8, key=key@entry=0x7fc92bffe6d0,
    val=val@entry=0x7fc92bffe6e0) at cob/cob.c:721
 #9  0x00007fca295fa5cf in m0_cob_name_add (cob=cob@entry=0x7fc9241ffc50, nskey=nskey@entry=0x7fc9241ffdc0,
    nsrec=nsrec@entry=0x7fc92bffe8e0, tx=tx@entry=0x7fc84c2266b8) at cob/cob.c:1640
 #10 0x00007fca295fa85a in m0_cob_create (cob=0x7fc9241ffc50, nskey=0x7fc9241ffdc0, nsrec=nsrec@entry=0x7fc92bffe8e0,
    fabrec=fabrec@entry=0x0, omgrec=omgrec@entry=0x0, tx=tx@entry=0x7fc84c2266b8) at cob/cob.c:1428
 #11 0x00007fca2966b097 in m0_cc_cob_setup (cc=cc@entry=0x7fc84c2265d0, cdom=<optimized out>, attr=attr@entry=0x7fc92bffec20,
    ctx=ctx@entry=0x7fc84c2266b8) at ioservice/cob_foms.c:1058
 #12 0x00007fca2966b275 in cc_cob_create (attr=0x7fc92bffec20, cc=0x7fc84c2265d0, fom=0x7fc84c2265f0) at ioservice/cob_foms.c:1016
 #13 cob_stob_create (fom=fom@entry=0x7fc84c2265f0, attr=attr@entry=0x7fc92bffec20) at ioservice/cob_foms.c:517
 #14 0x00007fca2966c40b in cob_ops_fom_tick (fom=0x7fc84c2265f0) at ioservice/cob_foms.c:767
 #15 0x00007fca2964c24b in fom_exec (fom=0x7fc84c2265f0) at fop/fom.c:785
 #16 loc_handler_thread (th=0x1b5c1e0) at fop/fom.c:925
 #17 0x00007fca2967e50e in m0_thread_trampoline (arg=arg@entry=0x1b5c1e8) at lib/thread.c:117
 #18 0x00007fca2968875d in uthread_trampoline (arg=0x1b5c1e8) at lib/user_space/uthread.c:98
 #19 0x00007fca28e36ea5 in start_thread () from /lib64/libpthread.so.0
 #20 0x00007fca27f278cd in clone () from /lib64/libc.so.6

So for LDR R1, as LVM paths are passed only for ioservices, at the
same place be seg size is applied.

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
yeshpal-jain-seagate pushed a commit that referenced this issue Oct 7, 2020
@madhavemuri @yeshpal-jain-seagate
EOS-8618 conf/rconfc: fix issues in multi confd restart
e42e707 
Following crash occured occured in multi confd configuration
during restart/failure of a confd m0d, when initialisation is
in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalisation issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised"
flag.

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
madhavemuri added a commit that referenced this issue Oct 9, 2020
@madhavemuri
EOS 8618 : fix for rconfc herd link panic during m0d initialization (#80
c1d4cff 
)

Following crash occurred in multi confd configuration
during restart/failure of a confd m0d, when initialization is in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalization issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised" flag.
* Handle sm fini from wait for reply state
* use different AST for rconfc_cctx_fini()
* rmservice fid fetch can fail in case of confd quorum is not possible.
   To resolve this returning from initlift_resource_manager() when
   confc in not initialized.

Co-authored-by: Hua Huang <hua.huang@seagate.com>

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
madhavemuri added a commit that referenced this issue Oct 9, 2020
@madhavemuri
EOS 8618 : fix for rconfc herd link panic during m0d initialization (#80
5c9ba6e 
)

Following crash occurred in multi confd configuration
during restart/failure of a confd m0d, when initialization is in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalization issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised" flag.
* Handle sm fini from wait for reply state
* use different AST for rconfc_cctx_fini()
* rmservice fid fetch can fail in case of confd quorum is not possible.
   To resolve this returning from initlift_resource_manager() when
   confc in not initialized.

Co-authored-by: Hua Huang <hua.huang@seagate.com>

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
madhavemuri added a commit that referenced this issue Oct 9, 2020
@madhavemuri
EOS 8618 : fix for rconfc herd link panic during m0d initialization (#80
49102da 
)

Following crash occurred in multi confd configuration
during restart/failure of a confd m0d, when initialization is in progress,

 #6  0x00007f99f255ad24 in m0_panic (ctx=ctx@entry=0x7f99f29758c0 <__pctx.20770>) at lib/assert.c:50
 #7  0x00007f99f24e16a4 in m0_confc_fini (confc=confc@entry=0x7f981c008650) at conf/confc.c:562
 #8  0x00007f99f24f2918 in rconfc_herd_link_fini (lnk=lnk@entry=0x7f981c008650) at conf/rconfc.c:1387
 #9  0x00007f99f24f6797 in rconfc_link_fom_fini (fom=0x7f981c009688) at conf/rconfc_link_fom.c:100
 #10 0x00007f99f252f141 in fom_exec (fom=0x7f981c009688) at fop/fom.c:771
 #11 loc_handler_thread (th=0xc138d0) at fop/fom.c:887
 #12 0x00007f99f256117e in m0_thread_trampoline (arg=arg@entry=0xc138d8) at lib/thread.c:116
 #13 0x00007f99f256b436 in uthread_trampoline (arg=0xc138d8) at lib/user_space/uthread.c:93
 #14 0x00007f99f349bea5 in start_thread () from /lib64/libpthread.so.0
 #15 0x00007f99f07a78cd in clone () from /lib64/libc.so.6

To fix link finalization issue, fini is done through AST.
And link ast is posted at one time only by checking "rl_finalised" flag.
* Handle sm fini from wait for reply state
* use different AST for rconfc_cctx_fini()
* rmservice fid fetch can fail in case of confd quorum is not possible.
   To resolve this returning from initlift_resource_manager() when
   confc in not initialized.

Co-authored-by: Hua Huang <hua.huang@seagate.com>

Signed-off-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
@max-seagate max-seagate mentioned this issue Jul 7, 2021
Closed
max-seagate added a commit that referenced this issue Sep 29, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug
b6bd370 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
@max-seagate max-seagate mentioned this issue Sep 29, 2021
Merged
max-seagate added a commit that referenced this issue Sep 29, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug
22cd279 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [2] or just
spinning in infinite loop in m0_list invariant due to a broken list [3].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
max-seagate added a commit that referenced this issue Sep 30, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug
e878095 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Signed-off-by: Maksym Medvied <maksym.medvied@seagate.com>
max-seagate added a commit that referenced this issue Oct 4, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug
fcf4b8b 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Signed-off-by: Maksym Medvied <maksym.medvied@seagate.com>
mehjoshi pushed a commit that referenced this issue Oct 5, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug (#1090)
190d3b6 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Signed-off-by: Maksym Medvied <maksym.medvied@seagate.com>
andriytk pushed a commit to andriytk/cortx-motr that referenced this issue Oct 6, 2021
@max-seagate @andriytk
EOS-25109 be/io_sched: fix op done ordering bug (Seagate#1090)
cf1cd06 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  Seagate#1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  Seagate#2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  Seagate#3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  Seagate#4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  Seagate#5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  Seagate#6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  Seagate#7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  Seagate#8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  Seagate#9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  Seagate#10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  Seagate#11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  Seagate#12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  Seagate#13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  Seagate#14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  Seagate#15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  Seagate#16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  Seagate#17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  Seagate#18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  Seagate#19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  Seagate#20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  Seagate#1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  Seagate#2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  Seagate#3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  Seagate#4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  Seagate#5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  Seagate#6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  Seagate#7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  Seagate#8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  Seagate#9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Signed-off-by: Maksym Medvied <maksym.medvied@seagate.com>
mehjoshi pushed a commit that referenced this issue Oct 8, 2021
@max-seagate
EOS-25109 be/io_sched: fix op done ordering bug (#1090)
2116e0c 
It was possible for the op, passed to m0_be_io_sched_add(), to become
DONE before sched lock is taken in be_io_sched_cb() because parent op
could become DONE before the child op M0_BTS_GC callback is called.
This situation led to failed invariant, assertion failures [1] or just
spinning in infinite loop in m0_list invariant due to a broken list [2].

The patch fixes the issue by moving the op (passed to
m0_be_io_sched_add()) to DONE only after finishing processing of the
corresponding m0_be_io.

The bug was discovered during EOS-25005 patch testing.

[1]

be-ut
  io_sched  motr[15961]:  e4b0  FATAL  [lib/assert.c:50:m0_panic]  panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() (be/io_sched.c:132)  [git: 2.0.0-307-37-gd35074f6-dirty] /w/var/m0ut/m0trace.15961
Motr panic: (io->bio_ext.e_start == sched->bis_pos) at be_io_sched_cb() be/io_sched.c:132 (errno: 0) (last failed: none) [git: 2.0.0-307-37-gd35074f6-dirty] pid: 15961  /w/var/m0ut/m0trace.15961
...

[2]

  (gdb) bt
  #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  #1  0x00007f432af53e1b in _L_lock_812 () from /lib64/libpthread.so.0
  #2  0x00007f432af53ce8 in __GI___pthread_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at ../nptl/pthread_mutex_lock.c:79
  #3  0x00007f432b8c3520 in m0_arch_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/user_space/umutex.c:56
  #4  0x00007f432b8aee6f in m0_mutex_lock (mutex=0x7f432d714a80 <be_ut_io_sched_scheduler+32>) at lib/mutex.c:55
  #5  0x00007f432b76673b in m0_be_io_sched_lock (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>) at be/io_sched.c:72
  #6  0x00007f432b766a75 in be_io_sched_cb (op=0x7f4288000998, param=0x7f42880008c0) at be/io_sched.c:123
  #7  0x00007f432b771bb3 in be_op_done (op=0x7f4288000998) at be/op.c:257
  #8  0x00007f432b771cb6 in m0_be_op_done (op=0x7f4288000998) at be/op.c:276
  #9  0x00007f432b765715 in be_io_finished (bio=0x7f42880008c0) at be/io.c:555
  #10 0x00007f432b7658e1 in be_io_cb (link=0x7f4288001040) at be/io.c:587
  #11 0x00007f432b8a53a0 in clink_signal (clink=0x7f4288001040) at lib/chan.c:135
  #12 0x00007f432b8a54ff in chan_signal_nr (chan=0x7f4288000f38, nr=0) at lib/chan.c:154
  #13 0x00007f432b8a55d4 in m0_chan_broadcast (chan=0x7f4288000f38) at lib/chan.c:174
  #14 0x00007f432b8a55fa in m0_chan_broadcast_lock (chan=0x7f4288000f38) at lib/chan.c:181
  #15 0x00007f432ba03cfe in ioq_complete (ioq=0x1367bc0, qev=0x7f42886a3fe0, res=8, res2=0) at stob/ioq.c:587
  #16 0x00007f432ba041d1 in stob_ioq_thread (ioq=0x1367bc0) at stob/ioq.c:669
  #17 0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x1367be0) at lib/thread.c:117
  #18 0x00007f432b8c37fc in uthread_trampoline (arg=0x1367be0) at lib/user_space/uthread.c:98
  #19 0x00007f432af51e25 in start_thread (arg=0x7f42ccff9700) at pthread_create.c:308
  #20 0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  (gdb) thread 2
  [Switching to thread 2 (Thread 0x7f428ffff700 (LWP 8730))]
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  253                     if (!M0_CHECK_EX(m0_tlink_invariant(d, amb(d, scan))))
  (gdb) bt
  #0  0x00007f432b8b270b in m0_tlist_invariant (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>) at lib/tlist.c:253
  #1  0x00007f432b8b1f13 in m0_tlist_add (d=0x7f432bd94600 <sched_io_tl>, list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, obj=0x7f42880008c0) at lib/tlist.c:128
  #2  0x00007f432b7664c8 in sched_io_tlist_add (list=0x7f432d714a68 <be_ut_io_sched_scheduler+8>, amb=0x7f42880008c0) at be/io_sched.c:48
  #3  0x00007f432b766d88 in be_io_sched_insert (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0) at be/io_sched.c:161
  #4  0x00007f432b767144 in m0_be_io_sched_add (sched=0x7f432d714a60 <be_ut_io_sched_scheduler>, io=0x7f42880008c0, ext=0x7f428fffed00, op=0x7f4288000c00) at be/io_sched.c:193
  #5  0x00007f432cf8a008 in be_ut_io_sched_thread (param=0x136a2b0) at be/ut/io_sched.c:241
  #6  0x00007f432b8b01b8 in m0_thread_trampoline (arg=0x136bad0) at lib/thread.c:117
  #7  0x00007f432b8c37fc in uthread_trampoline (arg=0x136bad0) at lib/user_space/uthread.c:98
  #8  0x00007f432af51e25 in start_thread (arg=0x7f428ffff700) at pthread_create.c:308
  #9  0x00007f4329999bad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Signed-off-by: Maksym Medvied <maksym.medvied@seagate.com>
@madhavemuri madhavemuri mentioned this issue Nov 18, 2021
Merged
12 tasks
andriytk added a commit to andriytk/cortx-motr that referenced this issue Apr 27, 2022
@andriytk
Fix crash of all m0d-ios processes during write i/o
79ccb98 
All m0d-ios processes may crash if some of them is crashed during write
i/o. Here is the scenario, for example:

setup: 1 node, 5 ios processes configured with 2 disks each.

1) Start write:

    m0cp -l <local-endpoint> -H <hax-endpoint> -p <profile-fid> -P <process-fid> -s 32k -c 1024 -L 2 /dev/zero -o 0x12345678:0x678900202

2) After about 5 secs (to allow m0_client_init() to finish and start the i/o)
   kill -9 <PID> one of m0d-ios processes.

Panic msg: `((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)`

Stack:

    Seagate#3  0x00007f9454ccbe37 in m0_panic (ctx=ctx@entry=0x7f94550e15a0 <__pctx.8664>) at lib/assert.c:52
    Seagate#4  0x00007f9454c0747c in btree_save (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90, op=op@entry=0x7f944ca77ec0,
        val=val@entry=0x7f944ca77e70, anchor=0x0, optype=BTREE_SAVE_UPDATE, zonemask=2, key=<optimized out>, key=<optimized out>)
        at be/btree.c:339
    Seagate#5  0x00007f9454c086f7 in m0_be_btree_update (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90,
        op=op@entry=0x7f944ca77ec0, key=key@entry=0x7f944ca77e60, val=val@entry=0x7f944ca77e70) at be/btree.c:1952
    Seagate#6  0x00007f9454bfd62b in btree_update_sync (val=0x7f944ca77e70, key=0x7f944ca77e60, tx=0x7f94200a7f90, tree=0x40000010ed80)
        at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync (cb=cb@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90, gi=gi@entry=0x13ff860) at balloc/balloc.c:928
    Seagate#8  0x00007f9454bfe36e in balloc_free_db_update (motr=motr@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90,
        grp=grp@entry=0x13ff860, tgt=tgt@entry=0x7f944ca78470, alloc_flag=<optimized out>) at balloc/balloc.c:1934
    Seagate#9  0x00007f9454bff9c6 in balloc_free_internal (req=<synthetic pointer>, req=<synthetic pointer>, tx=0x7f94200a7f90,
        ctx=0x40000010eb40) at balloc/balloc.c:2716
    Seagate#10 balloc_free (ballroom=0x40000010ec68, tx=0x7f94200a7f88, ext=0x7f944ca78560) at balloc/balloc.c:2929
    Seagate#11 0x00007f9454d97681 in stob_ad_bfree (adom=<optimized out>, adom=<optimized out>, ext=0x7f944ca78530, ext=0x7f944ca78530,
        tx=0x7f94200a7f88) at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (tx=0x7f94200a7f88, adom=<optimized out>, ext=ext@entry=0x7f944ca79160, val=1594, seg=<optimized out>)
        at stob/ad.c:1647
    Seagate#13 0x00007f9454d9783d in __lambda (seg=0x7f944ca79150) at stob/ad.c:1719
    Seagate#14 0x00007f9454c10802 in m0_be_emap_paste (it=it@entry=0x7f944ca79140, tx=0x7f94200a7f90, ext=ext@entry=0x7f944ca78a90,
        val=1794, del=del@entry=0x7f944ca78b1c, cut_left=cut_left@entry=0x7f944ca78b38, cut_right=0x7f944ca78b54)
        at be/extmap.c:628
    Seagate#15 0x00007f9454d9a546 in stob_ad_write_map_ext (orig=<optimized out>, off=464, adom=0x4000001120d8) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map (map=0x7f944ca78900, frags=18, wc=0x7f944ca78920, dst=0x7f944ca789b0, adom=0x4000001120d8,
        io=0x7f94340b4298) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare (map=0x7f944ca78900, src=0x7f944ca78970, adom=0x4000001120d8, io=<optimized out>) at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare (io=<optimized out>) at stob/ad.c:2052
    Seagate#19 0x00007f9454d9ca47 in m0_stob_io_prepare (io=io@entry=0x7f94340b4298, obj=obj@entry=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:178
    Seagate#20 0x00007f9454d9ce92 in m0_stob_io_prepare_and_launch (io=io@entry=0x7f94340b4298, obj=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:226
    Seagate#21 0x00007f9454cb702c in io_launch (fom=0x7f94200a7ec0) at ioservice/io_foms.c:1837
    Seagate#22 0x00007f9454cb47a0 in m0_io_fom_cob_rw_tick (fom=0x7f94200a7ec0) at ioservice/io_foms.c:2333
    Seagate#23 0x00007f9454c9edf1 in fom_exec (fom=0x7f94200a7ec0) at fop/fom.c:791
    Seagate#24 loc_handler_thread (th=0x11ed150) at fop/fom.c:931

RCA: the regression of BE credit calculation in
stob/ad.c:stob_ad_write_credit() code was introduced at
commit ab22d23.

Solution: rollback the change in stob/ad.c:stob_ad_write_credit()
introduced at commit ab22d23.

Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
andriytk added a commit to andriytk/cortx-motr that referenced this issue Apr 27, 2022
@andriytk
Fix crash of all ios processes in some write i/o scenarios
4f65eff 
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    Seagate#3  0x00007f9454ccbe37 in m0_panic (ctx=ctx@entry=0x7f94550e15a0 <__pctx.8664>) at lib/assert.c:52
    Seagate#4  0x00007f9454c0747c in btree_save (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90, op=op@entry=0x7f944ca77ec0,
        val=val@entry=0x7f944ca77e70, anchor=0x0, optype=BTREE_SAVE_UPDATE, zonemask=2, key=<optimized out>, key=<optimized out>)
        at be/btree.c:339
    Seagate#5  0x00007f9454c086f7 in m0_be_btree_update (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90,
        op=op@entry=0x7f944ca77ec0, key=key@entry=0x7f944ca77e60, val=val@entry=0x7f944ca77e70) at be/btree.c:1952
    Seagate#6  0x00007f9454bfd62b in btree_update_sync (val=0x7f944ca77e70, key=0x7f944ca77e60, tx=0x7f94200a7f90, tree=0x40000010ed80)
        at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync (cb=cb@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90, gi=gi@entry=0x13ff860) at balloc/balloc.c:928
    Seagate#8  0x00007f9454bfe36e in balloc_free_db_update (motr=motr@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90,
        grp=grp@entry=0x13ff860, tgt=tgt@entry=0x7f944ca78470, alloc_flag=<optimized out>) at balloc/balloc.c:1934
    Seagate#9  0x00007f9454bff9c6 in balloc_free_internal (req=<synthetic pointer>, req=<synthetic pointer>, tx=0x7f94200a7f90,
        ctx=0x40000010eb40) at balloc/balloc.c:2716
    Seagate#10 balloc_free (ballroom=0x40000010ec68, tx=0x7f94200a7f88, ext=0x7f944ca78560) at balloc/balloc.c:2929
    Seagate#11 0x00007f9454d97681 in stob_ad_bfree (adom=<optimized out>, adom=<optimized out>, ext=0x7f944ca78530, ext=0x7f944ca78530,
        tx=0x7f94200a7f88) at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (tx=0x7f94200a7f88, adom=<optimized out>, ext=ext@entry=0x7f944ca79160, val=1594, seg=<optimized out>)
        at stob/ad.c:1647
    Seagate#13 0x00007f9454d9783d in __lambda (seg=0x7f944ca79150) at stob/ad.c:1719
    Seagate#14 0x00007f9454c10802 in m0_be_emap_paste (it=it@entry=0x7f944ca79140, tx=0x7f94200a7f90, ext=ext@entry=0x7f944ca78a90,
        val=1794, del=del@entry=0x7f944ca78b1c, cut_left=cut_left@entry=0x7f944ca78b38, cut_right=0x7f944ca78b54)
        at be/extmap.c:628
    Seagate#15 0x00007f9454d9a546 in stob_ad_write_map_ext (orig=<optimized out>, off=464, adom=0x4000001120d8) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map (map=0x7f944ca78900, frags=18, wc=0x7f944ca78920, dst=0x7f944ca789b0, adom=0x4000001120d8,
        io=0x7f94340b4298) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare (map=0x7f944ca78900, src=0x7f944ca78970, adom=0x4000001120d8, io=<optimized out>) at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare (io=<optimized out>) at stob/ad.c:2052
    Seagate#19 0x00007f9454d9ca47 in m0_stob_io_prepare (io=io@entry=0x7f94340b4298, obj=obj@entry=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:178
    Seagate#20 0x00007f9454d9ce92 in m0_stob_io_prepare_and_launch (io=io@entry=0x7f94340b4298, obj=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:226
    Seagate#21 0x00007f9454cb702c in io_launch (fom=0x7f94200a7ec0) at ioservice/io_foms.c:1837
    Seagate#22 0x00007f9454cb47a0 in m0_io_fom_cob_rw_tick (fom=0x7f94200a7ec0) at ioservice/io_foms.c:2333
    Seagate#23 0x00007f9454c9edf1 in fom_exec (fom=0x7f94200a7ec0) at fop/fom.c:791
    Seagate#24 loc_handler_thread (th=0x11ed150) at fop/fom.c:931

Setup: 1-node, 5 ios processes configured with 2 disks each,
       4+2+0 EC data pool.

Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
andriytk added a commit to andriytk/cortx-motr that referenced this issue Apr 27, 2022
@andriytk
Fix crash of all ios processes in some write i/o scenarios
d3ff93e 
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    Seagate#3  0x00007f9454ccbe37 in m0_panic (ctx=ctx@entry=0x7f94550e15a0 <__pctx.8664>) at lib/assert.c:52
    Seagate#4  0x00007f9454c0747c in btree_save (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90, op=op@entry=0x7f944ca77ec0,
        val=val@entry=0x7f944ca77e70, anchor=0x0, optype=BTREE_SAVE_UPDATE, zonemask=2, key=<optimized out>, key=<optimized out>)
        at be/btree.c:339
    Seagate#5  0x00007f9454c086f7 in m0_be_btree_update (tree=tree@entry=0x40000010ed80, tx=tx@entry=0x7f94200a7f90,
        op=op@entry=0x7f944ca77ec0, key=key@entry=0x7f944ca77e60, val=val@entry=0x7f944ca77e70) at be/btree.c:1952
    Seagate#6  0x00007f9454bfd62b in btree_update_sync (val=0x7f944ca77e70, key=0x7f944ca77e60, tx=0x7f94200a7f90, tree=0x40000010ed80)
        at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync (cb=cb@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90, gi=gi@entry=0x13ff860) at balloc/balloc.c:928
    Seagate#8  0x00007f9454bfe36e in balloc_free_db_update (motr=motr@entry=0x40000010eb40, tx=tx@entry=0x7f94200a7f90,
        grp=grp@entry=0x13ff860, tgt=tgt@entry=0x7f944ca78470, alloc_flag=<optimized out>) at balloc/balloc.c:1934
    Seagate#9  0x00007f9454bff9c6 in balloc_free_internal (req=<synthetic pointer>, req=<synthetic pointer>, tx=0x7f94200a7f90,
        ctx=0x40000010eb40) at balloc/balloc.c:2716
    Seagate#10 balloc_free (ballroom=0x40000010ec68, tx=0x7f94200a7f88, ext=0x7f944ca78560) at balloc/balloc.c:2929
    Seagate#11 0x00007f9454d97681 in stob_ad_bfree (adom=<optimized out>, adom=<optimized out>, ext=0x7f944ca78530, ext=0x7f944ca78530,
        tx=0x7f94200a7f88) at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (tx=0x7f94200a7f88, adom=<optimized out>, ext=ext@entry=0x7f944ca79160, val=1594, seg=<optimized out>)
        at stob/ad.c:1647
    Seagate#13 0x00007f9454d9783d in __lambda (seg=0x7f944ca79150) at stob/ad.c:1719
    Seagate#14 0x00007f9454c10802 in m0_be_emap_paste (it=it@entry=0x7f944ca79140, tx=0x7f94200a7f90, ext=ext@entry=0x7f944ca78a90,
        val=1794, del=del@entry=0x7f944ca78b1c, cut_left=cut_left@entry=0x7f944ca78b38, cut_right=0x7f944ca78b54)
        at be/extmap.c:628
    Seagate#15 0x00007f9454d9a546 in stob_ad_write_map_ext (orig=<optimized out>, off=464, adom=0x4000001120d8) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map (map=0x7f944ca78900, frags=18, wc=0x7f944ca78920, dst=0x7f944ca789b0, adom=0x4000001120d8,
        io=0x7f94340b4298) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare (map=0x7f944ca78900, src=0x7f944ca78970, adom=0x4000001120d8, io=<optimized out>) at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare (io=<optimized out>) at stob/ad.c:2052
    Seagate#19 0x00007f9454d9ca47 in m0_stob_io_prepare (io=io@entry=0x7f94340b4298, obj=obj@entry=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:178
    Seagate#20 0x00007f9454d9ce92 in m0_stob_io_prepare_and_launch (io=io@entry=0x7f94340b4298, obj=0x7f94341170a0,
        tx=tx@entry=0x7f94200a7f88, scope=scope@entry=0x0) at stob/io.c:226
    Seagate#21 0x00007f9454cb702c in io_launch (fom=0x7f94200a7ec0) at ioservice/io_foms.c:1837
    Seagate#22 0x00007f9454cb47a0 in m0_io_fom_cob_rw_tick (fom=0x7f94200a7ec0) at ioservice/io_foms.c:2333
    Seagate#23 0x00007f9454c9edf1 in fom_exec (fom=0x7f94200a7ec0) at fop/fom.c:791
    Seagate#24 loc_handler_thread (th=0x11ed150) at fop/fom.c:931

Setup: 1-node, 4+2+0 EC data pool with 10 disks.
Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
andriytk added a commit to andriytk/cortx-motr that referenced this issue Apr 27, 2022
@andriytk @madhavemuri
Fix crash of all ios processes in some write scenarios
c2f8e32 
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    Seagate#3  m0_panic() at lib/assert.c:52
    Seagate#4  btree_save() at be/btree.c:339
    Seagate#5  m0_be_btree_update() at be/btree.c:1952
    Seagate#6  btree_update_sync() at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync() at balloc/balloc.c:928
    Seagate#8  balloc_free_db_update() at balloc/balloc.c:1934
    Seagate#9  balloc_free_internal() at balloc/balloc.c:2716
    Seagate#10 balloc_free() at balloc/balloc.c:2929
    Seagate#11 stob_ad_bfree() at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (val=1594) at stob/ad.c:1647
    Seagate#13 __lambda() at stob/ad.c:1719
    Seagate#14 m0_be_emap_paste(val=1794) at be/extmap.c:628
    Seagate#15 stob_ad_write_map_ext(off=464) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map(frags=18) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare() at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare() at stob/ad.c:2052
    Seagate#19 m0_stob_io_prepare() at stob/io.c:178
    Seagate#20 m0_stob_io_prepare_and_launch() at stob/io.c:226
    Seagate#21 io_launch() at ioservice/io_foms.c:1837
    Seagate#22 m0_io_fom_cob_rw_tick() at ioservice/io_foms.c:2333
    Seagate#23 fom_exec() at fop/fom.c:791
    Seagate#24 loc_handler_thread() at fop/fom.c:931

Setup: 1 node, 4+2+0 EC data pool with 10 disks.
Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Co-authored-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
andriytk added a commit to andriytk/cortx-motr that referenced this issue Apr 27, 2022
@andriytk @madhavemuri
Fix crash of all ios processes in some write scenarios
710f283 
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    Seagate#3  m0_panic() at lib/assert.c:52
    Seagate#4  btree_save() at be/btree.c:339
    Seagate#5  m0_be_btree_update() at be/btree.c:1952
    Seagate#6  btree_update_sync() at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync() at balloc/balloc.c:928
    Seagate#8  balloc_free_db_update() at balloc/balloc.c:1934
    Seagate#9  balloc_free_internal() at balloc/balloc.c:2716
    Seagate#10 balloc_free() at balloc/balloc.c:2929
    Seagate#11 stob_ad_bfree() at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (val=1594) at stob/ad.c:1647
    Seagate#13 __lambda() at stob/ad.c:1719
    Seagate#14 m0_be_emap_paste(val=1794) at be/extmap.c:628
    Seagate#15 stob_ad_write_map_ext(off=464) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map(frags=18) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare() at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare() at stob/ad.c:2052
    Seagate#19 m0_stob_io_prepare() at stob/io.c:178
    Seagate#20 m0_stob_io_prepare_and_launch() at stob/io.c:226
    Seagate#21 io_launch() at ioservice/io_foms.c:1837
    Seagate#22 m0_io_fom_cob_rw_tick() at ioservice/io_foms.c:2333
    Seagate#23 fom_exec() at fop/fom.c:791
    Seagate#24 loc_handler_thread() at fop/fom.c:931

Setup: 1 node, 4+2+0 EC data pool with 10 disks.
Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Co-authored-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
madhavemuri pushed a commit that referenced this issue May 4, 2022
@andriytk
motr: fix crash of all ios processes in some write scenarios (#1686)
317b5ca 
Problem: Following panic occurs if update operation is done,
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    #3  m0_panic() at lib/assert.c:52
    #4  btree_save() at be/btree.c:339
    #5  m0_be_btree_update() at be/btree.c:1952
    #6  btree_update_sync() at balloc/balloc.c:95
    #7  balloc_gi_sync() at balloc/balloc.c:928
    #8  balloc_free_db_update() at balloc/balloc.c:1934
    #9  balloc_free_internal() at balloc/balloc.c:2716
    #10 balloc_free() at balloc/balloc.c:2929
    #11 stob_ad_bfree() at stob/ad.c:1098
    #12 stob_ad_seg_free (val=1594) at stob/ad.c:1647
    #13 __lambda() at stob/ad.c:1719
    #14 m0_be_emap_paste(val=1794) at be/extmap.c:628
    #15 stob_ad_write_map_ext(off=464) at stob/ad.c:1731
    #16 stob_ad_write_map(frags=18) at stob/ad.c:1858
    #17 stob_ad_write_prepare() at stob/ad.c:2006
    #18 stob_ad_io_launch_prepare() at stob/ad.c:2052
    #19 m0_stob_io_prepare() at stob/io.c:178
    #20 m0_stob_io_prepare_and_launch() at stob/io.c:226
    #21 io_launch() at ioservice/io_foms.c:1837
    #22 m0_io_fom_cob_rw_tick() at ioservice/io_foms.c:2333
    #23 fom_exec() at fop/fom.c:791
    #24 loc_handler_thread() at fop/fom.c:931

Setup: 1 node, 4+2+0 EC data pool with 10 disks.
Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
andriytk added a commit to andriytk/cortx-motr that referenced this issue May 10, 2022
@andriytk @madhavemuri
Fix crash of all ios processes in some write i/o scenarios
96b2421 
Panic: ((cr->tc_balance[cu]) != 0) at btree_save() (be/btree.c:1393)

Stack:

    Seagate#3  m0_panic() at lib/assert.c:52
    Seagate#4  btree_save() at be/btree.c:339
    Seagate#5  m0_be_btree_update() at be/btree.c:1952
    Seagate#6  btree_update_sync() at balloc/balloc.c:95
    Seagate#7  balloc_gi_sync() at balloc/balloc.c:928
    Seagate#8  balloc_free_db_update() at balloc/balloc.c:1934
    Seagate#9  balloc_free_internal() at balloc/balloc.c:2716
    Seagate#10 balloc_free() at balloc/balloc.c:2929
    Seagate#11 stob_ad_bfree() at stob/ad.c:1098
    Seagate#12 stob_ad_seg_free (val=1594) at stob/ad.c:1647
    Seagate#13 __lambda() at stob/ad.c:1719
    Seagate#14 m0_be_emap_paste(val=1794) at be/extmap.c:628
    Seagate#15 stob_ad_write_map_ext(off=464) at stob/ad.c:1731
    Seagate#16 stob_ad_write_map(frags=18) at stob/ad.c:1858
    Seagate#17 stob_ad_write_prepare() at stob/ad.c:2006
    Seagate#18 stob_ad_io_launch_prepare() at stob/ad.c:2052
    Seagate#19 m0_stob_io_prepare() at stob/io.c:178
    Seagate#20 m0_stob_io_prepare_and_launch() at stob/io.c:226
    Seagate#21 io_launch() at ioservice/io_foms.c:1837
    Seagate#22 m0_io_fom_cob_rw_tick() at ioservice/io_foms.c:2333
    Seagate#23 fom_exec() at fop/fom.c:791
    Seagate#24 loc_handler_thread() at fop/fom.c:931

Setup: 1 node, 4+2+0 EC data pool with 10 disks.
Scenario: write the same object twice like this:

    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207
    $ m0cp <motr-conn-params> -s 1m -c 40 -L 4 /dev/zero -o 0x12345678:0x678900207 -u

RCA: regression of BE credit calculation in stob_ad_write_credit()
code was introduced at commit ab22d23.

Solution: rollback the regression change.

Co-authored-by: Madhavrao Vemuri <madhav.vemuri@seagate.com>
Signed-off-by: Andriy Tkachuk <andriy.tkachuk@seagate.com>
@vidyadhar-pinglikar vidyadhar-pinglikar mentioned this issue Jun 7, 2022
Merged
12 tasks
mehjoshi pushed a commit that referenced this issue Jun 7, 2022
@vidyadhar-pinglikar
CORTX-30993 - RCA: Due to recursive calls to be_op_state_change where…
6d1944d 
… gc callback of (#1820)

Problem : In m0_be_op_fini, when bos_tlink_fini is performed then its expected that bo_set_link should not have link for link for parent's m0_be_op::bo_children.

State seen at the time of crash:
Two gft_pd_io in progress state, with corresponding two bio in sched queue; crash is hit while performing the gc callback processing for gft whhose gft_pd_io is in progress state and bio is queued behind an active io.

Panic:
2022-04-24 11:19:15,672 - motr[00107]: e2e0 FATAL [lib/assert.c:50:m0_panic] panic: (!m0_list_link_is_in(link)) at m0_list_link_fini() (lib/list.c:178) [git: 2.0.0-670-27-g0012fe90] /etc/cortx/log/motr/0696b1d9e4744c59a92cb2bdded112ac/trace/m0d-0x7200000000000001:0x2e/m0trace.107
2022-04-24 11:19:15,672 - Motr panic: (!m0_list_link_is_in(link)) at m0_list_link_fini() lib/list.c:178 (errno: 0) (last failed: none) [git: 2.0.0-670-27-g0012fe90] pid: 107 /etc/cortx/log/motr/0696b1d9e4744c59a92cb2bdded112ac/trace/m0d-0x7200000000000001:0x2e/m0trace.107
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_arch_backtrace+0x33)[0x7f7514e79c83]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_arch_panic+0xe9)[0x7f7514e79e59]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_panic+0x13d)[0x7f7514e6890d]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(+0x3895f6)[0x7f7514e6c5f6]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_be_op_fini+0x1f)[0x7f7514dae66f]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(+0x2cb826)[0x7f7514dae826]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c4c5b)[0x7f7514da7c5b]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2cb826)[0x7f7514dae826]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c300a)[0x7f7514da600a]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c3119)[0x7f7514da6119]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x386f7f)[0x7f7514e69f7f]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x386ffa)[0x7f7514e69ffa]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(m0_chan_broadcast_lock+0x1d)[0x7f7514e6a08d]

Backtrace:
(gdb) bt
#0 0x00007f7512d8938f in raise () from /lib64/libc.so.6
#1 0x00007f7512d73dc5 in abort () from /lib64/libc.so.6
#2 0x00007f7514e79e63 in m0_arch_panic (c=c@entry=0x7f751531ade0 <__pctx.4611>, ap=ap@entry=0x7f74afffe390)
at lib/user_space/uassert.c:131
#3 0x00007f7514e6890d in m0_panic (ctx=ctx@entry=0x7f751531ade0 <__pctx.4611>) at lib/assert.c:52
#4 0x00007f7514e6c5f6 in m0_list_link_fini (link=) at lib/list.c:178
#5 0x00007f7514e70310 in m0_tlink_fini (d=d@entry=0x7f75152880a0 <bos_tl>, obj=obj@entry=0x56523e641a90) at lib/tlist.c:283
#6 0x00007f7514dae66f in bos_tlink_fini (amb=0x56523e641a90) at be/op.c:109
#7 m0_be_op_fini (op=0x56523e641a90) at be/op.c:109
#8 0x00007f7514dae826 in be_op_state_change (op=, state=state@entry=M0_BOS_DONE) at be/op.c:213
#9 0x00007f7514daea17 in m0_be_op_done (op=) at be/op.c:231
#10 0x00007f7514da7c5b in be_io_sched_cb (op=op@entry=0x56523e5f7870, param=param@entry=0x56523e5f7798) at be/io_sched.c:141
#11 0x00007f7514dae826 in be_op_state_change (op=op@entry=0x56523e5f7870, state=state@entry=M0_BOS_DONE) at be/op.c:213
#12 0x00007f7514daea17 in m0_be_op_done (op=op@entry=0x56523e5f7870) at be/op.c:231
#13 0x00007f7514da600a in be_io_finished (bio=bio@entry=0x56523e5f7798) at be/io.c:555
#14 0x00007f7514da6119 in be_io_cb (link=0x56523e61ac60) at be/io.c:587
#15 0x00007f7514e69f7f in clink_signal (clink=clink@entry=0x56523e61ac60) at lib/chan.c:135
#16 0x00007f7514e69ffa in chan_signal_nr (chan=chan@entry=0x56523e61ab58, nr=0) at lib/chan.c:154
#17 0x00007f7514e6a06c in m0_chan_broadcast (chan=chan@entry=0x56523e61ab58) at lib/chan.c:174
#18 0x00007f7514e6a08d in m0_chan_broadcast_lock (chan=chan@entry=0x56523e61ab58) at lib/chan.c:181
#19 0x00007f7514f4209a in ioq_complete (res2=, res=, qev=, ioq=0x56523e5de610)
at stob/ioq.c:587
#20 stob_ioq_thread (ioq=0x56523e5de610) at stob/ioq.c:669
#21 0x00007f7514e6f49e in m0_thread_trampoline (arg=arg@entry=0x56523e5de6e8) at lib/thread.c:117
#22 0x00007f7514e7ab11 in uthread_trampoline (arg=0x56523e5de6e8) at lib/user_space/uthread.c:98
#23 0x00007f751454915a in start_thread () from /lib64/libpthread.so.0
#24 0x00007f7512e4edd3 in clone () from /lib64/libc.so.6

RCA - Sequence of Events:

be_tx_group_format_seg_io_op_gc invoked for gft_pd_io_op of tx_group_fom_1 (last_child is false)
(gdb) p &((struct m0_be_group_format *)cb_gc_param)->gft_pd_io_op
$29 = (struct m0_be_op *) 0x56523e641a90

be_tx_group_format_seg_io_op_gc handling of gft_pd_io_op invokes m0_be_op_done for gft_tmp_op (no callbacks for gft_tmp_op) but now last_child is set true for parent as its both child (gft_tmp_op and gft_pd_io_op) op dones have been invoked

m0_be_op_done handling of gft_tmp_op invokes be_op_state_change with M0_BOS_DONE for parent(tgf_op)

During be_op_state_change processing for main parent tgf_op, m0_sm_state_set will update bo_sm state and it will unblock the tx_group_fom_1 by triggering op->bo_sm.sm_chan
This recursive callback processing happens in context of stob_ioq_thread which is initialized on M0_STOB_IOQ_NR_THREADS.
Here due to invocation of gft_tmp_op (i.e peer) child done processing from gft_pd_io_op child gc processing results in their parent early callback invocation.

Parent Callback Prcoseeing:
6. This now unblocks tx_group_fom_1 which will lead to m0_be_pd_io_put in m0_be_group_format_reset and and tx_group_fom_1 will move to TGS_OPEN.
So pd_io and tx_group_fom_1 is now ready for reuse.

Problem window:
7. problem will now occur in window if remaining gc callback processing of gft_pd_io_op
i.e.
m0_be_op_fini(&gft->gft_tmp_op);
m0_be_op_fini(op);
is being done if the pd_io and/or tx_group_fom_1 is reused with new context.

Solution:
Removal of gft_tmp_op altogether will ensure that parent callback processing never invoked ahead of its child callback processing
This way tx_group_fom will always be notifed of seg io completion only after all the relevent child calbback processing is completed and thereby
will avoid the crashes seen in the gc callback processing(be_tx_group_format_seg_io_op_gc) after m0_be_op_done(&gft->gft_tmp_op);
In proposed solution main parent op is made active at the start at the same place where gft_tmp_op was being activated in order to put this parent
into active state; there by making gft_tmp_op redundent and avoiding the out of order execution of child/parent callback executions;
RCA: Due to recursive calls to be_op_state_change where gc callback of gft_op i.e. child1 invokes done callback of gft_tmp_op i.e. child 2 which subsequently results in invocation of parent be_op_state_change. This results in group fom getting completed ahead of child op callback processing. so the subsequently crash is observed when group is reused before child callback processing is finished.

Signed-off-by: Vidyadhar Pinglikar vidyadhar.pinglikar@seagate.com
mehjoshi pushed a commit to mehjoshi/cortx-motr that referenced this issue Jul 18, 2022
@vidyadhar-pinglikar
CORTX-30993 - RCA: Due to recursive calls to be_op_state_change where…
9dfc351 
… gc callback of (Seagate#1820)

Problem : In m0_be_op_fini, when bos_tlink_fini is performed then its expected that bo_set_link should not have link for link for parent's m0_be_op::bo_children.

State seen at the time of crash:
Two gft_pd_io in progress state, with corresponding two bio in sched queue; crash is hit while performing the gc callback processing for gft whhose gft_pd_io is in progress state and bio is queued behind an active io.

Panic:
2022-04-24 11:19:15,672 - motr[00107]: e2e0 FATAL [lib/assert.c:50:m0_panic] panic: (!m0_list_link_is_in(link)) at m0_list_link_fini() (lib/list.c:178) [git: 2.0.0-670-27-g0012fe90] /etc/cortx/log/motr/0696b1d9e4744c59a92cb2bdded112ac/trace/m0d-0x7200000000000001:0x2e/m0trace.107
2022-04-24 11:19:15,672 - Motr panic: (!m0_list_link_is_in(link)) at m0_list_link_fini() lib/list.c:178 (errno: 0) (last failed: none) [git: 2.0.0-670-27-g0012fe90] pid: 107 /etc/cortx/log/motr/0696b1d9e4744c59a92cb2bdded112ac/trace/m0d-0x7200000000000001:0x2e/m0trace.107
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_arch_backtrace+0x33)[0x7f7514e79c83]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_arch_panic+0xe9)[0x7f7514e79e59]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_panic+0x13d)[0x7f7514e6890d]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(+0x3895f6)[0x7f7514e6c5f6]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(m0_be_op_fini+0x1f)[0x7f7514dae66f]
2022-04-24 11:19:15,706 - /lib64/libmotr.so.2(+0x2cb826)[0x7f7514dae826]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c4c5b)[0x7f7514da7c5b]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2cb826)[0x7f7514dae826]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c300a)[0x7f7514da600a]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x2c3119)[0x7f7514da6119]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x386f7f)[0x7f7514e69f7f]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(+0x386ffa)[0x7f7514e69ffa]
2022-04-24 11:19:15,707 - /lib64/libmotr.so.2(m0_chan_broadcast_lock+0x1d)[0x7f7514e6a08d]

Backtrace:
(gdb) bt
#0 0x00007f7512d8938f in raise () from /lib64/libc.so.6
Seagate#1 0x00007f7512d73dc5 in abort () from /lib64/libc.so.6
Seagate#2 0x00007f7514e79e63 in m0_arch_panic (c=c@entry=0x7f751531ade0 <__pctx.4611>, ap=ap@entry=0x7f74afffe390)
at lib/user_space/uassert.c:131
Seagate#3 0x00007f7514e6890d in m0_panic (ctx=ctx@entry=0x7f751531ade0 <__pctx.4611>) at lib/assert.c:52
Seagate#4 0x00007f7514e6c5f6 in m0_list_link_fini (link=) at lib/list.c:178
Seagate#5 0x00007f7514e70310 in m0_tlink_fini (d=d@entry=0x7f75152880a0 <bos_tl>, obj=obj@entry=0x56523e641a90) at lib/tlist.c:283
Seagate#6 0x00007f7514dae66f in bos_tlink_fini (amb=0x56523e641a90) at be/op.c:109
Seagate#7 m0_be_op_fini (op=0x56523e641a90) at be/op.c:109
Seagate#8 0x00007f7514dae826 in be_op_state_change (op=, state=state@entry=M0_BOS_DONE) at be/op.c:213
Seagate#9 0x00007f7514daea17 in m0_be_op_done (op=) at be/op.c:231
Seagate#10 0x00007f7514da7c5b in be_io_sched_cb (op=op@entry=0x56523e5f7870, param=param@entry=0x56523e5f7798) at be/io_sched.c:141
Seagate#11 0x00007f7514dae826 in be_op_state_change (op=op@entry=0x56523e5f7870, state=state@entry=M0_BOS_DONE) at be/op.c:213
Seagate#12 0x00007f7514daea17 in m0_be_op_done (op=op@entry=0x56523e5f7870) at be/op.c:231
Seagate#13 0x00007f7514da600a in be_io_finished (bio=bio@entry=0x56523e5f7798) at be/io.c:555
Seagate#14 0x00007f7514da6119 in be_io_cb (link=0x56523e61ac60) at be/io.c:587
Seagate#15 0x00007f7514e69f7f in clink_signal (clink=clink@entry=0x56523e61ac60) at lib/chan.c:135
Seagate#16 0x00007f7514e69ffa in chan_signal_nr (chan=chan@entry=0x56523e61ab58, nr=0) at lib/chan.c:154
Seagate#17 0x00007f7514e6a06c in m0_chan_broadcast (chan=chan@entry=0x56523e61ab58) at lib/chan.c:174
Seagate#18 0x00007f7514e6a08d in m0_chan_broadcast_lock (chan=chan@entry=0x56523e61ab58) at lib/chan.c:181
Seagate#19 0x00007f7514f4209a in ioq_complete (res2=, res=, qev=, ioq=0x56523e5de610)
at stob/ioq.c:587
Seagate#20 stob_ioq_thread (ioq=0x56523e5de610) at stob/ioq.c:669
Seagate#21 0x00007f7514e6f49e in m0_thread_trampoline (arg=arg@entry=0x56523e5de6e8) at lib/thread.c:117
Seagate#22 0x00007f7514e7ab11 in uthread_trampoline (arg=0x56523e5de6e8) at lib/user_space/uthread.c:98
Seagate#23 0x00007f751454915a in start_thread () from /lib64/libpthread.so.0
Seagate#24 0x00007f7512e4edd3 in clone () from /lib64/libc.so.6

RCA - Sequence of Events:

be_tx_group_format_seg_io_op_gc invoked for gft_pd_io_op of tx_group_fom_1 (last_child is false)
(gdb) p &((struct m0_be_group_format *)cb_gc_param)->gft_pd_io_op
$29 = (struct m0_be_op *) 0x56523e641a90

be_tx_group_format_seg_io_op_gc handling of gft_pd_io_op invokes m0_be_op_done for gft_tmp_op (no callbacks for gft_tmp_op) but now last_child is set true for parent as its both child (gft_tmp_op and gft_pd_io_op) op dones have been invoked

m0_be_op_done handling of gft_tmp_op invokes be_op_state_change with M0_BOS_DONE for parent(tgf_op)

During be_op_state_change processing for main parent tgf_op, m0_sm_state_set will update bo_sm state and it will unblock the tx_group_fom_1 by triggering op->bo_sm.sm_chan
This recursive callback processing happens in context of stob_ioq_thread which is initialized on M0_STOB_IOQ_NR_THREADS.
Here due to invocation of gft_tmp_op (i.e peer) child done processing from gft_pd_io_op child gc processing results in their parent early callback invocation.

Parent Callback Prcoseeing:
6. This now unblocks tx_group_fom_1 which will lead to m0_be_pd_io_put in m0_be_group_format_reset and and tx_group_fom_1 will move to TGS_OPEN.
So pd_io and tx_group_fom_1 is now ready for reuse.

Problem window:
7. problem will now occur in window if remaining gc callback processing of gft_pd_io_op
i.e.
m0_be_op_fini(&gft->gft_tmp_op);
m0_be_op_fini(op);
is being done if the pd_io and/or tx_group_fom_1 is reused with new context.

Solution:
Removal of gft_tmp_op altogether will ensure that parent callback processing never invoked ahead of its child callback processing
This way tx_group_fom will always be notifed of seg io completion only after all the relevent child calbback processing is completed and thereby
will avoid the crashes seen in the gc callback processing(be_tx_group_format_seg_io_op_gc) after m0_be_op_done(&gft->gft_tmp_op);
In proposed solution main parent op is made active at the start at the same place where gft_tmp_op was being activated in order to put this parent
into active state; there by making gft_tmp_op redundent and avoiding the out of order execution of child/parent callback executions;
RCA: Due to recursive calls to be_op_state_change where gc callback of gft_op i.e. child1 invokes done callback of gft_tmp_op i.e. child 2 which subsequently results in invocation of parent be_op_state_change. This results in group fom getting completed ahead of child op callback processing. so the subsequently crash is observed when group is reused before child callback processing is finished.

Signed-off-by: Vidyadhar Pinglikar vidyadhar.pinglikar@seagate.com
@cortx-admin cortx-admin mentioned this issue Aug 2, 2022
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@madhavemuri @imvenkip