[iser] [v1.18.0] iscsi_service failed with : revents is not POLLIN

[nbsdx]

Hello,

I'm getting the following output from QEMU with LIBISCSI_DEBUG=100:

libiscsi:5 small allocation size is 256 byte
libiscsi:2 connecting to portal 10.10.1.1:12000 [iqn.2018-02.testing.local:ds1]
libiscsi:1 revents is not POLLIN [iqn.2018-02.testing.local:ds1]
libiscsi:1 iscsi_service failed with : revents is not POLLIN [iqn.2018-02.testing.local:ds1]
libiscsi:1 515 memory blocks lost at iscsi_destroy_context() after 518 malloc(s), 11 realloc(s), 3 free(s) and 0 reused small allocations [iqn.2018-02.testing.local:ds1]
qemu-system-x86_64: -drive id=drive0,format=raw,if=none,cache=none,file=iser://10.10.1.1:12000/iqn.2018-02.testing.local:ds1/0: iSCSI: Failed to connect to LUN : iscsi_service failed with : revents is not POLLIN

I did some digging, and it looks like it's not getting a response to login events. My lio server acknowledges the login attempt, but then when the login fails it's as an "other_fail" (/sys/kernel/config/target/iscsi/$IQN/tgpt_1/fabric_statistics/iscsi_login_stats/other_fails). Because of this, it leads me to believe that the issue is with either

1. the libiscsi userspace iser implementation
2. LIO, but it works fine when configuring the target for TCP access
3. QEMU failing to configure libiscsi correctly.

The qemu command I'm using is

#!/bin/bash

export LIBISCSI_DEBUG=100

qemu-system-x86_64 \
	-enable-kvm \
	-m 4G \
	-smp cores=4 \
	-nodefaults \
	-display none \
	-cpu host \
	-realtime mlock=off \
	-no-hpet \
	-vga qxl \
	-spice port=5555,disable-ticketing \
	-device virtio-serial-pci \
	-device virtserialport,chardev=spicechannel0,name=com.redhat.spice.0 \
	-chardev spicevmc,id=spicechannel0,name=vdagent \
	-drive id=drive0,format=raw,if=none,cache=none,file=iser://10.10.1.1:12000/iqn.2018-02.testing.local:ds1/0 \
	-device virtio-blk-pci,drive=drive0

LIO Configuration:

storage-1 ~ # targetcli ls
o- / ......................................................................................................................... [...]
  o- backstores .............................................................................................................. [...]
  | o- block .................................................................................................. [Storage Objects: 0]
  | o- fileio ................................................................................................. [Storage Objects: 1]
  | | o- ds1 .......................................................................... [/srv/ds1.img (2.0GiB) write-thru activated]
  | |   o- alua ................................................................................................... [ALUA Groups: 1]
  | |     o- default_tg_pt_gp ....................................................................... [ALUA state: Active/optimized]
  | o- pscsi .................................................................................................. [Storage Objects: 0]
  | o- ramdisk ................................................................................................ [Storage Objects: 0]
  o- iscsi ............................................................................................................ [Targets: 1]
  | o- iqn.2018-02.testing.local:ds1 ..................................................................................... [TPGs: 1]
  |   o- tpg1 .................................................................................................. [gen-acls, no-auth]
  |     o- acls .......................................................................................................... [ACLs: 0]
  |     o- luns .......................................................................................................... [LUNs: 1]
  |     | o- lun0 ................................................................... [fileio/ds1 (/srv/ds1.img) (default_tg_pt_gp)]
  |     o- portals .................................................................................................... [Portals: 1]
  |       o- 10.10.1.1:12000 ................................................................................................ [iser]
  o- loopback ......................................................................................................... [Targets: 0]
  o- srpt ............................................................................................................. [Targets: 0]
  o- vhost ............................................................................................................ [Targets: 0]
  o- xen_pvscsi ....................................................................................................... [Targets: 0]

We're using Mellanox ConnectX-3 cards, and the OFED 3.12 drivers from OpenFabrics.

If there's anything else you need, please ask. Thank you.

[efschu]

I'm running into the same problem. You can reproduce this with libiscsi-bin by:

iscsi-inq iser://192.168.40.10:3260/iqn.2023-04.de.efeu.efeutc./0 -i iqn.1993-08.org.debian:01:ca23a2818d75

If you run this command for the first time (actual a "fresh" initiator-name - dunno why???), it works.:

Peripheral Qualifier:CONNECTED Peripheral Device Type:DIRECT_ACCESS Removable:0 Version:6 unknown NormACA:0 HiSup:0 ReponseDataFormat:2 SCCS:1 ACC:0 TPGS:3 3PC:1 Protect:0 EncServ:0 MultiP:0 SYNC:0 CmdQue:1 Vendor:LIO-ORG Product:rpool-vm-100-di Revision:4.0 Version Descriptor:00a0 unknown Version Descriptor:0960 iSCSI Version Descriptor:0460 SPC-4 Version Descriptor:04c0 SBC-3

But if ran a few seconds later it gives:

Login Failed. iscsi_service failed with : revents is not POLLIN

dmesg on target tells:

iscsi_np: page allocation failure: order:9, mode:0x40dc0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null),cpuset=/,mems_allowed=0 CPU: 15 PID: 709811 Comm: iscsi_np Tainted: P OE 6.1.0-8-amd64 #1 Debian 6.1.25-1 Hardware name: ASUS System Product Name/Pro B550M-C, BIOS 2403 06/15/2021 Call Trace: TASK dump_stack_lvl+0x44/0x5c warn_alloc+0x151/0x170 ? __alloc_pages_direct_compact+0x221/0x330 __alloc_pages_slowpath.constprop.0+0xd5e/0xdc0 ? iommu_map_atomic+0x42/0x60 __alloc_pages+0x305/0x330 __kmalloc_large_node+0x6e/0xe0 kmalloc_large+0x19/0xa0 isert_put_login_tx+0x147/0x4d0 [ib_isert] iscsi_target_do_tx_login_io+0xaa/0x1d0 [iscsi_target_mod] iscsi_target_do_login+0x287/0x570 [iscsi_target_mod] iscsi_target_start_negotiation+0x51/0xe0 [iscsi_target_mod] iscsi_target_login_thread+0xb2c/0x1040 [iscsi_target_mod] ? iscsi_target_login_sess_out+0x180/0x180 [iscsi_target_mod] kthread+0xe9/0x110 ? kthread_complete_and_exit+0x20/0x20 ret_from_fork+0x22/0x30 TASK Mem-Info: active_anon:10643 inactive_anon:1133971 isolated_anon:0 active_file:43758 inactive_file:20443 isolated_file:0 unevictable:242 dirty:67 writeback:0 slab_reclaimable:15438 slab_unreclaimable:296488 mapped:78748 shmem:34955 pagetables:12652 sec_pagetables:0 bounce:0 kernel_misc_reclaimable:0 free:530375 free_pcp:55 free_cma:0 Node 0 active_anon:42572kB inactive_anon:4535884kB active_file:175032kB inactive_file:81772kB unevictable:968kB isolated(anon):0kB isolated(file):0kB mapped:314992kB dirty:268kB writeback:0kB shmem:139820kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 1495040kB writeback_tmp:0kB kernel_stack:34784kB pagetables:50608kB sec_pagetables:0kB all_unreclaimable? yes Node 0 DMA free:13308kB boost:0kB min:84kB low:104kB high:124kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB lowmem_reserve[]: 0 2919 11627 11627 11627 Node 0 DMA32 free:1259708kB boost:0kB min:16948kB low:21184kB high:25420kB reserved_highatomic:0KB active_anon:34072kB inactive_anon:1178612kB active_file:40900kB inactive_file:15596kB unevictable:272kB writepending:0kB present:3210940kB managed:3098184kB mlocked:272kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB lowmem_reserve[]: 0 0 8707 8707 8707 Node 0 Normal free:848484kB boost:113724kB min:164268kB low:176904kB high:189540kB reserved_highatomic:0KB active_anon:8500kB inactive_anon:3357272kB active_file:134132kB inactive_file:66176kB unevictable:696kB writepending:268kB present:9145344kB managed:8916200kB mlocked:696kB bounce:0kB free_pcp:216kB local_pcp:0kB free_cma:0kB lowmem_reserve[]: 0 0 0 0 0 Node 0 DMA: 14kB (U) 18kB (U) 116kB (U) 132kB (U) 164kB (U) 1128kB (U) 1256kB (U) 1512kB (U) 01024kB 22048kB (UM) 24096kB (M) = 13308kB Node 0 DMA32: 130724kB (UM) 131778kB (UME) 1008516kB (UE) 828032kB (UE) 286664kB (UE) 1784128kB (U) 763256kB (U) 112512kB (U) 111024kB (U) 02048kB 04096kB = 1259736kB Node 0 Normal: 235304kB (UME) 493288kB (UME) 1743816kB (UE) 252232kB (UE) 064kB 0128kB 0256kB 0512kB 01024kB 02048kB 0*4096kB = 848456kB Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB 99156 total pagecache pages 0 pages in swap cache Free swap = 0kB Total swap = 0kB 3093070 pages RAM 0 pages HighMem/MovableOnly 85634 pages reserved 0 pages hwpoisoned iSCSI Login negotiation failed. INFO: task iscsi_ttx:1991384 blocked for more than 120 seconds. Tainted: P OE 6.1.0-8-amd64 #1 Debian 6.1.25-1 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:iscsi_ttx state:D stack:0 pid:1991384 ppid:2 flags:0x00004004 Call Trace: TASK __schedule+0x351/0xa20 schedule+0x5d/0xe0 schedule_timeout+0x94/0x150 ? __bpf_trace_tick_stop+0x10/0x10 target_wait_for_sess_cmds+0x106/0x160 [target_core_mod] ? dequeue_task_stop+0x70/0x70 isert_wait_conn+0x1bf/0x290 [ib_isert] ? preempt_count_add+0x6a/0xa0 ? iscsit_get_rx_pdu+0xfc0/0xfc0 [iscsi_target_mod] iscsit_close_connection+0x154/0x930 [iscsi_target_mod] ? __schedule+0x359/0xa20 ? preempt_count_add+0x6a/0xa0 ? iscsit_get_rx_pdu+0xfc0/0xfc0 [iscsi_target_mod] iscsit_take_action_for_connection_exit+0x7c/0x100 [iscsi_target_mod] iscsi_target_tx_thread+0x16a/0x230 [iscsi_target_mod] ? dequeue_task_stop+0x70/0x70 kthread+0xe9/0x110 ? kthread_complete_and_exit+0x20/0x20 ret_from_fork+0x22/0x30 TASK

Running it with iscsi instead is always working.

Connecting and using to an iser target via iscsiadm is working fine but not via libiscsi.