BUG in slab_free after iSCSI login timeout

BUG in slab_free after iSCSI login timeout

[Vincent Pelletier]

Hello,

I am getting the following BUG with a Windows 10 initiator and a
Debian sid LIO iSCSI target:

Aug 11 11:28:28 boke kernel: [  141.536023] iSCSI Login timeout on Network Portal [::]:3260
Aug 11 11:28:28 boke kernel: [  141.536164] iSCSI Login negotiation failed.
Aug 11 11:28:28 boke kernel: [  141.536247] ------------[ cut here ]------------
Aug 11 11:28:28 boke kernel: [  141.536250] kernel BUG at /build/linux-0buYvw/linux-4.17.8/mm/slub.c:296!
Aug 11 11:28:28 boke kernel: [  141.536362] invalid opcode: 0000 [#1] SMP PTI
Aug 11 11:28:28 boke kernel: [  141.536432] Modules linked in: target_core_user uio target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_mod configfs hid_generic usbhid uas usb_storage snd_hda_codec_hdmi spi_pxa2xx_platform evdev intel_rapl intel_soc_dts_thermal intel_soc_dts_iosf intel_powerclamp coretemp kvm_intel i915 kvm drm_kms_helper drm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel intel_cstate snd_hda_codec efi_pstore pcspkr efivars snd_hda_core snd_hwdep snd_pcm sg snd_timer iTCO_wdt iTCO_vendor_support snd ir_rc6_decoder soundcore spi_pxa2xx_pci shpchp rc_rc6_mce fintek_cir rc_core video pwm_lpss_platform pwm_lpss button gpio_keys_polled(O) input_polldev leds_gpio nfsd auth_rpcgss nfs_acl lockd grace sunrpc gpio_f7188x(O) qnap_tsx51(O) ledtrig_timer f71882fg efivarfs
Aug 11 11:28:28 boke kernel: [  141.537528]  ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb crypto_simd cryptd glue_helper aes_x86_64 dm_mod raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c crc32c_generic raid0 multipath linear raid1 md_mod sd_mod crc32c_intel lpc_ich i2c_i801 igb i2c_algo_bit dca ahci libahci libata xhci_pci xhci_hcd i2c_designware_pci scsi_mod usbcore usb_common sdhci_pci cqhci sdhci mmc_core i2c_hid hid thermal fan
Aug 11 11:28:28 boke kernel: [  141.538191] CPU: 0 PID: 992 Comm: iscsi_np Tainted: G           O      4.17.0-1-amd64 #1 Debian 4.17.8-1
Aug 11 11:28:28 boke kernel: [  141.538333] Hardware name: To be filled by O.E.M. To be filled by O.E.M./Aptio CRB, BIOS 5.6.5 05/19/2014
Aug 11 11:28:28 boke kernel: [  141.538481] RIP: 0010:__slab_free+0x18a/0x300
Aug 11 11:28:28 boke kernel: [  141.538550] RSP: 0018:ffffb44380a57dd0 EFLAGS: 00010246
Aug 11 11:28:28 boke kernel: [  141.538633] RAX: ffff9c6f36dfbc00 RBX: ffff9c6f36dfbc00 RCX: 000000018010000e
Aug 11 11:28:28 boke kernel: [  141.538744] RDX: ffff9c6f36dfbc00 RSI: ffffe52004db7e80 RDI: ffff9c6f3b003080
Aug 11 11:28:28 boke kernel: [  141.538851] RBP: ffffb44380a57e70 R08: 0000000000000001 R09: ffffffffc0ca83c6
Aug 11 11:28:28 boke kernel: [  141.541763] R10: ffffe52004db7e80 R11: 00000000ffffffff R12: ffff9c6f3b003080
Aug 11 11:28:28 boke kernel: [  141.544714] R13: ffffe52004db7e80 R14: ffff9c6f36dfbc00 R15: 0000000000000000
Aug 11 11:28:28 boke kernel: [  141.547638] FS:  0000000000000000(0000) GS:ffff9c6f3fc00000(0000) knlGS:0000000000000000
Aug 11 11:28:28 boke kernel: [  141.550593] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 11 11:28:28 boke kernel: [  141.553496] CR2: 00007f3331ff3300 CR3: 000000000aa0a000 CR4: 00000000001006f0
Aug 11 11:28:28 boke kernel: [  141.556422] Call Trace:
Aug 11 11:28:28 boke kernel: [  141.559290]  ? vprintk_emit+0x3e4/0x450
Aug 11 11:28:28 boke kernel: [  141.562112]  ? __slab_free+0x15a/0x300
Aug 11 11:28:28 boke kernel: [  141.564861]  ? printk+0x52/0x6e
Aug 11 11:28:28 boke kernel: [  141.567531]  ? iscsi_target_login_sess_out+0x1e6/0x240 [iscsi_target_mod]
Aug 11 11:28:28 boke kernel: [  141.570233]  iscsi_target_login_sess_out+0x1e6/0x240 [iscsi_target_mod]
Aug 11 11:28:28 boke kernel: [  141.572897]  iscsi_target_login_thread+0x432/0xff0 [iscsi_target_mod]
Aug 11 11:28:28 boke kernel: [  141.575488]  ? iscsi_target_login_sess_out+0x240/0x240 [iscsi_target_mod]
Aug 11 11:28:28 boke kernel: [  141.578027]  kthread+0x113/0x130
Aug 11 11:28:28 boke kernel: [  141.580483]  ? kthread_create_worker_on_cpu+0x70/0x70
Aug 11 11:28:28 boke kernel: [  141.582904]  ret_from_fork+0x35/0x40
Aug 11 11:28:28 boke kernel: [  141.585239] Code: fe ff ff 44 0f b6 bd 7f ff ff ff 80 7d ab 00 79 05 45 84 ff 74 7b 48 83 c4 78 5b 41 5c 41 5d 41 5e 41 5f 5d 49 8d 65 f0 41 5d c3 <0f> 0b 4c 89 d0 4c 89 55 88 45 89 fa 48 85 c0 44 0f b6 bd 7f ff
Aug 11 11:28:28 boke kernel: [  141.592324] RIP: __slab_free+0x18a/0x300 RSP: ffffb44380a57dd0
Aug 11 11:28:28 boke kernel: [  141.594641] ---[ end trace 6ee2f89117f24b05 ]---

I had this issue several times, but the way to reproduce is not clear
to me yet. It seems it fails especially when initiator is up before
server, but it is not strictly required either.

What can I try to help debug this further ?

Side notes:
Of the 3 out-of-tree modules, 2 are actually from-tree (but not build
in default debian sid kernels): gpio_keys_polled gpio_f7188x, and one is
actually out-of-tree (qnap_tsx51), although it should be trivially
valid (static data structure describing a few gpios, with attached leds
and buttons, as firmware does not describe these):
  https://github.com/vpelletier/linux/blob/4fc287fee9846bbfbb356ea161578342f5672a12/drivers/platform/x86/qnap-tsx51.c

Regards,
-- 
Vincent Pelletier

Re: BUG in slab_free after iSCSI login timeout

[Bart Van Assche]

On Sat, 2018-08-11 at 09:36 +-0000, Vincent Pelletier wrote:
+AD4- What can I try to help debug this further ?

Can you try to reproduce this with KASAN enabled in the kernel config?

Thanks,

Bart.

Re: BUG in slab_free after iSCSI login timeout

[Vincent Pelletier]

On Sat, 11 Aug 2018 22:50:12 +0000, Bart Van Assche
<Bart.VanAssche@wdc.com> wrote:
> On Sat, 2018-08-11 at 09:36 +0000, Vincent Pelletier wrote:
> > What can I try to help debug this further ?  
> 
> Can you try to reproduce this with KASAN enabled in the kernel config?

Here is the syslog with KASAN enabled:

Aug 12 04:44:53 boke kernel: [   64.736033] iSCSI Login timeout on Network Portal [::]:3260
Aug 12 04:44:53 boke kernel: [   64.736449] iSCSI Login negotiation failed.
Aug 12 04:44:53 boke kernel: [   64.736653] =================================
Aug 12 04:44:53 boke kernel: [   64.737069] BUG: KASAN: use-after-free in iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.737515] Read of size 8 at addr ffff880113ca6bc8 by task iscsi_np/992
Aug 12 04:44:53 boke kernel: [   64.737814]
Aug 12 04:44:53 boke kernel: [   64.737914] CPU: 0 PID: 992 Comm: iscsi_np Tainted: G           O      4.17.8kasan #1
Aug 12 04:44:53 boke kernel: [   64.737920] Hardware name: To be filled by O.E.M. To be filled by O.E.M./Aptio CRB, BIOS 5.6.5 05/19/2014
Aug 12 04:44:53 boke kernel: [   64.737924] Call Trace:
Aug 12 04:44:53 boke kernel: [   64.737945]  dump_stack+0x71/0xac
Aug 12 04:44:53 boke kernel: [   64.737961]  print_address_description+0x65/0x22e
Aug 12 04:44:53 boke kernel: [   64.738054]  ? iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738066]  kasan_report.cold.6+0x241/0x2fd
Aug 12 04:44:53 boke kernel: [   64.738157]  iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738246]  iscsi_target_login_thread+0x10c4/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738264]  ? __sched_text_start+0x8/0x8
Aug 12 04:44:53 boke kernel: [   64.738349]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738361]  ? __kthread_parkme+0xcc/0x100
Aug 12 04:44:53 boke kernel: [   64.738374]  ? parse_args.cold.14+0xd3/0xd3
Aug 12 04:44:53 boke kernel: [   64.738460]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738478]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.738491]  ? kthread_bind+0x30/0x30
Aug 12 04:44:53 boke kernel: [   64.738502]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.738510]
Aug 12 04:44:53 boke kernel: [   64.738600] Allocated by task 992:
Aug 12 04:44:53 boke kernel: [   64.738772]  kasan_kmalloc+0xbf/0xe0
Aug 12 04:44:53 boke kernel: [   64.738782]  kmem_cache_alloc_trace+0x112/0x210
Aug 12 04:44:53 boke kernel: [   64.738865]  iscsi_target_login_thread+0x844/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.738875]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.738884]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.738887]
Aug 12 04:44:53 boke kernel: [   64.738973] Freed by task 992:
Aug 12 04:44:53 boke kernel: [   64.739129]  __kasan_slab_free+0x125/0x170
Aug 12 04:44:53 boke kernel: [   64.739137]  kfree+0x90/0x1d0
Aug 12 04:44:53 boke kernel: [   64.739220]  iscsi_target_login_thread+0x15c7/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.739230]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.739239]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.739241]
Aug 12 04:44:53 boke kernel: [   64.739330] The buggy address belongs to the object at ffff880113ca6a00
Aug 12 04:44:53 boke kernel: [   64.739330]  which belongs to the cache kmalloc-512 of size 512
Aug 12 04:44:53 boke kernel: [   64.739877] The buggy address is located 456 bytes inside of
Aug 12 04:44:53 boke kernel: [   64.739877]  512-byte region [ffff880113ca6a00, ffff880113ca6c00)
Aug 12 04:44:53 boke kernel: [   64.740385] The buggy address belongs to the page:
Aug 12 04:44:53 boke kernel: [   64.740611] page:ffffea00044f2980 count:1 mapcount:0 mapping:0000000000000000 index:0x0 compound_mapcount: 0
Aug 12 04:44:53 boke kernel: [   64.741053] flags: 0x17fffc000008100(slab|head)
Aug 12 04:44:53 boke kernel: [   64.741273] raw: 017fffc000008100 0000000000000000 0000000000000000 00000001000c000c
Aug 12 04:44:53 boke kernel: [   64.741626] raw: dead000000000100 dead000000000200 ffff88011b002e00 0000000000000000
Aug 12 04:44:53 boke kernel: [   64.741971] page dumped because: kasan: bad access detected
Aug 12 04:44:53 boke kernel: [   64.742222]
Aug 12 04:44:53 boke kernel: [   64.742304] Memory state around the buggy address:
Aug 12 04:44:53 boke kernel: [   64.742531]  ffff880113ca6a80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.742858]  ffff880113ca6b00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.747255] >ffff880113ca6b80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.751156]                                               ^
Aug 12 04:44:53 boke kernel: [   64.755081]  ffff880113ca6c00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
Aug 12 04:44:53 boke kernel: [   64.758397]  ffff880113ca6c80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.762372] =================================
Aug 12 04:44:53 boke kernel: [   64.768126] Disabling lock debugging due to kernel taint
Aug 12 04:44:53 boke kernel: [   64.768226] =================================
Aug 12 04:44:53 boke kernel: [   64.771148] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.776782]
Aug 12 04:44:53 boke kernel: [   64.779480] CPU: 0 PID: 992 Comm: iscsi_np Tainted: G    B      O      4.17.8kasan #1
Aug 12 04:44:53 boke kernel: [   64.779483] Hardware name: To be filled by O.E.M. To be filled by O.E.M./Aptio CRB, BIOS 5.6.5 05/19/2014
Aug 12 04:44:53 boke kernel: [   64.779486] Call Trace:
Aug 12 04:44:53 boke kernel: [   64.779499]  dump_stack+0x71/0xac
Aug 12 04:44:53 boke kernel: [   64.779508]  print_address_description+0x65/0x22e
Aug 12 04:44:53 boke kernel: [   64.779555]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779562]  kasan_report_invalid_free+0x65/0xa0
Aug 12 04:44:53 boke kernel: [   64.779609]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779614]  __kasan_slab_free+0x157/0x170
Aug 12 04:44:53 boke kernel: [   64.779661]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779666]  kfree+0x90/0x1d0
Aug 12 04:44:53 boke kernel: [   64.779712]  iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779758]  iscsi_target_login_thread+0x10c4/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779769]  ? __sched_text_start+0x8/0x8
Aug 12 04:44:53 boke kernel: [   64.779812]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779819]  ? __kthread_parkme+0xcc/0x100
Aug 12 04:44:53 boke kernel: [   64.779826]  ? parse_args.cold.14+0xd3/0xd3
Aug 12 04:44:53 boke kernel: [   64.779870]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.779875]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.779882]  ? kthread_bind+0x30/0x30
Aug 12 04:44:53 boke kernel: [   64.779888]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.779892]
Aug 12 04:44:53 boke kernel: [   64.782589] Allocated by task 992:
Aug 12 04:44:53 boke kernel: [   64.785331]  kasan_kmalloc+0xbf/0xe0
Aug 12 04:44:53 boke kernel: [   64.785336]  kmem_cache_alloc_trace+0x112/0x210
Aug 12 04:44:53 boke kernel: [   64.785378]  iscsi_target_login_thread+0x844/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.785384]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.785388]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.785390]
Aug 12 04:44:53 boke kernel: [   64.788089] Freed by task 992:
Aug 12 04:44:53 boke kernel: [   64.790828]  __kasan_slab_free+0x125/0x170
Aug 12 04:44:53 boke kernel: [   64.790833]  kfree+0x90/0x1d0
Aug 12 04:44:53 boke kernel: [   64.790876]  iscsi_target_login_thread+0x15c7/0x1720 [iscsi_target_mod]
Aug 12 04:44:53 boke kernel: [   64.790881]  kthread+0x1a0/0x1c0
Aug 12 04:44:53 boke kernel: [   64.790885]  ret_from_fork+0x35/0x40
Aug 12 04:44:53 boke kernel: [   64.790887]
Aug 12 04:44:53 boke kernel: [   64.793592] The buggy address belongs to the object at ffff880113ca6a00
Aug 12 04:44:53 boke kernel: [   64.793592]  which belongs to the cache kmalloc-512 of size 512
Aug 12 04:44:53 boke kernel: [   64.799193] The buggy address is located 0 bytes inside of
Aug 12 04:44:53 boke kernel: [   64.799193]  512-byte region [ffff880113ca6a00, ffff880113ca6c00)
Aug 12 04:44:53 boke kernel: [   64.804771] The buggy address belongs to the page:
Aug 12 04:44:53 boke kernel: [   64.807550] page:ffffea00044f2980 count:1 mapcount:0 mapping:0000000000000000 index:0x0 compound_mapcount: 0
Aug 12 04:44:53 boke kernel: [   64.813107] flags: 0x17fffc000008100(slab|head)
Aug 12 04:44:53 boke kernel: [   64.815886] raw: 017fffc000008100 0000000000000000 0000000000000000 00000001000c000c
Aug 12 04:44:53 boke kernel: [   64.818736] raw: dead000000000100 dead000000000200 ffff88011b002e00 0000000000000000
Aug 12 04:44:53 boke kernel: [   64.821581] page dumped because: kasan: bad access detected
Aug 12 04:44:53 boke kernel: [   64.824383]
Aug 12 04:44:53 boke kernel: [   64.827097] Memory state around the buggy address:
Aug 12 04:44:53 boke kernel: [   64.829886]  ffff880113ca6900: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.832729]  ffff880113ca6980: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
Aug 12 04:44:53 boke kernel: [   64.835621] >ffff880113ca6a00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.838559]                    ^
Aug 12 04:44:53 boke kernel: [   64.841412]  ffff880113ca6a80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.844354]  ffff880113ca6b00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:44:53 boke kernel: [   64.847247] =================================
Aug 12 04:45:28 boke kernel: [   99.808033] iSCSI Login timeout on Network Portal [::]:3260
Aug 12 04:45:28 boke kernel: [   99.813911] iSCSI Login negotiation failed.
Aug 12 04:45:28 boke kernel: [   99.819178] =================================
Aug 12 04:45:28 boke kernel: [   99.824242] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.834681]
Aug 12 04:45:28 boke kernel: [   99.839909] CPU: 1 PID: 992 Comm: iscsi_np Tainted: G    B      O      4.17.8kasan #1
Aug 12 04:45:28 boke kernel: [   99.839914] Hardware name: To be filled by O.E.M. To be filled by O.E.M./Aptio CRB, BIOS 5.6.5 05/19/2014
Aug 12 04:45:28 boke kernel: [   99.839918] Call Trace:
Aug 12 04:45:28 boke kernel: [   99.839937]  dump_stack+0x71/0xac
Aug 12 04:45:28 boke kernel: [   99.839952]  print_address_description+0x65/0x22e
Aug 12 04:45:28 boke kernel: [   99.840033]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840045]  kasan_report_invalid_free+0x65/0xa0
Aug 12 04:45:28 boke kernel: [   99.840125]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840135]  __kasan_slab_free+0x157/0x170
Aug 12 04:45:28 boke kernel: [   99.840215]  ? iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840223]  kfree+0x90/0x1d0
Aug 12 04:45:28 boke kernel: [   99.840303]  iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840382]  iscsi_target_login_thread+0x10c4/0x1720 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840398]  ? __sched_text_start+0x8/0x8
Aug 12 04:45:28 boke kernel: [   99.840474]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840485]  ? __kthread_parkme+0xcc/0x100
Aug 12 04:45:28 boke kernel: [   99.840496]  ? parse_args.cold.14+0xd3/0xd3
Aug 12 04:45:28 boke kernel: [   99.840572]  ? iscsi_target_login_sess_out+0x280/0x280 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.840581]  kthread+0x1a0/0x1c0
Aug 12 04:45:28 boke kernel: [   99.840593]  ? kthread_bind+0x30/0x30
Aug 12 04:45:28 boke kernel: [   99.840603]  ret_from_fork+0x35/0x40
Aug 12 04:45:28 boke kernel: [   99.840610]
Aug 12 04:45:28 boke kernel: [   99.845766] Allocated by task 992:
Aug 12 04:45:28 boke kernel: [   99.851007]  kasan_kmalloc+0xbf/0xe0
Aug 12 04:45:28 boke kernel: [   99.851016]  kmem_cache_alloc_trace+0x112/0x210
Aug 12 04:45:28 boke kernel: [   99.851090]  iscsi_target_login_thread+0x844/0x1720 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.851099]  kthread+0x1a0/0x1c0
Aug 12 04:45:28 boke kernel: [   99.851107]  ret_from_fork+0x35/0x40
Aug 12 04:45:28 boke kernel: [   99.851109]
Aug 12 04:45:28 boke kernel: [   99.856286] Freed by task 992:
Aug 12 04:45:28 boke kernel: [   99.861405]  __kasan_slab_free+0x125/0x170
Aug 12 04:45:28 boke kernel: [   99.861412]  kfree+0x90/0x1d0
Aug 12 04:45:28 boke kernel: [   99.861486]  iscsi_target_login_thread+0x15c7/0x1720 [iscsi_target_mod]
Aug 12 04:45:28 boke kernel: [   99.861495]  kthread+0x1a0/0x1c0
Aug 12 04:45:28 boke kernel: [   99.861503]  ret_from_fork+0x35/0x40
Aug 12 04:45:28 boke kernel: [   99.861505]
Aug 12 04:45:28 boke kernel: [   99.866456] The buggy address belongs to the object at ffff880119ce4c80
Aug 12 04:45:28 boke kernel: [   99.866456]  which belongs to the cache kmalloc-512 of size 512
Aug 12 04:45:28 boke kernel: [   99.876739] The buggy address is located 0 bytes inside of
Aug 12 04:45:28 boke kernel: [   99.876739]  512-byte region [ffff880119ce4c80, ffff880119ce4e80)
Aug 12 04:45:28 boke kernel: [   99.886859] The buggy address belongs to the page:
Aug 12 04:45:28 boke kernel: [   99.891718] page:ffffea0004673900 count:1 mapcount:0 mapping:0000000000000000 index:0x0 compound_mapcount: 0
Aug 12 04:45:28 boke kernel: [   99.901751] flags: 0x17fffc000008100(slab|head)
Aug 12 04:45:28 boke kernel: [   99.906847] raw: 017fffc000008100 0000000000000000 0000000000000000 00000001800c000c
Aug 12 04:45:28 boke kernel: [   99.912053] raw: dead000000000100 dead000000000200 ffff88011b002e00 0000000000000000
Aug 12 04:45:28 boke kernel: [   99.917221] page dumped because: kasan: bad access detected
Aug 12 04:45:28 boke kernel: [   99.922409]
Aug 12 04:45:28 boke kernel: [   99.927394] Memory state around the buggy address:
Aug 12 04:45:28 boke kernel: [   99.932535]  ffff880119ce4b80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:45:28 boke kernel: [   99.937874]  ffff880119ce4c00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
Aug 12 04:45:28 boke kernel: [   99.943113] >ffff880119ce4c80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:45:28 boke kernel: [   99.948253]                    ^
Aug 12 04:45:28 boke kernel: [   99.953425]  ffff880119ce4d00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:45:28 boke kernel: [   99.958724]  ffff880119ce4d80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
Aug 12 04:45:28 boke kernel: [   99.963801] =================================

For completeness, I should mention this is with a vanilla kernel build
as of:
  commit 5606f577a707aa4ccc391714dca815933aeba508 (HEAD, tag: v4.17.8)
  Author: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
  Date:   Wed Jul 18 07:56:38 2018 +0200

      Linux 4.17.8
which hence lacks any debian patch which would have been present in
the previous kernel.
I did build it with the debian-provided .config, enabling CONFIG_KASAN
and emptying CONFIG_SYSTEM_TRUSTED_KEYS. Post-menuconfig .config diff
against /boot/config-4.17.0-1-amd64:
40a41
> CONFIG_KASAN_SHADOW_OFFSET=0xdffffc0000000000
45a47
> CONFIG_CONSTRUCTORS=y
56c58
< CONFIG_LOCALVERSION=""
---
> CONFIG_LOCALVERSION="kasan"
58d59
< CONFIG_BUILD_SALT="4.17.0-1-amd64"
342d342
< CONFIG_VMAP_STACK=y
927d926
< CONFIG_X86_X32_DISABLED=y
5241a5241,5242
> # CONFIG_FB_NVIDIA is not set
> # CONFIG_FB_RIVA is not set
5854c5855
< CONFIG_USB_COMMON=m
---
> CONFIG_USB_COMMON=y
6767c6768
< CONFIG_ASHMEM=m
---
> # CONFIG_ASHMEM is not set
7370,7372c7371
< CONFIG_ANDROID_BINDER_IPC=m
< CONFIG_ANDROID_BINDER_DEVICES="binder"
< # CONFIG_ANDROID_BINDER_IPC_SELFTEST is not set
---
> # CONFIG_ANDROID_BINDER_IPC is not set
7860c7859,7863
< # CONFIG_KASAN is not set
---
> CONFIG_KASAN=y
> # CONFIG_KASAN_EXTRA is not set
> CONFIG_KASAN_OUTLINE=y
> # CONFIG_KASAN_INLINE is not set
> # CONFIG_TEST_KASAN is not set
8057d8059
< # CONFIG_UNWINDER_GUESS is not set
8070d8071
< CONFIG_SECURITY_PERF_EVENTS_RESTRICT=y
8086,8088d8086
< CONFIG_LOCK_DOWN_KERNEL=y
< # CONFIG_ALLOW_LOCKDOWN_LIFT_BY_SYSRQ is not set
< CONFIG_LOCK_DOWN_IN_EFI_SECURE_BOOT=y
8330c8328
< CONFIG_SYSTEM_TRUSTED_KEYS="debian/certs/test-signing-certs.pem"
---
> CONFIG_SYSTEM_TRUSTED_KEYS=""
8456a8455
> CONFIG_STACKDEPOT=y
-- 
Vincent Pelletier

Re: BUG in slab_free after iSCSI login timeout

[Vincent Pelletier]

On Sun, 12 Aug 2018 02:55:31 +0000, Vincent Pelletier
<plr.vincent@gmail.com> wrote:
> Aug 12 04:44:53 boke kernel: [   64.737069] BUG: KASAN: use-after-free in iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
> Aug 12 04:44:53 boke kernel: [   64.771148] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]

If I'm reading the code correctly, the double-free would be
iscsi_login_init_conn and iscsi_target_login_sess_out both calling
kfree(conn->conn_ops), with the latter called by
__iscsi_target_login_thread precisely when the former fails (returns
NULL after freeing).

I'm not spotting the use-after-free so far, and do not yet understand
why iscsi_login_init_conn would fail:
- allocation-related failures allocate a fixed amount of ram, the
  target machine has 4GB and very few userland processes
  This said, I was surprised by "free" output listing only a bit
  above 3GB of ram total:
  $ free -m
                total        used        free      shared  buff/cache   available
  Mem:           3310         250        2867           5         192        2847
  Swap:          5015           0        5015
  Would it be an effect of KASAN ?
  I also found the following line in dmesg:
  [    0.000000] Memory: 3099784K/4088348K available (14348K kernel code, 4532K rwdata, 5400K rodata, 1840K init, 9112K bss, 988564K reserved, 0K cma-reserved)
  Checking pre-KASAN boots it was:
  [    0.000000] Memory: 3657884K/4088348K available (10252K kernel code, 1210K rwdata, 3216K rodata, 1548K init, 656K bss, 430464K reserved, 0K cma-reserved)
- $ grep CONFIG_CPUMASK_OFFSTACK .config
  $
  so zalloc_cpumask_var should have no way to fail.

Regards,
-- 
Vincent Pelletier

Re: BUG in slab_free after iSCSI login timeout

[Vincent Pelletier]

On Sun, 12 Aug 2018 03:51:40 +0000, Vincent Pelletier
<plr.vincent@gmail.com> wrote:
>   This said, I was surprised by "free" output listing only a bit
>   above 3GB of ram total:
>   $ free -m
>                 total        used        free      shared  buff/cache   available
>   Mem:           3310         250        2867           5         192        2847
>   Swap:          5015           0        5015
>   Would it be an effect of KASAN ?
>   I also found the following line in dmesg:
>   [    0.000000] Memory: 3099784K/4088348K available (14348K kernel code, 4532K rwdata, 5400K rodata, 1840K init, 9112K bss, 988564K reserved, 0K cma-reserved)
>   Checking pre-KASAN boots it was:
>   [    0.000000] Memory: 3657884K/4088348K available (10252K kernel code, 1210K rwdata, 3216K rodata, 1548K init, 656K bss, 430464K reserved, 0K cma-reserved)

Answering my own question after a bit of RTFM: KASAN uses 1 byte to
track 8 bytes, so monitoring 4GB takes 512MB, so it indeed explains the
vast majority of the difference in reserved memory.
-- 
Vincent Pelletier

Re: BUG in slab_free after iSCSI login timeout

[Mike Christie]

On 08/11/2018 10:51 PM, Vincent Pelletier wrote:
> On Sun, 12 Aug 2018 02:55:31 +0000, Vincent Pelletier
> <plr.vincent@gmail.com> wrote:
>> Aug 12 04:44:53 boke kernel: [   64.737069] BUG: KASAN: use-after-free in iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
>> Aug 12 04:44:53 boke kernel: [   64.771148] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
> 
> If I'm reading the code correctly, the double-free would be
> iscsi_login_init_conn and iscsi_target_login_sess_out both calling
> kfree(conn->conn_ops), with the latter called by
> __iscsi_target_login_thread precisely when the former fails (returns
> NULL after freeing).
> 

I think I fixed that with this patch:

https://www.spinics.net/lists/target-devel/msg17018.html

It fixes a mix of problems double free of the ops, session and reference
after free.

Re: BUG in slab_free after iSCSI login timeout

[Mike Christie]

On 08/13/2018 02:48 PM, Mike Christie wrote:
> On 08/11/2018 10:51 PM, Vincent Pelletier wrote:
>> On Sun, 12 Aug 2018 02:55:31 +0000, Vincent Pelletier
>> <plr.vincent@gmail.com> wrote:
>>> Aug 12 04:44:53 boke kernel: [   64.737069] BUG: KASAN: use-after-free in iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
>>> Aug 12 04:44:53 boke kernel: [   64.771148] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
>>
>> If I'm reading the code correctly, the double-free would be
>> iscsi_login_init_conn and iscsi_target_login_sess_out both calling
>> kfree(conn->conn_ops), with the latter called by
>> __iscsi_target_login_thread precisely when the former fails (returns
>> NULL after freeing).
>>
> 
> I think I fixed that with this patch:
> 
> https://www.spinics.net/lists/target-devel/msg17018.html
> 
> It fixes a mix of problems double free of the ops, session and reference
> after free.

Ignore this. I see you said conn. My patch fixed basically the same
issue but with the session.

Re: BUG in slab_free after iSCSI login timeout

[Mike Christie]

[-- Attachment #1: Type: text/plain, Size: 1257 bytes --]

On 08/13/2018 04:42 PM, Mike Christie wrote:
> On 08/13/2018 02:48 PM, Mike Christie wrote:
>> On 08/11/2018 10:51 PM, Vincent Pelletier wrote:
>>> On Sun, 12 Aug 2018 02:55:31 +0000, Vincent Pelletier
>>> <plr.vincent@gmail.com> wrote:
>>>> Aug 12 04:44:53 boke kernel: [   64.737069] BUG: KASAN: use-after-free in iscsi_target_login_sess_out.cold.11+0x58/0x123 [iscsi_target_mod]
>>>> Aug 12 04:44:53 boke kernel: [   64.771148] BUG: KASAN: double-free or invalid-free in iscsi_target_login_sess_out.cold.11+0x103/0x123 [iscsi_target_mod]
>>>
>>> If I'm reading the code correctly, the double-free would be
>>> iscsi_login_init_conn and iscsi_target_login_sess_out both calling
>>> kfree(conn->conn_ops), with the latter called by
>>> __iscsi_target_login_thread precisely when the former fails (returns
>>> NULL after freeing).
>>>
>>
>> I think I fixed that with this patch:
>>
>> https://www.spinics.net/lists/target-devel/msg17018.html
>>
>> It fixes a mix of problems double free of the ops, session and reference
>> after free.
> 
> Ignore this. I see you said conn. My patch fixed basically the same
> issue but with the session.

Could you try the attached patch? I have done a couple login/logout
tests only, but have not yet completed testing.


[-- Attachment #2: 0001-iscsi-target-fix-conn_ops-double-free.patch --]
[-- Type: text/x-patch, Size: 7614 bytes --]

From b6d6e8da919b775e9a0dae64628f4e32ec705feb Mon Sep 17 00:00:00 2001
From: Mike Christie <mchristi@redhat.com>
Date: Mon, 13 Aug 2018 17:52:18 -0500
Subject: [PATCH] iscsi target: fix conn_ops double free

If iscsi_login_init_conn fails it can free conn_ops.
__iscsi_target_login_thread will then call iscsi_target_login_sess_out
which will also free it.

This prevents the bug by moving the non login-only items that need to
be allocated/setup to new functions iscsit_alloc/free_conn. These alloc
function is then called in __iscsi_target_login_thread and the free
unction is only called if the alloc function is successfull.

Signed-off-by: Mike Christie <mchristi@redhat.com>
---
 drivers/target/iscsi/iscsi_target.c       |   9 +--
 drivers/target/iscsi/iscsi_target_login.c | 101 ++++++++++++++++--------------
 drivers/target/iscsi/iscsi_target_login.h |   2 +-
 3 files changed, 57 insertions(+), 55 deletions(-)

diff --git a/drivers/target/iscsi/iscsi_target.c b/drivers/target/iscsi/iscsi_target.c
index 8e22379..a4ecc9d 100644
--- a/drivers/target/iscsi/iscsi_target.c
+++ b/drivers/target/iscsi/iscsi_target.c
@@ -4211,22 +4211,15 @@ int iscsit_close_connection(
 		crypto_free_ahash(tfm);
 	}
 
-	free_cpumask_var(conn->conn_cpumask);
-
-	kfree(conn->conn_ops);
-	conn->conn_ops = NULL;
-
 	if (conn->sock)
 		sock_release(conn->sock);
 
 	if (conn->conn_transport->iscsit_free_conn)
 		conn->conn_transport->iscsit_free_conn(conn);
 
-	iscsit_put_transport(conn->conn_transport);
-
 	pr_debug("Moving to TARG_CONN_STATE_FREE.\n");
 	conn->conn_state = TARG_CONN_STATE_FREE;
-	kfree(conn);
+	iscsit_free_conn(conn);
 
 	spin_lock_bh(&sess->conn_lock);
 	atomic_dec(&sess->nconn);
diff --git a/drivers/target/iscsi/iscsi_target_login.c b/drivers/target/iscsi/iscsi_target_login.c
index 923b1a9..e1bdfd5 100644
--- a/drivers/target/iscsi/iscsi_target_login.c
+++ b/drivers/target/iscsi/iscsi_target_login.c
@@ -67,13 +67,6 @@ static struct iscsi_login *iscsi_login_init_conn(struct iscsi_conn *conn)
 		goto out_req_buf;
 	}
 
-	conn->conn_ops = kzalloc(sizeof(struct iscsi_conn_ops), GFP_KERNEL);
-	if (!conn->conn_ops) {
-		pr_err("Unable to allocate memory for"
-			" struct iscsi_conn_ops.\n");
-		goto out_rsp_buf;
-	}
-
 	init_waitqueue_head(&conn->queues_wq);
 	INIT_LIST_HEAD(&conn->conn_list);
 	INIT_LIST_HEAD(&conn->conn_cmd_list);
@@ -94,18 +87,10 @@ static struct iscsi_login *iscsi_login_init_conn(struct iscsi_conn *conn)
 	spin_lock_init(&conn->response_queue_lock);
 	spin_lock_init(&conn->state_lock);
 
-	if (!zalloc_cpumask_var(&conn->conn_cpumask, GFP_KERNEL)) {
-		pr_err("Unable to allocate conn->conn_cpumask\n");
-		goto out_conn_ops;
-	}
 	conn->conn_login = login;
 
 	return login;
 
-out_conn_ops:
-	kfree(conn->conn_ops);
-out_rsp_buf:
-	kfree(login->rsp_buf);
 out_req_buf:
 	kfree(login->req_buf);
 out_login:
@@ -1150,6 +1135,55 @@ int iscsit_put_login_tx(struct iscsi_conn *conn, struct iscsi_login *login,
 	return 0;
 }
 
+static struct iscsi_conn *iscsit_alloc_conn(struct iscsi_np *np)
+{
+	struct iscsi_conn *conn;
+
+	conn = kzalloc(sizeof(struct iscsi_conn), GFP_KERNEL);
+	if (!conn) {
+		pr_err("Could not allocate memory for new connection\n");
+		return NULL;
+	}
+	pr_debug("Moving to TARG_CONN_STATE_FREE.\n");
+	conn->conn_state = TARG_CONN_STATE_FREE;
+
+	timer_setup(&conn->nopin_response_timer,
+		    iscsit_handle_nopin_response_timeout, 0);
+	timer_setup(&conn->nopin_timer, iscsit_handle_nopin_timeout, 0);
+
+	if (iscsit_conn_set_transport(conn, np->np_transport) < 0)
+		goto free_conn;
+
+	conn->conn_ops = kzalloc(sizeof(struct iscsi_conn_ops), GFP_KERNEL);
+	if (!conn->conn_ops) {
+		pr_err("Unable to allocate memory for struct iscsi_conn_ops.\n");
+		goto put_transport;
+	}
+
+	if (!zalloc_cpumask_var(&conn->conn_cpumask, GFP_KERNEL)) {
+		pr_err("Unable to allocate conn->conn_cpumask\n");
+		goto free_mask;
+	}
+
+	return conn;
+
+free_mask:
+	free_cpumask_var(conn->conn_cpumask);
+put_transport:
+	iscsit_put_transport(conn->conn_transport);
+free_conn:
+	kfree(conn);
+	return NULL;
+}
+
+void iscsit_free_conn(struct iscsi_conn *conn)
+{
+	free_cpumask_var(conn->conn_cpumask);
+	kfree(conn->conn_ops);
+	iscsit_put_transport(conn->conn_transport);
+	kfree(conn);
+}
+
 void iscsi_target_login_sess_out(struct iscsi_conn *conn,
 		struct iscsi_np *np, bool zero_tsih, bool new_sess)
 {
@@ -1203,10 +1237,6 @@ void iscsi_target_login_sess_out(struct iscsi_conn *conn,
 		crypto_free_ahash(tfm);
 	}
 
-	free_cpumask_var(conn->conn_cpumask);
-
-	kfree(conn->conn_ops);
-
 	if (conn->param_list) {
 		iscsi_release_param_list(conn->param_list);
 		conn->param_list = NULL;
@@ -1224,8 +1254,7 @@ void iscsi_target_login_sess_out(struct iscsi_conn *conn,
 	if (conn->conn_transport->iscsit_free_conn)
 		conn->conn_transport->iscsit_free_conn(conn);
 
-	iscsit_put_transport(conn->conn_transport);
-	kfree(conn);
+	iscsit_free_conn(conn);
 }
 
 static int __iscsi_target_login_thread(struct iscsi_np *np)
@@ -1255,31 +1284,16 @@ static int __iscsi_target_login_thread(struct iscsi_np *np)
 	}
 	spin_unlock_bh(&np->np_thread_lock);
 
-	conn = kzalloc(sizeof(struct iscsi_conn), GFP_KERNEL);
+	conn = iscsit_alloc_conn(np);
 	if (!conn) {
-		pr_err("Could not allocate memory for"
-			" new connection\n");
 		/* Get another socket */
 		return 1;
 	}
-	pr_debug("Moving to TARG_CONN_STATE_FREE.\n");
-	conn->conn_state = TARG_CONN_STATE_FREE;
-
-	timer_setup(&conn->nopin_response_timer,
-		    iscsit_handle_nopin_response_timeout, 0);
-	timer_setup(&conn->nopin_timer, iscsit_handle_nopin_timeout, 0);
-
-	if (iscsit_conn_set_transport(conn, np->np_transport) < 0) {
-		kfree(conn);
-		return 1;
-	}
 
 	rc = np->np_transport->iscsit_accept_np(np, conn);
 	if (rc == -ENOSYS) {
 		complete(&np->np_restart_comp);
-		iscsit_put_transport(conn->conn_transport);
-		kfree(conn);
-		conn = NULL;
+		iscsit_free_conn(conn);
 		goto exit;
 	} else if (rc < 0) {
 		spin_lock_bh(&np->np_thread_lock);
@@ -1287,17 +1301,13 @@ static int __iscsi_target_login_thread(struct iscsi_np *np)
 			np->np_thread_state = ISCSI_NP_THREAD_ACTIVE;
 			spin_unlock_bh(&np->np_thread_lock);
 			complete(&np->np_restart_comp);
-			iscsit_put_transport(conn->conn_transport);
-			kfree(conn);
-			conn = NULL;
+			iscsit_free_conn(conn);
 			/* Get another socket */
 			return 1;
 		}
 		spin_unlock_bh(&np->np_thread_lock);
-		iscsit_put_transport(conn->conn_transport);
-		kfree(conn);
-		conn = NULL;
-		goto out;
+		iscsit_free_conn(conn);
+		return 1;
 	}
 	/*
 	 * Perform the remaining iSCSI connection initialization items..
@@ -1447,7 +1457,6 @@ static int __iscsi_target_login_thread(struct iscsi_np *np)
 		tpg_np = NULL;
 	}
 
-out:
 	return 1;
 
 exit:
diff --git a/drivers/target/iscsi/iscsi_target_login.h b/drivers/target/iscsi/iscsi_target_login.h
index 74ac3ab..3b8e363 100644
--- a/drivers/target/iscsi/iscsi_target_login.h
+++ b/drivers/target/iscsi/iscsi_target_login.h
@@ -19,7 +19,7 @@ extern int iscsi_target_setup_login_socket(struct iscsi_np *,
 extern int iscsit_accept_np(struct iscsi_np *, struct iscsi_conn *);
 extern int iscsit_get_login_rx(struct iscsi_conn *, struct iscsi_login *);
 extern int iscsit_put_login_tx(struct iscsi_conn *, struct iscsi_login *, u32);
-extern void iscsit_free_conn(struct iscsi_np *, struct iscsi_conn *);
+extern void iscsit_free_conn(struct iscsi_conn *);
 extern int iscsit_start_kthreads(struct iscsi_conn *);
 extern void iscsi_post_login_handler(struct iscsi_np *, struct iscsi_conn *, u8);
 extern void iscsi_target_login_sess_out(struct iscsi_conn *, struct iscsi_np *,
-- 
1.8.3.1