Hi,
Kernel blocked very rarely when I was calling target.delete() using
python RTSlib.
I am using Ubuntu 14.04.2 with kernel 3.16.0-30-generic.
Currently, a windows 7 desktop uses this target server.
Call stack of the python process was as follows;
[<ffffffffc09ea557>] iscsit_reset_np_thread+0xc7/0xf0 [iscsi_target_mod]
[<ffffffffc09e30b6>] iscsit_tpg_del_network_portal+0xf6/0x200
[iscsi_target_mod]
[<ffffffffc09f0cf9>] lio_target_call_delnpfromtpg+0x39/0xa0
[iscsi_target_mod]
[<ffffffffc091a021>] target_fabric_np_base_release+0x21/0x30
[target_core_mod]
[<ffffffffc0905827>] config_item_release+0x67/0xe0 [configfs]
[<ffffffffc09058cc>] config_item_put+0x2c/0x2f [configfs]
[<ffffffffc0903d10>] configfs_rmdir+0x1e0/0x310 [configfs]
[<ffffffff811e08c8>] vfs_rmdir+0xa8/0x100
[<ffffffff811e38d1>] do_rmdir+0x1c1/0x1e0
[<ffffffff811e4aa6>] SyS_rmdir+0x16/0x20
[<ffffffff8176aced>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff
And the process was not killed by signal since it is in 'D' state.
I also captured all the iSCSI packets and found out that
this occurs when the desktop asks 'Logical Unit Reset' and the server
tries to delete the corresponding target.
Following is the last part of the packet capture from tshark when the
target.delete() blocks
and the caller process hangs while producing syslog like this.
|
Aug ||29| |03||:||27||:||26| |XXX||kernel: [||1619267.924061||]
INFO: task python:||11036| |blocked ||for| |more than ||120| |seconds.|
The server IP is 10.77.56.205; and desktop 10.77.56.135.
1069.734321 10.77.56.205 3260 10.77.56.135 49244 TCP 54 0 3260 > 49244
[ACK] Seq=3457 Ack=3457 Win=11169 Len=0 17:35:00.932216
1071.954960 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 SCSI:
Read(10) LUN: 0x00 (LBA: 0x0100d298, Len: 8) 17:35:03.152855
1071.956950 10.77.56.205 3260 10.77.56.135 49152 TCP 102 48 [TCP segment
of a reassembled PDU] 17:35:03.154845
1071.956954 10.77.56.205 3260 10.77.56.135 49152 iSCSI 4150 4096 SCSI:
Data In LUN: 0x00 (Read(10) Response Data) SCSI: Response LUN: 0x00
(Read(10)) (Good) 17:35:03.154849
1071.960313 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[ACK] Seq=263330577 Ack=7000261 Win=7753 Len=0 17:35:03.158208
1071.960321 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[ACK] Seq=263330577 Ack=7002897 Win=7742 Len=0 17:35:03.158216
1074.951699 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 SCSI:
Read(10) LUN: 0x00 (LBA: 0x00fd95c8, Len: 8) 17:35:06.149594
1074.952047 10.77.56.205 3260 10.77.56.135 49152 TCP 102 48 [TCP segment
of a reassembled PDU] 17:35:06.149942
1074.952055 10.77.56.205 3260 10.77.56.135 49152 iSCSI 4150 4096 SCSI:
Data In LUN: 0x00 (Read(10) Response Data) SCSI: Response LUN: 0x00
(Read(10)) (Good) 17:35:06.149950
1074.955499 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[ACK] Seq=263330625 Ack=7004405 Win=7736 Len=0 17:35:06.153394
1074.955680 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[ACK] Seq=263330625 Ack=7007041 Win=7726 Len=0 17:35:06.153575
1075.106379 10.77.56.205 3260 10.77.56.135 49152 iSCSI 102 48 NOP In
17:35:06.304274
1075.109903 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:06.307798
1075.146370 10.77.56.205 3260 10.77.56.135 49152 TCP 54 0 3260 > 49152
[ACK] Seq=7007089 Ack=263330673 Win=24576 Len=0 17:35:06.344265
1084.770382 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 NOP In
17:35:15.968277
1084.770650 10.77.56.135 49244 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:15.968545
1084.770667 10.77.56.205 3260 10.77.56.135 49244 TCP 54 0 3260 > 49244
[ACK] Seq=3505 Ack=3505 Win=11169 Len=0 17:35:15.968562
1086.390149 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 Task
Management Function (Logical Unit Reset) 17:35:17.588044
1086.390158 10.77.56.205 3260 10.77.56.135 49152 TCP 54 0 3260 > 49152
[ACK] Seq=7007089 Ack=263330721 Win=24576 Len=0 17:35:17.588053
1086.390177 10.77.56.205 3260 10.77.56.135 49152 iSCSI 102 48 Task
Management Function Response (Function complete) 17:35:17.588072
1086.589153 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[ACK] Seq=263330721 Ack=7007137 Win=7726 Len=0 17:35:17.787048
1090.146379 10.77.56.205 3260 10.77.56.135 49152 iSCSI 102 48 NOP In
17:35:21.344274
1090.150237 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:21.348132
1090.186371 10.77.56.205 3260 10.77.56.135 49152 TCP 54 0 3260 > 49152
[ACK] Seq=7007185 Ack=263330769 Win=24576 Len=0 17:35:21.384266
1099.810378 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 NOP In
17:35:31.008273
1099.817330 10.77.56.135 49244 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:31.015225
1099.817342 10.77.56.205 3260 10.77.56.135 49244 TCP 54 0 3260 > 49244
[ACK] Seq=3553 Ack=3553 Win=11169 Len=0 17:35:31.015237
1105.186378 10.77.56.205 3260 10.77.56.135 49152 iSCSI 102 48 NOP In
17:35:36.384273
1105.191588 10.77.56.135 49152 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:36.389483
1105.191595 10.77.56.205 3260 10.77.56.135 49152 TCP 54 0 3260 > 49152
[ACK] Seq=7007233 Ack=263330817 Win=24576 Len=0 17:35:36.389490
1105.763000 10.77.56.135 49153 10.77.56.205 3260 TCP 66 0 49153 > 3260
[SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1 17:35:36.960895
1105.763019 10.77.56.205 3260 10.77.56.135 49153 TCP 66 0 3260 > 49153
[SYN, ACK] Seq=0 Ack=1 Win=29200 Len=0 MSS=1460 SACK_PERM=1 WS=128
17:35:36.960914
1105.764520 10.77.56.135 49153 10.77.56.205 3260 TCP 60 0 49153 > 3260
[ACK] Seq=1 Ack=1 Win=65536 Len=0 17:35:36.962415
1105.764569 10.77.56.135 49153 10.77.56.205 3260 iSCSI 242 188 Login
Command 17:35:36.962464
1105.764576 10.77.56.205 3260 10.77.56.135 49153 TCP 54 0 3260 > 49153
[ACK] Seq=1 Ack=189 Win=30336 Len=0 17:35:36.962471
1105.764653 10.77.56.205 3260 10.77.56.135 49153 iSCSI 166 112 Login
Response (Success) 17:35:36.962548
1105.764999 10.77.56.135 49152 10.77.56.205 3260 TCP 60 0 49152 > 3260
[RST, ACK] Seq=263330817 Ack=7007233 Win=0 Len=0 17:35:36.962894
1105.962370 10.77.56.205 3260 10.77.56.135 49153 iSCSI 166 112 [TCP
Retransmission] Login Response (Success) 17:35:37.160265
1105.963581 10.77.56.135 49153 10.77.56.205 3260 TCP 66 0 49153 > 3260
[ACK] Seq=189 Ack=113 Win=65536 Len=0 SLE=1 SRE=113 17:35:37.161476
1114.850385 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 NOP In
17:35:46.048280
1114.854154 10.77.56.135 49244 10.77.56.205 3260 iSCSI 102 48 NOP Out
17:35:46.052049
1114.854170 10.77.56.205 3260 10.77.56.135 49244 TCP 54 0 3260 > 49244
[ACK] Seq=3601 Ack=3601 Win=11169 Len=0 17:35:46.052065
1129.890379 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 NOP In
17:36:01.088274
1130.094370 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:01.292265
1130.298370 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:01.496265
1130.706369 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:01.904264
1131.526369 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:02.724264
1133.162370 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:04.360265
1136.434384 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:07.632279
1142.978386 10.77.56.205 3260 10.77.56.135 49244 iSCSI 102 48 [TCP
Retransmission] NOP In 17:36:14.176281
And the windows desktop stuck in BSOD with the error code
'KERNEL_DATA_INPAGE_ERROR'
when this happened.
I just wonder if this is an already fixed issue or I am doing something
wrong.
Thank you in advance.
--Jae-Wan Jang [JJ]
--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
