search

IRATI / stack

RINA implementation for OS/Linux
http://irati.github.io/stack
73 stars 39 forks source link

rnl_ipcm_sock_closed_notif_msg bangs the kernel #212

Closed kewinrausch closed 9 years ago

kewinrausch commented 9 years ago

Issue by salvestrini Friday Nov 15, 2013 at 11:20 GMT Originally opened as https://github.com/dana-i2cat/irati/issues/209

/serio1/input/input5 [ 20.029367] microcode: CPU1 sig=0x306a9, pf=0x1, revision=0x0 [ 20.056049] microcode: Microcode Update Driver: v2.00 tigran@aivazian.fsnet.co.uk, Peter Oruba [ 20.379466] echo (561) used greatest stack depth: 2960 bytes left [ 22.939678] Adding 392188k swap on /dev/sda5. Priority:-1 extents:1 across:392188k FS [ 23.124162] EXT4-fs (sda1): re-mounted. Opts: (null) [ 23.552539] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro [ 31.724847] ip (1646) used greatest stack depth: 2912 bytes left [ 32.212039] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX [ 33.444032] RPC: Registered named UNIX socket transport module. [ 33.444032] RPC: Registered udp transport module. [ 33.444032] RPC: Registered tcp transport module. [ 33.444032] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 33.520927] mv (1761) used greatest stack depth: 2688 bytes left [ 33.544057] FS-Cache: Loaded [ 33.948022] FS-Cache: Netfs 'nfs' registered for caching [ 34.264316] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 37.842696] rc (231) used greatest stack depth: 2672 bytes left [ 63.048048] rina-personality-default: Rina default personality loading [ 63.048048] rina-personality-default: Finally registering personality [ 63.048048] rina-personality: Checking name [ 63.048048] rina-personality: Name is ok [ 63.048048] rina-personality: Checking ops ffffffffa01ae040 [ 63.048048] rina-personality: Ops are ok [ 63.048048] rina-personality: Registering personality 'default' [ 63.048048] rina-personality: Calling personality 'default' initializer [ 63.048048] rina-personality-default: Initializing default personality [ 63.048048] rina-personality-default: Initializing KFA [ 63.048048] rina-pidm: Instance initialized successfully (2048 bits) [ 63.048048] rina-personality-default: Initializing RNL [ 63.048048] rina-rnl: Set ffff880038a2af88 created successfully [ 63.048048] rina-personality-default: Initializing KIPCM [ 63.048048] rina-kipcm: Initializing [ 63.048048] rina-ipcp-factories: Initializing layer [ 63.048518] rina-ipcp-factories: Layer initialized successfully [ 63.048518] rina-pidm: Instance initialized successfully (2048 bits) [ 63.048518] rina-rnl: Set ffff880038a2af88 registered [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7f10 and data ffff88001acf9b60 for message type 1 [ 63.048518] rina-rnl: Handler ffffffffa01a7f10 (data ffff88001acf9b60) registered for message type 1 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a8350 and data ffff88001acf9b60 for message type 3 [ 63.048518] rina-rnl: Handler ffffffffa01a8350 (data ffff88001acf9b60) registered for message type 3 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a85a0 and data ffff88001acf9b60 for message type 11 [ 63.048518] rina-rnl: Handler ffffffffa01a85a0 (data ffff88001acf9b60) registered for message type 11 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7c90 and data ffff88001acf9b60 for message type 14 [ 63.048518] rina-rnl: Handler ffffffffa01a7c90 (data ffff88001acf9b60) registered for message type 14 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7450 and data ffff88001acf9b60 for message type 15 [ 63.048518] rina-rnl: Handler ffffffffa01a7450 (data ffff88001acf9b60) registered for message type 15 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a79d0 and data ffff88001acf9b60 for message type 18 [ 63.048518] rina-rnl: Handler ffffffffa01a79d0 (data ffff88001acf9b60) registered for message type 18 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7710 and data ffff88001acf9b60 for message type 20 [ 63.048518] rina-rnl: Handler ffffffffa01a7710 (data ffff88001acf9b60) registered for message type 20 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7390 and data ffff88001acf9b60 for message type 29 [ 63.048518] rina-rnl: Handler ffffffffa01a7390 (data ffff88001acf9b60) registered for message type 29 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a7180 and data ffff88001acf9b60 for message type 30 [ 63.048518] rina-rnl: Handler ffffffffa01a7180 (data ffff88001acf9b60) registered for message type 30 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a6f40 and data ffff88001acf9b60 for message type 32 [ 63.048518] rina-rnl: Handler ffffffffa01a6f40 (data ffff88001acf9b60) registered for message type 32 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a6d60 and data ffff88001acf9b60 for message type 34 [ 63.048518] rina-rnl: Handler ffffffffa01a6d60 (data ffff88001acf9b60) registered for message type 34 [ 63.048518] rina-rnl: Registering handler callback ffffffffa01a6b80 and data ffff88001acf9b60 for message type 36 [ 63.048518] rina-rnl: Handler ffffffffa01a6b80 (data ffff88001acf9b60) registered for message type 36 [ 63.048518] rina-kipcm: NL handlers registered successfully [ 63.048518] rina-kipcm: Initialized successfully [ 63.048518] rina-personality-default: Default personality initialized successfully [ 63.048518] rina-personality: Personality 'default' initialized successfully [ 63.048518] rina-personality: Default personality set to 'default' [ 63.048518] rina-personality: Personality 'default' registered successfully [ 63.048518] rina-personality-default: Rina default personality loaded successfully [ 63.059948] rina-ipcp-factories: Registering new factory [ 63.059948] rina-ipcp-factories: Checking name [ 63.059948] rina-ipcp-factories: Name is ok [ 63.059948] rina-ipcp-factories: Checking ops [ 63.059948] rina-ipcp-factories: Ops are ok [ 63.059948] rina-ipcp-factories: Checking name [ 63.059948] rina-ipcp-factories: Name is ok [ 63.059948] rina-ipcp-factories: Registering factory 'shim-dummy' [ 63.059948] rina-utils: Workqueue 'dummy-wq' (ffff88001b3fc000) created successfully [ 63.059948] rina-ipcp-factories: Factory 'shim-dummy' registered successfully [ 74.424291] rina-rnl: Dispatching message (skb-in=ffff88001a652fc0, info=ffff88001a6f19b0) [ 74.424291] rina-rnl: Multiplexing message type 29 [ 74.424291] rina-rnl: Fetching handler callback and data [ 74.424291] rina-kipcm: IPC Manager started. It is listening at NL port-id 1 [ 74.424291] rina-rnl: Message 29 handled successfully [ 74.436037] rina-ipcp-utils: Name at ffff88001decdc20 finalized successfully [ 74.436037] rina-utils: String size is 0, cannot strdup-from-user [ 74.436037] rina-ipcp-utils: Cannot duplicate source string from user-space [ 74.436037] rina-ipcp-utils: Name at ffff88001decdc20 finalized successfully [ 74.436037] rina-ipcp-utils: Name at ffff88001decdc20 finalized successfully [ 74.436037] rina-ipcp-utils: Name at ffff88001decdc20 destroyed successfully [ 74.620042] rina-rnl: IPC Manager port: 1 [ 74.620042] rina-rnl-utils: Result of genlmesg_end: 32 [ 74.620042] BUG: sleeping function called from invalid context at mm/slub.c:926 [ 74.620042] in_atomic(): 1, irqs_disabled(): 0, pid: 2713, name: sshd [ 74.622163] 1 lock held by sshd/2713: [ 74.622163] #3: (rcu_read_lock){.+.+.+}, at: [] atomic_notifier_call_chain+0x5/0xc0 [ 74.622163] CPU: 1 PID: 2713 Comm: sshd Tainted: G W 3.10.0 #1009 [ 74.622163] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 74.622163] ffff88003f402b40 ffff88003c283b18 ffffffff816c1f81 ffff88003c283b38 [ 74.622163] ffffffff81078647 ffff88003f402b40 0000000000000010 ffff88003c283bc8 [ 74.622163] ffffffff8118394f 0000000000000000 ffffffff81c33518 ffff88003c283b88 [ 74.622163] Call Trace: [ 74.622163] [] dump_stack+0x19/0x1b [ 74.622163] [] might_sleep+0xe7/0x110 [ 74.622163] [] kmalloc_node_track_caller+0x6f/0x290 [ 74.622163] [] ? pskb_expand_head+0x6b/0x2e0 [ 74.622163] [] __kmalloc_reserve.isra.51+0x3c/0xa0 [ 74.622163] [] ? vprintk_emit+0x1ce/0x5c0 [ 74.622163] [] pskb_expand_head+0x6b/0x2e0 [ 74.622163] [] ? trace_hardirqs_on+0xd/0x10 [ 74.622163] [] netlink_trim+0x7f/0xc0 [ 74.622163] [] netlink_unicast+0x48/0x1e0 [ 74.622163] [] ? printk+0x61/0x63 [ 74.622163] [] send_nl_unicast_msg.constprop.44+0x3e/0xa0 [ 74.622163] [] rnl_ipcm_sock_closed_notif_msg+0xb8/0x120 [ 74.622163] [] kipcm_netlink_notify+0x6a/0xa0 [ 74.622163] [] ? skb_dequeue+0x67/0x90 [ 74.622163] [] notifier_call_chain+0x4d/0x70 [ 74.622163] [] atomic_notifier_call_chain+0x82/0xc0 [ 74.622163] [] ? atomic_notifier_call_chain+0x5/0xc0 [ 74.622163] [] atomic_notifier_call_chain+0x16/0x20 [ 74.622163] [] netlink_release+0x282/0x2c0 [ 74.622163] [] sock_release+0x28/0x90 [ 74.622163] [] sock_close+0x12/0x20 [ 74.622163] [] fput+0xd3/0x260 [ 74.622163] [] ? close_fd+0x80/0xb0 [ 74.622163] [] __fput+0xe/0x10 [ 74.622163] [] task_work_run+0xb4/0xe0 [ 74.622163] [] do_notify_resume+0xaa/0xc0 [ 74.622163] [] int_signal+0x12/0x17 [ 74.622163] BUG: scheduling while atomic: sshd/2713/0x10000002 [ 74.622163] 1 lock held by sshd/2713: [ 74.622163] #3: (rcu_read_lock){.+.+.+}, at: [] atomic_notifier_call_chain+0x5/0xc0 [ 74.622163] Modules linked in: shim_dummy rina_personality_default nfsd auth_rpcgss oid_registry nfs_acl nfs lockd fscache sunrpc psmouse serio_raw microcode pcspkr i2c_piix4 hid_generic usbhid hid ahci libahci e1000 [ 74.622163] CPU: 1 PID: 2713 Comm: sshd Tainted: G W 3.10.0 #1009 [ 74.622163] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 74.622163] 0000000000000001 ffff88003c283a68 ffffffff816c1f81 ffff88003c283a88 [ 74.622163] ffffffff816bcce2 0000000000000000 ffff88003fbd4000 ffff88003c283b08 [ 74.622163] ffffffff816c9085 ffff88003f9fffc0 000000000000000b ffff880031878000 [ 74.622163] Call Trace: [ 74.622163] [] dump_stack+0x19/0x1b [ 74.622163] [] __schedule_bug+0x63/0x73 [ 74.622163] [] schedule+0x7e5/0x8a0 [ 74.622163] [] cond_resched+0x2a/0x40 [ 74.622163] [] _cond_resched+0x32/0x40 [ 74.622163] [] __kmalloc_node_track_caller+0x74/0x290 [ 74.622163] [] ? pskb_expand_head+0x6b/0x2e0 [ 74.622163] [] kmalloc_reserve.isra.51+0x3c/0xa0 [ 74.622163] [] ? vprintk_emit+0x1ce/0x5c0 [ 74.622163] [] pskb_expand_head+0x6b/0x2e0 [ 74.622163] [] ? trace_hardirqs_on+0xd/0x10 [ 74.622163] [] netlink_trim+0x7f/0xc0 [ 74.622163] [] netlink_unicast+0x48/0x1e0 [ 74.622163] [] ? printk+0x61/0x63 [ 74.622163] [] send_nl_unicast_msg.constprop.44+0x3e/0xa0 [ 74.622163] [] rnl_ipcm_sock_closed_notif_msg+0xb8/0x120 [ 74.622163] [] kipcm_netlink_notify+0x6a/0xa0 [ 74.622163] [] ? skb_dequeue+0x67/0x90 [ 74.622163] [] notifier_call_chain+0x4d/0x70 [ 74.622163] [] atomic_notifier_call_chain+0x82/0xc0 [ 74.622163] [] ? __atomic_notifier_call_chain+0x5/0xc0 [ 74.622163] [] atomic_notifier_call_chain+0x16/0x20 [ 74.622163] [] netlink_release+0x282/0x2c0 [ 74.622163] [] sock_release+0x28/0x90 [ 74.622163] [] sock_close+0x12/0x20 [ 74.622163] [] fput+0xd3/0x260 [ 74.622163] [] ? close_fd+0x80/0xb0 [ 74.622163] [] __fput+0xe/0x10 [ 74.622163] [] task_work_run+0xb4/0xe0 [ 74.622163] [] do_notify_resume+0xaa/0xc0 [ 74.622163] [] int_signal+0x12/0x17 [ 74.622163] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1 [ 74.622163] rina-rnl: IPC Manager port: 1 [ 74.622163] rina-rnl-utils: Result of genlmesg_end: 32 [ 74.622163] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1 [ 75.196058] rina-rnl: IPC Manager port: 1 [ 75.196058] rina-rnl-utils: Result of genlmesg_end: 32 [ 75.196058] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1 [ 75.288499] rina-rnl: IPC Manager port: 1 [ 75.288499] rina-rnl-utils: Result of genlmesg_end: 32 [ 75.289098] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1 [ 75.289098] rina-rnl: IPC Manager port: 1 [ 75.289098] rina-rnl-utils: Result of genlmesg_end: 32 [ 75.289098] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1 [ 77.132042] rina-rnl: IPC Manager port: 1 [ 77.132042] rina-rnl-utils: Result of genlmesg_end: 32 [ 77.132042] BUG: sleeping function called from invalid context at mm/slub.c:926 [ 77.132042] in_atomic(): 1, irqs_disabled(): 0, pid: 2719, name: sshd [ 77.132042] 1 lock held by sshd/2719: [ 77.132042] #3: (rcu_read_lock){.+.+.+}, at: [] atomic_notifier_call_chain+0x5/0xc0 [ 77.132042] CPU: 0 PID: 2719 Comm: sshd Tainted: G W 3.10.0 #1009 [ 77.132042] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 77.132042] ffff88003f402b40 ffff88001a861b18 ffffffff816c1f81 ffff88001a861b38 [ 77.132042] ffffffff81078647 ffff88003f402b40 0000000000000010 ffff88001a861bc8 [ 77.132042] ffffffff8118394f 0000000000000000 ffffffff81c33518 ffff88001a861b88 [ 77.132042] Call Trace: [ 77.132042] [] dump_stack+0x19/0x1b [ 77.132042] [] __might_sleep+0xe7/0x110 [ 77.132042] [] kmalloc_node_track_caller+0x6f/0x290 [ 77.132042] [] ? pskb_expand_head+0x6b/0x2e0 [ 77.132042] [] kmalloc_reserve.isra.51+0x3c/0xa0 [ 77.132042] [] ? vprintk_emit+0x1ce/0x5c0 [ 77.132042] [] pskb_expand_head+0x6b/0x2e0 [ 77.132042] [] ? trace_hardirqs_on+0xd/0x10 [ 77.132042] [] netlink_trim+0x7f/0xc0 [ 77.132042] [] netlink_unicast+0x48/0x1e0 [ 77.132042] [] ? printk+0x61/0x63 [ 77.132042] [] send_nl_unicast_msg.constprop.44+0x3e/0xa0 [ 77.132042] [] rnl_ipcm_sock_closed_notif_msg+0xb8/0x120 [ 77.132042] [] kipcm_netlink_notify+0x6a/0xa0 [ 77.132042] [] ? skb_dequeue+0x67/0x90 [ 77.132042] [] notifier_call_chain+0x4d/0x70 [ 77.132042] [] __atomic_notifier_call_chain+0x82/0xc0 [ 77.132042] [] ? atomic_notifier_call_chain+0x5/0xc0 [ 77.132042] [] atomic_notifier_call_chain+0x16/0x20 [ 77.132042] [] netlink_release+0x282/0x2c0 [ 77.132042] [] sock_release+0x28/0x90 [ 77.132042] [] sock_close+0x12/0x20 [ 77.132042] [] fput+0xd3/0x260 [ 77.132042] [] ? close_fd+0x80/0xb0 [ 77.132042] [] ____fput+0xe/0x10 [ 77.132042] [] task_work_run+0xb4/0xe0 [ 77.132042] [] do_notify_resume+0xaa/0xc0 [ 77.132042] [] int_signal+0x12/0x17 [ 77.132042] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1

kewinrausch commented 9 years ago

Comment by salvestrini Monday Nov 18, 2013 at 13:28 GMT

Another log. modprobe-d shim-dummy, run the ipcmanager and this is what I get:

[ 282.567814] rina-rnl-utils: NL unicast message sent (result = 0) [ 282.567815] rina-rnl: Message 1 handled successfully [ 297.080994] rina-rnl: IPC Manager port: 1 [ 297.081036] rina-rnl-utils: Result of genlmesg_end: 32 [ 297.081044] BUG: sleeping function called from invalid context at mm/slub.c:926 [ 297.081603] in_atomic(): 1, irqs_disabled(): 0, pid: 2779, name: sshd [ 297.082086] 1 lock held by sshd/2779: [ 297.082088] #3: (rcu_read_lock){.+.+.+}, at: [] atomic_notifier_call_chain+0x5/0xc0 [ 297.082101] CPU: 0 PID: 2779 Comm: sshd Not tainted 3.10.0 #1026 [ 297.082103] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 297.082105] ffff88003f402b40 ffff88002416db18 ffffffff816c22b1 ffff88002416db38 [ 297.082110] ffffffff81078647 ffff88003f402b40 0000000000000010 ffff88002416dbc8 [ 297.082114] ffffffff8118394f 0000000000000000 ffffffff81c33518 ffff88002416db88 [ 297.082118] Call Trace: [ 297.082123] [] dump_stack+0x19/0x1b [ 297.082136] [] might_sleep+0xe7/0x110 [ 297.082141] [] kmalloc_node_track_caller+0x6f/0x290 [ 297.082146] [] ? pskb_expand_head+0x6b/0x2e0 [ 297.082150] [] __kmalloc_reserve.isra.51+0x3c/0xa0 [ 297.082156] [] ? vprintk_emit+0x1ce/0x5c0 [ 297.082159] [] pskb_expand_head+0x6b/0x2e0 [ 297.082163] [] ? trace_hardirqs_on+0xd/0x10 [ 297.082166] [] netlink_trim+0x7f/0xc0 [ 297.082170] [] netlink_unicast+0x48/0x1e0 [ 297.082175] [] ? printk+0x61/0x63 [ 297.082179] [] send_nl_unicast_msg.constprop.44+0x3e/0xa0 [ 297.082183] [] rnl_ipcm_sock_closed_notif_msg+0xb8/0x120 [ 297.082187] [] kipcm_netlink_notify+0x6a/0xa0 [ 297.082190] [] ? skb_dequeue+0x67/0x90 [ 297.082193] [] notifier_call_chain+0x4d/0x70 [ 297.082197] [] atomic_notifier_call_chain+0x82/0xc0 [ 297.082201] [] ? atomic_notifier_call_chain+0x5/0xc0 [ 297.082205] [] atomic_notifier_call_chain+0x16/0x20 [ 297.082208] [] netlink_release+0x282/0x2c0 [ 297.082212] [] sock_release+0x28/0x90 [ 297.082215] [] sock_close+0x12/0x20 [ 297.082219] [] fput+0xd3/0x260 [ 297.082223] [] ? close_fd+0x80/0xb0 [ 297.082226] [] __fput+0xe/0x10 [ 297.082231] [] task_work_run+0xb4/0xe0 [ 297.082236] [] do_notify_resume+0xaa/0xc0 [ 297.082240] [] int_signal+0x12/0x17 [ 297.082305] rina-rnl-utils: Sent NL unicast msg of type 28 with seq num 0 to 1