‘BUG: scheduling while atomic’ with crypto_alloc_hash
I am trying to use Linux kernel’s crypto libraries to calculate an HMAC value, given key and message. The idea is to calculate the HMAC and insert it in a TCP option during an iperf session (this part is not relevant). This is the function I wrote to use the crypto libraries, and it takes two keys of 8 bytes (to be combined) and a variable number of bytes composing the message:
void crypto_hmac_sha1(u8 *key_1, u8 *key_2, u32 *hash_out, int arg_num, . ) < struct crypto_ashash *shash; struct shash_desc *desc = NULL; const char hmac_alg[] = "hmac(sha1)"; u8 key[16]; int i; int ret; int length; u8 *msg; va_list list; /* Initialize result placeholder */ memset(hash_out, 0, sizeof(hash_out)); for (i = 0; i < 8; i++) key[i] ^= key_1[i]; for (i = 0; i < 8; i++) key[i + 8] ^= key_2[i]; printk("A1\n"); shash = crypto_alloc_ahash(hmac_alg, 0, 0); printk("A2\n"); desc = kzalloc(sizeof(*desc) + crypto_shash_descsize(shash), GFP_KERNEL); if (!desc) goto out; desc->tfm = shash; desc->flags = CRYPTO_TFM_REQ_MAY_SLEEP; ret = crypto_shash_setkey(shash, key, 16); if (ret < 0) goto out; crypto_shash_init(desc); for (i = 0; i < arg_num; i++) < length = va_arg(list, int); msg = va_arg(list, u8 *); ret = crypto_shash_update(desc, msg, length); if (ret < 0) goto out; >ret = crypto_shash_final(desc, hash_out); out: kfree(desc); > The error is the following (due to the fact that crypto_alloc_ahash tries to acquire a semaphore and it is not allowed in the current context):
BUG: scheduling while atomic: iperf/769/0x00000100 CPU: 0 PID: 769 Comm: iperf Not tainted 4.1.0-gdee0521-dirty #143 Received SIGSEGV in SIGSEGV handler, aborting stack trace! Ошибка: BUG: scheduling while atomic:
Проблема появляется при вызове функции wait_event_interruptible() в доморощенной функции read_wbuffs() при работе с tcp протоколом. Передача идет по защищенному каналу ipsec.
Функция wait_event_interruptible() используется для синхронизации с приемным буфером.
static ssize_t read_wbuffs(char *buf, size_t count, int fuser) < int flags; printk(KERN_INFO "======myrnd_read================\n"); if(!atomic_read(&(buff_data.buff_full))) < printk(KERN_ERR "sizeBuf empty wait\n"); if(wait_event_interruptible(buff_data.waitQueue,atomic_read(& (buff_data.rsrc)))) < atomic_set(&(buff_data.rsrc),0); return -ERESTARTSYS; // signal (tell to handle it) >atomic_set(&(buff_data.rsrc),0); > memcpy(buf, data_wbuf, count); atomic_set(&(buff_data.buff_full),0); atomic_set(&(buff_data.wsrc),1); wake_up_interruptible_all(&(buff_data.waitQueue)); wake_up_interruptible(&msk_sleep); return count; > Проявляется при работе с tcp протоколом, с udp всё ок!
На передающей стороне (проблемная) запускаю команду:
#nc -q1 10.1.101.125 6789 < ./text_out (стек вызовов tcp см. ниже), которая по протоколу tcp передает файл text_out
на приемной стороне, команда записывает его в файл text_in:
#nc -l -p 6789 > ./text_in
С udp:
#nc -u -q1 10.1.101.125 6789 < ./text_out (стек вызовов udp см. ниже).
#nc -u -l -p 6789 > ./text_in
[ 124.220724] Call Trace: [ 124.217139] ===========myrnd_read======================== [ 124.217143] sizeBuf empty wait [ 124.218839] BUG: scheduling while atomic: nc/2271/0x00000200 [ 124.220640] Modules linked in: my myiv myrndm loop snd_hda_codec_realtek snd_hda_intel snd_hda_codec i915 drm_kms_helper snd_hwdep drm snd_pcm snd_timer i2c_algo_bit i2c_i801 psmouse snd parport_pc evdev i2c_core serio_raw pcspkr parport soundcore rng_core video button processor snd_page_alloc output ext3 jbd mbcache sd_mod crc_t10dif ata_generic 8139too r8169 uhci_hcd ata_piix 8139cp ehci_hcd thermal mii libata scsi_mod usbcore nls_base thermal_sys [last unloaded: scsi_wait_scan] [ 124.220719] Pid: 2271, comm: nc Not tainted 2.6.32-debug #2 [ 124.220724] Call Trace: [ 124.220737] [] ? printk+0x18/0x1a [ 124.220746] [] __schedule_bug+0x58/0x5e [ 124.220755] [] schedule+0x44/0x3f4 [ 124.220766] [] read_wbuffs+0x8b/0x11b [myrndm] [ 124.220775] [] ? autoremove_wake_function+0x0/0x3d [ 124.220784] [] my_rndg+0x2a/0x34 [myrndm] [ 124.220793] [] myiv_aead_givencrypt+0xe0/0x139 [myiv] [ 124.220803] [] esp_output+0x2a1/0x2db [ 124.220812] [] xfrm_output_resume+0x249/0x2d6 [ 124.220822] [] ? sch_direct_xmit+0x45/0x12c [ 124.220830] [] xfrm_output2+0xd/0xf [ 124.220837] [] xfrm_output+0xa4/0xb8 [ 124.220845] [] xfrm4_output_finish+0x24/0x26 [ 124.220852] [] xfrm4_output+0x59/0x6a [ 124.220859] [] ? xfrm_dst_check+0x12/0x28 [ 124.220867] [] ip_local_out+0x18/0x1b [ 124.220874] [] ip_queue_xmit+0x285/0x2fb [ 124.220883] [] ? __slab_free+0x4d/0x20b [ 124.220892] [] ? ip_local_deliver+0x78/0x7e [ 124.220900] [] ? tcp_v4_md5_lookup+0xe/0x10 [ 124.220909] [] tcp_transmit_skb+0x5a8/0x5e8 [ 124.220917] [] tcp_write_xmit+0x73c/0x81b [ 124.220926] [] __tcp_push_pending_frames+0x30/0x81 [ 124.220934] [] tcp_rcv_established+0xe6/0x660 [ 124.220943] [] tcp_v4_do_rcv+0x154/0x2e5 [ 124.220953] [] release_sock+0x3a/0x99 [ 124.220960] [] tcp_sendmsg+0x85b/0x923 [ 124.220969] [] ? __generic_unplug_device+0x26/0x29 [ 124.220979] [] ? kmap_atomic_prot+0xa8/0xc8 [ 124.220988] [] sock_aio_write+0xfc/0x10b [ 124.220996] [] do_sync_write+0xaf/0xeb [ 124.221004] [] ? sys_connect+0x88/0xc3 [ 124.221013] [] ? ktime_get+0x6b/0xdf [ 124.221021] [] ? autoremove_wake_function+0x0/0x3d [ 124.221029] [] ? security_file_permission+0xf/0x11 [ 124.221037] [] ? rw_verify_area+0xb0/0xe4 [ 124.221044] [] vfs_write+0xa0/0x174 [ 124.221052] [] sys_write+0x38/0x63 [ 124.221060] [] sysenter_do_call+0x12/0x28 sys_write vfs_write do_sync_write sock_aio_write do_sock_write __sock_sendmsg inet_sendmsg udp_sendmsg release_sock udp_push_pending_frames ip_push_pending_frames ip_local_out dst_output xfrm4_output xfrm4_output_finish xfrm_output xfrm_output2 xfrm_output_one esp_output myiv_aead_givencrypt my_rndg read_wbuffs sys_write vfs_write do_sync_write sock_aio_write do_sock_write __sock_sendmsg tcp_sendmsg release_sock __release_sock sk_backlog_rcv tcp_v4_do_rcv tcp_rcv_established tcp_data_snd_check tcp_push_pending_frames _tcp_push_pending_frames tcp_write_xmit tcp_transmit_skb ip_queue_xmit ip_local_out dst_output xfrm4_output xfrm4_output_finish xfrm_output xfrm_output2 xfrm_output_resume xfrm_output_one esp_output myiv_aead_givencrypt my_rndg read_wbuff Bhanage.com
Why do you see that print
«Scheduling while atomic» indicates that you’ve tried to sleep somewhere that you shouldn’t — like within a spinlock-protected critical section or an interrupt handler.
1. In this case you should check if you are actually returning from some code that could cause the lock not to be released or actually sleeping in some part of the code.
2. Another error that may be spitted out during such a crash is :
BUG: workqueue leaked lock or atomic
This clearly indicates that you were not unlocking a certain lock, which could be typically caused by returning from a routine before the lock is released.
3. You are running something under a spinlock and it could not run to completion for some reason causing the kernel scheduler to be eventually invoked (schedule() ) with the spinlock still held.
These are few of the most popular reasons why you might see this print. If your kernel is configured to crash under such conditions, try and take a look at the backtrace which might hint towards what was running when this crash happened.
Why Are Some Actions/Contexts Atomic?
Some actions not «schedulable» in the kernel. This is because such actions do not have an associated task struct with which they can work off the scheduler.
Other valuable excerpts:
The might_sleep() function is supposed to be executed from within schedulable entities which are expected to sleep on a semaphore at some time during their execution. Therefore, functions which are expected to sleep at some point should include a call to might_sleep().
The only thing might_sleep does is print a stack trace for debug when called from within a non-schedulable entity. For schedulable entities, it does nothing.
BUG: Scheduling while atomic RAID_LAZY_WRITE/102/0x00000205
I am developing a raid system and I am getting following BUG when I issue lots of parallel IO. I am not able to figure out how to go about debugging this dump. It’s evident here that RAID_LAZY_WRITE thread is trying to schedule while it has locked the CPU but I am not able to trace it exactly how and why it’s happening. As I don’t acquire any lock to issue IO to block layer. I enabled spin lock debugging and lock dependency checking so that I could get detailed debug info. Here is the whole dump which I got, please provide me tips, ideas on how to analyze and debug using this dump.
BUG: scheduling while atomic: RAID_LAZY_WRITE/102/0x00000205 no locks held by RAID_LAZY_WRITE/102. Showing all locks held in the system: ============================================= Pid: 102, comm: RAID_LAZY_WRITE CPU: 0 Not tainted (2.6.24 #274) PC is at add_preempt_count+0xa0/0xbc LR is at raid_write_stripe+0x388/0x544 pc : [] lr : [] psr: 80000013 sp : cfc63ec4 ip : cfc63ed4 fp : cfc63ed0 r10: cf5ce118 r9 : 00000001 r8 : 000000b4 r7 : 00000001 r6 : cf403cd8 r5 : cfc62000 r4 : 00000002 r3 : 00000001 r2 : 00000001 r1 : cfc62000 r0 : 00000001 Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment kernel Control: 0000397f Table: 0f558000 DAC: 00000017 [] (show_regs+0x0/0x4c) from [] (__schedule_bug+0x54/0x68) r4:cfc9b0a0 [] (__schedule_bug+0x0/0x68) from [] (schedule+0x74/0x2f4) r5:cfc9b0a0 r4:c034d13c [] (schedule+0x0/0x2f4) from [] (io_schedule+0x30/0x54) [] (io_schedule+0x0/0x54) from [] (get_request_wait+0xac/0x140) r4:00000000 [] (get_request_wait+0x0/0x140) from [] (__make_request+0x478/0x544) [] (__make_request+0x0/0x544) from [] (generic_make_request+0x2a8/0x2f0) [] (generic_make_request+0x0/0x2f0) from [] (raid_submit_disk_io+0x348/0x37c) [] (raid_submit_disk_io+0x0/0x37c) from [] (perform_raid5_ops+0xdc8/0x1100) [] (perform_raid5_ops+0x0/0x1100) from [] (raid5_RCW_postXOR+0x438/0x4c4) [] (raid5_RCW_postXOR+0x0/0x4c4) from [] (raid5_xor_completed+0x2a4/0x3b0) [] (raid5_xor_completed+0x0/0x3b0) from [] (iop_adma_run_tx_complete_actions+0x64/0xe8) [] (iop_adma_run_tx_complete_actions+0x0/0xe8) from [] (__iop_adma_slot_cleanup+0x2f8/0x3c0) r8:c0352f24 r7:00000000 r6:00000000 r5:00000000 r4:cf4faa7c [] (__iop_adma_slot_cleanup+0x0/0x3c0) from [] (iop_adma_tasklet+0x10/0x14) [] (iop_adma_tasklet+0x0/0x14) from [] (run_timer_softirq+0x17c/0x208) [] (run_timer_softirq+0x0/0x208) from [] (__do_softirq+0x64/0xd0) [] (__do_softirq+0x0/0xd0) from [] (irq_exit+0x48/0x5c) [] (irq_exit+0x0/0x5c) from [] (__exception_text_start+0x48/0x60) [] (__exception_text_start+0x0/0x60) from [] (__irq_svc+0x50/0x7c) Exception stack(0xcfc63e7c to 0xcfc63ec4) 3e60: 00000001 3e80: cfc62000 00000001 00000001 00000002 cfc62000 cf403cd8 00000001 000000b4 3ea0: 00000001 cf5ce118 cfc63ed0 cfc63ed4 cfc63ec4 c015a83c c004b014 80000013 3ec0: ffffffff r6:00000020 r5:cfc63eb0 r4:ffffffff [] (add_preempt_count+0x0/0xbc) from [] (raid_write_stripe+0x388/0x544) [] (raid_write_stripe+0x0/0x544) from [] (raid_lazy_writer+0x4c4/0x6b8) [] (raid_lazy_writer+0x0/0x6b8) from [] (raid_thread_daemon+0x140/0x15c) [] (raid_thread_daemon+0x0/0x15c) from [] (kthread+0x58/0x90) [] (kthread+0x0/0x90) from [] (do_exit+0x0/0x764) r6:00000000 r5:00000000 r4:00000000 BUG: spinlock cpu recursion on CPU#0, RAID_DAEMON/101 lock: cf4faae0, .magic: dead4ead, .owner: RAID_LAZY_WRITE/102, .owner_cpu: 0 [] (dump_stack+0x0/0x14) from [] (spin_bug+0x90/0xa4) [] (spin_bug+0x0/0xa4) from [] (_raw_spin_lock+0x68/0x15c) r5:c01fb378 r4:cf4faae0 [] (_raw_spin_lock+0x0/0x15c) from [] (_spin_lock_bh+0x4c/0x54) [] (_spin_lock_bh+0x0/0x54) from [] (iop_adma_run_tx_complete_actions+0x38/0xe8) r5:00000000 r4:cf4faa7c [] (iop_adma_run_tx_complete_actions+0x0/0xe8) from [] (__iop_adma_slot_cleanup+0x2f8/0x3c0) r8:00000001 r7:00000000 r6:00000000 r5:00000000 r4:cf4faa7c [] (__iop_adma_slot_cleanup+0x0/0x3c0) from [] (iop_adma_tasklet+0x10/0x14) [] (iop_adma_tasklet+0x0/0x14) from [] (tasklet_action+0x8c/0xe4) [] (tasklet_action+0x0/0xe4) from [] (__do_softirq+0x64/0xd0) r6:0000000a r5:00000001 r4:c0351f44 [] (__do_softirq+0x0/0xd0) from [] (irq_exit+0x48/0x5c) [] (irq_exit+0x0/0x5c) from [] (__exception_text_start+0x48/0x60) [] (__exception_text_start+0x0/0x60) from [] (__irq_svc+0x50/0x7c) Exception stack(0xcfcb1e64 to 0xcfcb1eac) 1e60: cf652404 00000001 ffffffff 00000001 cf652404 40000013 c0417bec 1e80: 7fffffff cea81d88 00000000 cf6523e0 cfcb1ec0 cfcb1eac cfcb1eac c0298d00 1ea0: c0298d04 60000013 ffffffff r6:00000064 r5:cfcb1e98 r4:ffffffff [] (_spin_unlock_irqrestore+0x0/0x54) from [] (raid_read_stripe+0x204/0x560) r5:00000008 r4:cf652404 [] (raid_read_stripe+0x0/0x560) from [] (raid_daemon+0x1d4/0x1110) [] (raid_daemon+0x0/0x1110) from [] (raid_thread_daemon+0x140/0x15c) [] (raid_thread_daemon+0x0/0x15c) from [] (kthread+0x58/0x90) [] (kthread+0x0/0x90) from [] (do_exit+0x0/0x764) r6:00000000 r5:00000000 r4:00000000