Re: kernel BUG scsi_dh_alua sleeping from invalid context && kernel WARNING do not call blocking ops when !TASK_RUNNING

[Martin Wilck <mwilck@suse.com>]

On Tue, 2023-01-24 at 12:16 +0100, Steffen Maier wrote:
> On 1/18/23 17:17, Steffen Maier wrote:
> 
> > 
> > I had removed those two lines yesterday for our CI kernel build.
> > Tonight's run obviously no longer had any related BUG or WARNING.
> > I checked all dumps from that run to see if anything stalled and
> > whether it was 
> > related to ALUA, but I think we're good.
> > 
> > Tested-by: Steffen Maier <maier@linux.ibm.com>
> 
> I'm afraid, that might have been too early.
> Today, I got BUG/WARNING with a slightly different stack trace where 
> alua_rtpg_queue calls scsi_device_put(), which in turn contains a
> might_sleep 
> but seems called in atomic context:
> 
> > [ 2517.231562] sd 13:0:0:1073823768: Power-on or device reset
> > occurred
> > [ 2517.231582] sd 13:0:0:1073823768: [sdax] tag#2787 Done:
> > ADD_TO_MLQUEUE Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> > cmd_age=0s
> > [ 2517.231590] sd 13:0:0:1073823768: [sdax] tag#2787 CDB: Test Unit
> > Ready 00 00 00 00 00 00
> > [ 2517.231598] sd 13:0:0:1073823768: [sdax] tag#2787 Sense Key :
> > Unit Attention [current] 
> > [ 2517.231605] sd 13:0:0:1073823768: [sdax] tag#2787 Add. Sense:
> > Power on, reset, or bus device reset occurred
> > [ 2517.236104] sd 13:0:0:1074348056: Power-on or device reset
> > occurred
> > [ 2517.236124] BUG: sleeping function called from invalid context
> > at drivers/scsi/scsi.c:591
> > [ 2517.236130] in_atomic(): 1, irqs_disabled(): 0, non_block: 0,
> > pid: 166768, name: systemd-udevd
> > [ 2517.236137] preempt_count: 100, expected: 0
> > [ 2517.236143] RCU nest depth: 0, expected: 0
> > [ 2517.236148] no locks held by systemd-udevd/166768.
> > [ 2517.236154] Preemption disabled at:
> > [ 2517.236157] [<000000019704d22e>] __do_softirq+0x5e/0x6b8
> > [ 2517.236177] CPU: 2 PID: 166768 Comm: systemd-udevd Tainted:
> > G              K    6.2.0-
> > 20230123.rc5.git2.9dea08313ff5.300.fc37.s390x+debug #1
> > [ 2517.236185] Hardware name: IBM 8561 T01 703 (z/VM 7.3.0)
> > [ 2517.236190] Call Trace:
> > [ 2517.236195]  [<00000001970367cc>] dump_stack_lvl+0xac/0x100 
> > [ 2517.236203]  [<00000001962a590c>] __might_resched+0x284/0x2c8 
> > [ 2517.236213]  [<0000000196c7b34a>] scsi_device_put+0x42/0x60 
> > [ 2517.236224]  [<000003ff7fb9c57e>]
> > alua_rtpg_queue.part.0+0xce/0x348 [scsi_dh_alua] 
> > [ 2517.236234]  [<000003ff7fb9d20a>] alua_check+0x132/0x260
> > [scsi_dh_alua] 
> > [ 2517.236241]  [<000003ff7fb9d4aa>] alua_check_sense+0x172/0x228
> > [scsi_dh_alua] 
> > [ 2517.236248]  [<0000000196c7fd0e>] scsi_check_sense+0x86/0x2e0 
> > [ 2517.236256]  [<0000000196c82cc6>]
> > scsi_decide_disposition+0x286/0x298 
> > [ 2517.236262]  [<0000000196c873da>] scsi_complete+0x6a/0x108 
> > [ 2517.236269]  [<0000000196a5aeea>] blk_complete_reqs+0x6a/0x88 
> > [ 2517.236281]  [<000000019704d30a>] __do_softirq+0x13a/0x6b8 
> > [ 2517.236287]  [<000000019626b802>] __irq_exit_rcu+0x14a/0x170 
> > [ 2517.236297]  [<000000019626c372>] irq_exit_rcu+0x22/0x50 
> > [ 2517.236303]  [<0000000197036fda>] do_ext_irq+0xba/0x1d0 
> > [ 2517.236309]  [<000000019704ad06>] ext_int_handler+0xd6/0x110 
> > [ 2517.236315]  [<00000001963accd2>] seccomp_run_filters+0x9a/0x198
> > [ 2517.236328]  [<00000001963ad5bc>] __seccomp_filter+0x4c/0x3b8 
> > [ 2517.236334]  [<0000000196335f1a>]
> > syscall_trace_enter.constprop.0+0xda/0x310 
> > [ 2517.236345]  [<0000000197036bf0>] __do_syscall+0xf0/0x208 
> > [ 2517.236350]  [<000000019704aa52>] system_call+0x82/0xb0 
> > [ 2517.236356] no locks held by systemd-udevd/166768.
> 
> The same can also happen outside of process context, where it
> happened to run 
> alua_rtpg() before an IRQ happened for :
> 
> > [ 2517.249685] ------------[ cut here ]------------
> > [ 2517.249691] do not call blocking ops when !TASK_RUNNING; state=2
> > set at [<0000000197040cb2>] __wait_for_common+0xa2/0x240
> > [ 2517.249710] WARNING: CPU: 0 PID: 121221 at
> > kernel/sched/core.c:9959 __might_sleep+0x7c/0x98
> > [ 2517.249719] Modules linked in: kvm af_iucv algif_hash af_alg
> > nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet
> > nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat
> > nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nf_tables
> > nfnetlink dm_service_time sunrpc zfcp scsi_transport_fc s390_trng
> > vfio_ccw mdev vfio_iommu_type1 vfio sch_fq_codel ip6_tables
> > ip_tables x_tables configfs ghash_s390 prng chacha_s390 libchacha
> > aes_s390 des_s390 libdes sha3_512_s390 sha3_256_s390 nvme
> > sha512_s390 sha256_s390 sha1_s390 sha_common nvme_core scsi_dh_rdac
> > scsi_dh_emc scsi_dh_alua pkey zcrypt rng_core dm_multipath autofs4
> > [ 2517.249869] Unloaded tainted modules: test_klp_state3(K):1
> > test_klp_state2(K):4 test_klp_state(K):3
> > test_klp_callbacks_demo2(K):2 test_klp_callbacks_demo(K):12
> > test_klp_atomic_replace(K):2 test_klp_livepatch(K):6 [last
> > unloaded: test_klp_callbacks_demo(K)]
> > [ 2517.249907] CPU: 0 PID: 121221 Comm: kworker/0:1 Tainted:
> > G        W     K    6.2.0-
> > 20230123.rc5.git2.9dea08313ff5.300.fc37.s390x+debug #1
> > [ 2517.249915] Hardware name: IBM 8561 T01 703 (z/VM 7.3.0)
> > [ 2517.249921] Workqueue: kaluad alua_rtpg_work [scsi_dh_alua]
> > [ 2517.249931] Krnl PSW : 0704d00180000000 00000001962a59d0
> > (__might_sleep+0x80/0x98)
> > [ 2517.249944]            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3
> > CC:1 PM:0 RI:0 EA:3
> > [ 2517.249953] Krnl GPRS: c0000000ffffbfff 0000000080000101
> > 000000000000006d 00000001974ae114
> > [ 2517.249960]            0000037ffff339a0 0000037ffff33998
> > 0000000000000000 0000000000000001
> > [ 2517.249966]            0700037ffff33b50 00000000be69c000
> > 000000000000024f 00000001974cb458
> > [ 2517.249973]            00000000a4080100 00000000a5344220
> > 00000001962a59cc 0000037ffff33b30
> > [ 2517.249985] Krnl Code: 00000001962a59c0:
> > c020008c269f        larl    %r2,000000019742a6fe
> >                           00000001962a59c6:
> > c0e5006bbf19        brasl   %r14,000000019701d7f8
> >                          #00000001962a59cc:
> > af000000            mc      0,0
> >                          >00000001962a59d0:
> > a7490000            lghi    %r4,0
> >                           00000001962a59d4:
> > b904003a            lgr     %r3,%r10
> >                           00000001962a59d8:
> > b904002b            lgr     %r2,%r11
> >                           00000001962a59dc:
> > ebaff0a00004        lmg     %r10,%r15,160(%r15)
> >                           00000001962a59e2:
> > c0f4fffffe53        brcl    15,00000001962a5688
> > [ 2517.250023] Call Trace:
> > [ 2517.250028]  [<00000001962a59d0>] __might_sleep+0x80/0x98 
> > [ 2517.250036] ([<00000001962a59cc>] __might_sleep+0x7c/0x98)
> > [ 2517.250043]  [<0000000196c7b34a>] scsi_device_put+0x42/0x60 
> > [ 2517.250050]  [<000003ff7fb9c57e>]
> > alua_rtpg_queue.part.0+0xce/0x348 [scsi_dh_alua] 
> > [ 2517.250058]  [<000003ff7fb9d20a>] alua_check+0x132/0x260
> > [scsi_dh_alua] 
> > [ 2517.250066]  [<000003ff7fb9d4aa>] alua_check_sense+0x172/0x228
> > [scsi_dh_alua] 
> > [ 2517.250073]  [<0000000196c7fd0e>] scsi_check_sense+0x86/0x2e0 
> > [ 2517.250080]  [<0000000196c82cc6>]
> > scsi_decide_disposition+0x286/0x298 
> > [ 2517.250087]  [<0000000196c873da>] scsi_complete+0x6a/0x108 
> > [ 2517.250095]  [<0000000196a5aeea>] blk_complete_reqs+0x6a/0x88 
> > [ 2517.250102]  [<000000019704d30a>] __do_softirq+0x13a/0x6b8 
> > [ 2517.250109]  [<000000019626b802>] __irq_exit_rcu+0x14a/0x170 
> > [ 2517.250116]  [<000000019626c372>] irq_exit_rcu+0x22/0x50 
> > [ 2517.250123]  [<0000000197036fda>] do_ext_irq+0xba/0x1d0 
> > [ 2517.250130]  [<000000019704ad06>] ext_int_handler+0xd6/0x110 
> > [ 2517.250136]  [<0000000197049ac2>] _raw_spin_unlock_irq+0x42/0x70
> > [ 2517.250143] ([<0000000197049abe>]
> > _raw_spin_unlock_irq+0x3e/0x70)
> > [ 2517.250150]  [<0000000197040cdc>] __wait_for_common+0xcc/0x240 
> > [ 2517.250157]  [<0000000196a5bf8e>] blk_execute_rq+0x126/0x1f8 
> > [ 2517.250165]  [<0000000196c84f32>] __scsi_execute+0x112/0x260 
> > [ 2517.250172]  [<000003ff7fb9d698>] alua_rtpg+0x138/0xb10
> > [scsi_dh_alua] 
> > [ 2517.250179]  [<000003ff7fb9e32c>] alua_rtpg_work+0x2bc/0x4e0
> > [scsi_dh_alua] 
> > [ 2517.250186]  [<000000019628c244>] process_one_work+0x30c/0x730 
> > [ 2517.250197]  [<000000019628c6ca>] worker_thread+0x62/0x420 
> > [ 2517.250205]  [<0000000196297b08>] kthread+0x138/0x150 
> > [ 2517.250214]  [<000000019620f92c>] __ret_from_fork+0x3c/0x58 
> > [ 2517.250222]  [<000000019704aa8a>] ret_from_fork+0xa/0x40 
> > [ 2517.250229] 2 locks held by kworker/0:1/121221:
> > [ 2517.250235]  #0: 000000008ba79148 ((wq_completion)kaluad){+.+.}-
> > {0:0}, at: process_one_work+0x232/0x730
> > [ 2517.250256]  #1: 000003800695fdc8 ((work_completion)(&(&pg-
> > >rtpg_work)->work)){+.+.}-{0:0}, at: process_one_work+0x232/0x730
> > [ 2517.250276] Last Breaking-Event-Address:
> > [ 2517.250281]  [<000000019701d85e>] __warn_printk+0x66/0x70
> > [ 2517.250291] Kernel panic - not syncing: kernel: panic_on_warn
> > set ...
> 

I assume that Bart's previous reasoning applies here, too.
scsi_device_put() sleeps only if it releases the last reference to the
device. The calling stack, working on an I/O if the device in question,
must hold another reference to the scsi_device, so the ref being put
by alua_check->alua_rtpg_queue() can't be the last one.

Consequently, following this line of reasoning, we could remove the
might_sleep() in scsi_device_put(), too, eliminating this issue. But
that would mean that we couldn't detect possible other, actually broken
callers of scsi_device_put() any more, neither now nor in the future.

Perhaps we should introduce something like scsi_device_put_safe(), 
to be called only from contexts where we are certain that another
reference must exists? It's the only possibility I see, but it doesn't
feel quite right.

Regards
Martin