libiscsi test suite can cause double free in spdk iSCSI target

[sitsofe]

Description of the problem
Repeatedly running libiscsi's test suite against a spdk memory based iSCSI target resulted in a double free.

Step to reproduce:

1. Create an iSCSI configuration at app/iscsi_tgt/iscsi.conf that includes the following:

[Malloc]
  # Number of Malloc targets
  NumberOfLuns 1
  # Malloc targets are 128M
  LunSizeInMB 128
  # Block size. Default is 512 bytes.
  BlockSize 512

[InitiatorGroup1]
  InitiatorName ALL
  Netmask 127.0.0.1/16

[TargetNode1]
  TargetName disk1
  TargetAlias "Data Disk1"
  Mapping PortalGroup1 InitiatorGroup1
  UseDigest Auto
  # Use the first malloc target
  LUN0 Malloc0

  QueueDepth 128

2. Run
   sudo app/iscsi_tgt/iscsi_tgt -c app/iscsi_tgt/iscsi.conf
3. After the target is started run
   iscsi-test-cu -V -t SCSI.Read6 iscsi://127.0.0.1/iqn.2016-06.io.spdk:disk1/0
4. When step 3 hangs press Ctrl-C.
5. Run
   iscsi-test-cu -V -t SCSI.Read6 iscsi://127.0.0.1/iqn.2016-06.io.spdk:disk1/0

Expected result:
Test suite not to hang after 3? iSCSI target not to crash after 5?

Actual result:
After 3 libiscsi's test suite hangs on

    Send READ6 (Expecting CHECK_CONDITION) LBA:261985 blocks:160
    [FAILED] READ6 failed with wrong sense. Should have failed with ILLEGAL_REQUEST(0x05)/LBA_OUT_OF_RANGE(0x2100) but failed with Sense: (null)(0x00)/(0x0000)

    Send READ6 (Expecting CHECK_CONDITION) LBA:261984 blocks:161

After 5 the iSCSI target prints this:

iscsi.c:1540:spdk_iscsi_op_login_initialize_port: ***ERROR*** InitiatorName is empty
iscsi.c:4247:spdk_iscsi_execute: ***ERROR*** iscsi_op_login() failed
conn.c:1214:spdk_iscsi_conn_handle_incoming_pdus: ***ERROR*** spdk_iscsi_execute() fatal error on NULL(NULL)
iscsi_subsystem.c: 493:spdk_put_pdu: ***ERROR*** Negative PDU refcount: 0x7f7d825716c0
*** Error in `app/iscsi_tgt/iscsi_tgt': double free or corruption (!prev): 0x00000000024aaa50 ***

How reproducible is the problem?
The problem is reproducible every time.

Version information:
libiscsi commit 3a598ea8465c8204688c6ccbc6d74003342f6651
spdk commit b8da09b
dpdk-16.11

[optimistyzy]

I have a question for Ctrl-c in step3, it kill the iSCSI target or the iscsi-test-cu?

[sitsofe]

@optimistyzy - do you mean Step 4? If so, the Ctrl-C should be only be done on iscsi-test-cu. The SPDK iscsi_tgt should be left running until it crashes.

[sitsofe]

Valgrind output:

==55224== Invalid free() / delete / delete[] / realloc()
==55224==    at 0x4C2EDEB: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==55224==    by 0x420A74: spdk_put_pdu (iscsi_subsystem.c:502)
==55224==    by 0x411C14: spdk_iscsi_conn_flush_pdus_internal (conn.c:1125)
==55224==    by 0x412017: spdk_iscsi_conn_flush_pdus (conn.c:1176)
==55224==    by 0x412017: spdk_iscsi_conn_execute (conn.c:1260)
==55224==    by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314)
==55224==    by 0x432725: _spdk_reactor_run (reactor.c:328)
==55224==    by 0x432B5D: spdk_reactors_start (reactor.c:541)
==55224==    by 0x431AD4: spdk_app_start (app.c:436)
==55224==    by 0x404831: main (iscsi_tgt.c:188)
==55224==  Address 0xf46d440 is 0 bytes inside a block of size 8,192 free'd
==55224==    at 0x4C2EDEB: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==55224==    by 0x420A74: spdk_put_pdu (iscsi_subsystem.c:502)
==55224==    by 0x411E79: spdk_iscsi_conn_handle_incoming_pdus (conn.c:1210)
==55224==    by 0x411E79: spdk_iscsi_conn_execute (conn.c:1257)
==55224==    by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314)
==55224==    by 0x432725: _spdk_reactor_run (reactor.c:328)
==55224==    by 0x432B5D: spdk_reactors_start (reactor.c:541)
==55224==    by 0x431AD4: spdk_app_start (app.c:436)
==55224==    by 0x404831: main (iscsi_tgt.c:188)
==55224==  Block was alloc'd at
==55224==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==55224==    by 0x41728A: spdk_iscsi_op_login_rsp_init (iscsi.c:1815)
==55224==    by 0x41728A: spdk_iscsi_op_login (iscsi.c:2172)
==55224==    by 0x419424: spdk_iscsi_execute (iscsi.c:4245)
==55224==    by 0x411E6D: spdk_iscsi_conn_handle_incoming_pdus (conn.c:1209)
==55224==    by 0x411E6D: spdk_iscsi_conn_execute (conn.c:1257)
==55224==    by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314)
==55224==    by 0x432725: _spdk_reactor_run (reactor.c:328)
==55224==    by 0x432B5D: spdk_reactors_start (reactor.c:541)
==55224==    by 0x431AD4: spdk_app_start (app.c:436)
==55224==    by 0x404831: main (iscsi_tgt.c:188)

[jimharris]

On Dec 18, 2016, at 11:53 PM, Sitsofe Wheeler <notifications@github.com<mailto:notifications@github.com>> wrote: Valgrind output: ==55224== Invalid free() / delete / delete[] / realloc() ==55224== at 0x4C2EDEB: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==55224== by 0x420A74: spdk_put_pdu (iscsi_subsystem.c:502) ==55224== by 0x411C14: spdk_iscsi_conn_flush_pdus_internal (conn.c:1125) ==55224== by 0x412017: spdk_iscsi_conn_flush_pdus (conn.c:1176) ==55224== by 0x412017: spdk_iscsi_conn_execute (conn.c:1260) ==55224== by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314) ==55224== by 0x432725: _spdk_reactor_run (reactor.c:328) ==55224== by 0x432B5D: spdk_reactors_start (reactor.c:541) ==55224== by 0x431AD4: spdk_app_start (app.c:436) ==55224== by 0x404831: main (iscsi_tgt.c:188) ==55224== Address 0xf46d440 is 0 bytes inside a block of size 8,192 free'd ==55224== at 0x4C2EDEB: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==55224== by 0x420A74: spdk_put_pdu (iscsi_subsystem.c:502) ==55224== by 0x411E79: spdk_iscsi_conn_handle_incoming_pdus (conn.c:1210) ==55224== by 0x411E79: spdk_iscsi_conn_execute (conn.c:1257) ==55224== by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314) ==55224== by 0x432725: _spdk_reactor_run (reactor.c:328) ==55224== by 0x432B5D: spdk_reactors_start (reactor.c:541) ==55224== by 0x431AD4: spdk_app_start (app.c:436) ==55224== by 0x404831: main (iscsi_tgt.c:188) ==55224== Block was alloc'd at ==55224== at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==55224== by 0x41728A: spdk_iscsi_op_login_rsp_init (iscsi.c:1815) ==55224== by 0x41728A: spdk_iscsi_op_login (iscsi.c:2172) ==55224== by 0x419424: spdk_iscsi_execute (iscsi.c:4245) ==55224== by 0x411E6D: spdk_iscsi_conn_handle_incoming_pdus (conn.c:1209) ==55224== by 0x411E6D: spdk_iscsi_conn_execute (conn.c:1257) ==55224== by 0x4120D2: spdk_iscsi_conn_login_do_work (conn.c:1314) ==55224== by 0x432725: _spdk_reactor_run (reactor.c:328) ==55224== by 0x432B5D: spdk_reactors_start (reactor.c:541) ==55224== by 0x431AD4: spdk_app_start (app.c:436) ==55224== by 0x404831: main (iscsi_tgt.c:188) Hi Sitsofe, We have reproduced your issue and have a couple of patches we will be pushing to fix this issue shortly. Thanks for the report.

…

-Jim — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub<#89 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/ABDT6V9z55_-7MG_E7KAQ1awAOgU0GPUks5rJinOgaJpZM4LQAJG>.

[optimistyzy]

The issue is solved, the related patches will be pushed later.

[sitsofe]

Thanks all!

[optimistyzy]

@sitofe Can you retest this case, I think that this issue has been fixed.

[benlwalker]

We believe this issue is fixed. If the original submitter can reproduce, please re-open.