Timeouts: Fix bugs in scsi task timeout code

Add a test to verify the pdu timeout handling.
Fix numerous bugs in the timeout handling. It was really broken.

Add test for non-SCSI task PDUs too and verify they works.

Signed-off-by: Ronnie Sahlberg <ronniesahlberg@gmail.com>

include/iscsi.h

@@ -83,9 +83,44 @@ EXTERN int iscsi_service(struct iscsi_context *iscsi, int revents);
  */
 EXTERN int iscsi_queue_length(struct iscsi_context *iscsi);
 
+/************************************************************
+ * Timeout Handling.
+ * Libiscsi does not use or interface with any system timers.
+ * Instead all timeout processing in libiscsi is done as part
+ * of the iscsi_service() processing.
+ *
+ * This means that if you use the timeout function below you must
+ * device your application to call out to iscsi_service() at regular
+ * intervals.
+ * An easy way to do this is calling iscsi_service(iscsi, 0), i.e.
+ * by passing 0 as the revents arguments once every second or so.
+ ************************************************************/
+
 /*
- * Set the timeout in seconds after which a synchronous SCSI command
+ * Set the timeout in seconds after which a task/pdu will timeout.
- * will timeout.
+ * This timeout applies to SCSI task PDUs as well as normal iSCSI
+ * PDUs such as login/task management/logout/...
+ *
+ * Each PDU is assigned its timeout value upon creation and can not be
+ * changed afterwards. I.e. When you change the default timeout, it will
+ * only affect any commands that are issued in the future but will not
+ * affect the timeouts for any commands already in flight.
+ *
+ * The recommended usecase is to set to a default value for all PDUs
+ * and only change the default temporarily when a specific task needs
+ * a different timeout.
+ *
+ * // Set default to 5 seconds for all commands at beginning of program.
+ * iscsi_set_timeout(iscsi, 5);
+ *
+ * ...
+ * // SANITIZE command will take long so set it to no tiemout.
+ * iscsi_set_timeout(iscsi, 0);
+ * iscsi_sanitize_task(iscsi, ...
+ * iscsi_set_timeout(iscsi, <set back to original value>);
+ * ...
+ *
+ *
  * Default is 0 == no timeout.
  */
 EXTERN int iscsi_set_timeout(struct iscsi_context *iscsi, int timeout);

lib/iscsi-command.c

@@ -56,10 +56,13 @@ iscsi_scsi_response_cb(struct iscsi_context *iscsi, int status,
 	case SCSI_STATUS_TASK_ABORTED:
 	case SCSI_STATUS_ERROR:
 	case SCSI_STATUS_CANCELLED:
+	case SCSI_STATUS_TIMEOUT:
+		scsi_cbdata->task->status = status;
 		scsi_cbdata->callback(iscsi, status, scsi_cbdata->task,
 				      scsi_cbdata->private_data);
 		return;
 	default:
+		scsi_cbdata->task->status = SCSI_STATUS_ERROR;
 		iscsi_set_error(iscsi, "Cant handle  scsi status %d yet.",
 				status);
 		scsi_cbdata->callback(iscsi, SCSI_STATUS_ERROR, scsi_cbdata->task,
@@ -148,44 +151,6 @@ iscsi_send_data_out(struct iscsi_context *iscsi, struct iscsi_pdu *cmd_pdu,
 	return 0;
 }
 
-void
-iscsi_timeout_scan(struct iscsi_context *iscsi)
-{
-	struct iscsi_pdu *pdu;
-	struct iscsi_pdu *next_pdu;
-	time_t t = time(NULL);
-
-	for (pdu = iscsi->waitpdu; pdu; pdu = next_pdu) {
-		struct iscsi_scsi_cbdata *scsi_cbdata;
-		struct scsi_task *task;
-
-		next_pdu = pdu->next;
-
-		if (pdu->scsi_timeout == 0) {
-			/* no timeout for this pdu */
-			continue;
-		}
-		if (t < pdu->scsi_timeout) {
-			/* not expired yet */
-			continue;
-		}
-		if (pdu->outdata.data[0] != ISCSI_PDU_SCSI_REQUEST) {
-			continue;
-		}
-
-		scsi_cbdata = &pdu->scsi_cbdata;
-		task = scsi_cbdata->task;
-
-		ISCSI_LIST_REMOVE(&iscsi->waitpdu, pdu);
-		pdu->callback(iscsi, SCSI_STATUS_TIMEOUT,
-				task, pdu->private_data);
-		iscsi_set_error(iscsi, "SCSI command timed out");
-
-		/* task is freed by the sync caller */
-		task->status = SCSI_STATUS_TIMEOUT;
-	}
-}
-
 static int
 iscsi_send_unsolicited_data_out(struct iscsi_context *iscsi, struct iscsi_pdu *pdu)
 {
@@ -1938,4 +1903,3 @@ iscsi_scsi_cancel_all_tasks(struct iscsi_context *iscsi)
 		iscsi_free_pdu(iscsi, pdu);
 	}
 }
-

lib/pdu.c

@@ -686,3 +686,42 @@ iscsi_pdu_set_expxferlen(struct iscsi_pdu *pdu, uint32_t expxferlen)
 	pdu->expxferlen = expxferlen;
 	scsi_set_uint32(&pdu->outdata.data[20], expxferlen);
 }
+
+void
+iscsi_timeout_scan(struct iscsi_context *iscsi)
+{
+	struct iscsi_pdu *pdu;
+	struct iscsi_pdu *next_pdu;
+	time_t t = time(NULL);
+
+	for (pdu = iscsi->outqueue; pdu; pdu = next_pdu) {
+		next_pdu = pdu->next;
+
+		if (pdu->scsi_timeout == 0) {
+			/* no timeout for this pdu */
+			continue;
+		}
+		if (t < pdu->scsi_timeout) {
+			/* not expired yet */
+			continue;
+		}
+		ISCSI_LIST_REMOVE(&iscsi->outqueue, pdu);
+		pdu->callback(iscsi, SCSI_STATUS_TIMEOUT,
+			      NULL, pdu->private_data);
+	}
+	for (pdu = iscsi->waitpdu; pdu; pdu = next_pdu) {
+		next_pdu = pdu->next;
+
+		if (pdu->scsi_timeout == 0) {
+			/* no timeout for this pdu */
+			continue;
+		}
+		if (t < pdu->scsi_timeout) {
+			/* not expired yet */
+			continue;
+		}
+		ISCSI_LIST_REMOVE(&iscsi->waitpdu, pdu);
+		pdu->callback(iscsi, SCSI_STATUS_TIMEOUT,
+			      NULL, pdu->private_data);
+	}
+}

lib/socket.c

@@ -889,6 +889,8 @@ iscsi_service(struct iscsi_context *iscsi, int revents)
 			return iscsi_service_reconnect_if_loggedin(iscsi);
 		}
 	}
+	iscsi_timeout_scan(iscsi);
+
 	return 0;
 }
 

lib/sync.c

@@ -53,6 +53,8 @@ event_loop(struct iscsi_context *iscsi, struct iscsi_sync_state *state)
 	int ret;
 
 	while (state->finished == 0) {
+		short revents;
+
 		pfd.fd = iscsi_get_fd(iscsi);
 		pfd.events = iscsi_which_events(iscsi);
 
@@ -61,11 +63,8 @@ event_loop(struct iscsi_context *iscsi, struct iscsi_sync_state *state)
 			state->status = -1;
 			return;
 		}
-		if (ret == 0) {
+		revents = (ret == 0) ? 0 : pfd.revents;
-			iscsi_timeout_scan(iscsi);
+		if (iscsi_service(iscsi, revents) < 0) {
-			continue;
-		}
-		if (iscsi_service(iscsi, pfd.revents) < 0) {
 			iscsi_set_error(iscsi,
 				"iscsi_service failed with : %s",
 				iscsi_get_error(iscsi));

tests/Makefile.am

@@ -3,7 +3,8 @@ AM_CPPFLAGS = -I../include "-D_U_=__attribute__((unused))" \
 AM_CFLAGS = $(WARN_CFLAGS)
 LDADD = ../lib/libiscsi.la
 
-noinst_PROGRAMS = prog_reconnect prog_reconnect_timeout prog_noop_reply
+noinst_PROGRAMS = prog_reconnect prog_reconnect_timeout prog_noop_reply \
+	prog_timeout
 
 T = `ls test_*.sh`
 

tests/prog_timeout.c

@@ -0,0 +1,228 @@
+/* 
+   Copyright (C) 2015 by Ronnie Sahlberg <ronniesahlberg@gmail.com>
+   
+   This program is free software; you can redistribute it and/or modify
+   it under the terms of the GNU General Public License as published by
+   the Free Software Foundation; either version 2 of the License, or
+   (at your option) any later version.
+   
+   This program is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+   GNU General Public License for more details.
+   
+   You should have received a copy of the GNU General Public License
+   along with this program; if not, see <http://www.gnu.org/licenses/>.
+*/
+#ifdef HAVE_CONFIG_H
+#include "config.h"
+#endif
+
+#ifdef HAVE_POLL_H
+#include <poll.h>
+#endif
+
+#ifdef HAVE_UNISTD_H
+#include <unistd.h>
+#endif
+#include <getopt.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <string.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+#include "iscsi.h"
+#include "iscsi-private.h"
+#include "scsi-lowlevel.h"
+
+#ifndef discard_const
+#define discard_const(ptr) ((void *)((intptr_t)(ptr)))
+#endif
+
+const char *initiator = "iqn.2007-10.com.github:sahlberg:libiscsi:prog-timeout";
+
+void print_usage(void)
+{
+	fprintf(stderr, "Usage: prog_timeout [-?|--help] [--usage] "
+		"[-i|--initiator-name=iqn-name]\n"
+		"\t\t<iscsi-portal-url>\n");
+	fprintf(stderr, "\n");
+	fprintf(stderr, "This command is used to test that if we do not "
+		"receive a responmse we recognize to a task that we will "
+		"trigger the task timeout.\n");
+}
+
+void print_help(void)
+{
+	fprintf(stderr, "Usage: prog_timeout [OPTION...] <iscsi-url>\n");
+	fprintf(stderr, "  -i, --initiator-name=iqn-name     "
+		"Initiatorname to use\n");
+	fprintf(stderr, "\n");
+	fprintf(stderr, "Help options:\n");
+	fprintf(stderr, "  -?, --help                        "
+		"Show this help message\n");
+	fprintf(stderr, "      --usage                       "
+		"Display brief usage message\n");
+	fprintf(stderr, "\n");
+	fprintf(stderr, "iSCSI Portal URL format : %s\n",
+		ISCSI_PORTAL_URL_SYNTAX);
+	fprintf(stderr, "\n");
+	fprintf(stderr, "<host> is either of:\n");
+	fprintf(stderr, "  \"hostname\"       iscsi.example\n");
+	fprintf(stderr, "  \"ipv4-address\"   10.1.1.27\n");
+	fprintf(stderr, "  \"ipv6-address\"   [fce0::1]\n");
+}
+
+void tur_cb(struct iscsi_context *iscsi _U_, int status, void *command_data _U_, void *private_data)
+{
+	uint32_t *i = private_data;
+
+	(*i)--;
+
+	printf("testunitready cb\n");
+	if (status != SCSI_STATUS_TIMEOUT) {
+		printf("Failed. We did NOT get a TIMEOUT error for the SCSI "
+		       "task\n");
+		exit(10);
+	}
+}
+
+void logout_cb(struct iscsi_context *iscsi _U_, int status, void *command_data _U_, void *private_data)
+{
+	uint32_t *i = private_data;
+
+	(*i)--;
+
+	printf("logout command cb\n");
+	if (status != SCSI_STATUS_TIMEOUT) {
+		printf("Failed. We did NOT get a TIMEOUT error for the iSCSI "
+		       "logout command\n");
+		exit(10);
+	}
+}
+
+int main(int argc, char *argv[])
+{
+	struct iscsi_context *iscsi;
+	struct iscsi_url *iscsi_url = NULL;
+	const char *url = NULL;
+	int c;
+	static int show_help = 0, show_usage = 0, debug = 0;
+	uint32_t count;
+
+	static struct option long_options[] = {
+		{"help",           no_argument,          NULL,        'h'},
+		{"usage",          no_argument,          NULL,        'u'},
+		{"debug",          no_argument,          NULL,        'd'},
+		{"initiator-name", required_argument,    NULL,        'i'},
+		{0, 0, 0, 0}
+	};
+	int option_index;
+
+	while ((c = getopt_long(argc, argv, "h?uUdi:s", long_options,
+			&option_index)) != -1) {
+		switch (c) {
+		case 'h':
+		case '?':
+			show_help = 1;
+			break;
+		case 'u':
+			show_usage = 1;
+			break;
+		case 'd':
+			debug = 1;
+			break;
+		case 'i':
+			initiator = optarg;
+			break;
+		default:
+			fprintf(stderr, "Unrecognized option '%c'\n\n", c);
+			print_help();
+			exit(0);
+		}
+	}
+
+	if (show_help != 0) {
+		print_help();
+		exit(0);
+	}
+
+	if (show_usage != 0) {
+		print_usage();
+		exit(0);
+	}
+
+	if (optind != argc -1) {
+		print_usage();
+		exit(0);
+	}
+
+	if (argv[optind] != NULL) {
+		url = strdup(argv[optind]);
+	}
+	if (url == NULL) {
+		fprintf(stderr, "You must specify iscsi target portal.\n");
+		print_usage();
+		exit(10);
+	}
+
+	iscsi = iscsi_create_context(initiator);
+	if (iscsi == NULL) {
+		printf("Failed to create context\n");
+		exit(10);
+	}
+
+	if (debug > 0) {
+		iscsi_set_log_level(iscsi, debug);
+		iscsi_set_log_fn(iscsi, iscsi_log_to_stderr);
+	}
+
+	iscsi_url = iscsi_parse_full_url(iscsi, url);
+	
+	if (url) {
+		free(discard_const(url));
+	}
+
+	if (iscsi_url == NULL) {
+		fprintf(stderr, "Failed to parse URL: %s\n", 
+			iscsi_get_error(iscsi));
+		exit(10);
+	}
+
+	iscsi_set_session_type(iscsi, ISCSI_SESSION_NORMAL);
+
+	if (iscsi_full_connect_sync(iscsi, iscsi_url->portal, iscsi_url->lun)
+	    != 0) {
+		fprintf(stderr, "iscsi_connect failed. %s\n",
+			iscsi_get_error(iscsi));
+		exit(10);
+	}
+
+	iscsi_set_timeout(iscsi, 3);
+	count=0;
+
+	printf("Send a TUR we will never get a reply for\n");
+	count++;
+	iscsi_testunitready_task(iscsi, iscsi_url->lun, tur_cb, &count);
+
+	printf("Send a LOGOUT we will never get a reply for\n");
+	count++;
+	iscsi_logout_async(iscsi, logout_cb, &count);
+
+
+	printf("Spin on iscsi_service(iscsi, 0) until all callbacks are "
+	       "triggered\n");
+	while (count) {
+	      	iscsi_service(iscsi, 0);
+	      	sleep(1);
+	}
+	printf("yey, we got all timeouts we expected\n");
+
+	iscsi_destroy_url(iscsi_url);
+	iscsi_destroy_context(iscsi);
+	return 0;
+}
+

tests/test_2100_timeout.sh

@@ -0,0 +1,17 @@
+#!/bin/sh
+
+. ./functions.sh
+
+echo "Basic iSCSI Timeout test"
+
+start_target
+create_lun
+
+echo -n "Test that timeouts trigger when we get no reply to an iSCSI PDU..."
+./prog_timeout -i ${IQNINITIATOR} iscsi://${TGTPORTAL}/${IQNTARGET}/1 || failure
+success
+
+shutdown_target
+delete_lun
+
+exit 0