4 commits - src/cmd.c src/delta_lease.c src/delta_lease.h src/direct.c src/diskio.c src/diskio.h src/lockspace.c src/main.c src/sanlock.8 src/sanlock.conf src/sanlock_internal.h src/task.c

[David Teigland]

 src/cmd.c              |    2 +
 src/delta_lease.c      |   43 +++++++++++++++++++++++------
 src/delta_lease.h      |    1 
 src/direct.c           |    1 
 src/diskio.c           |   72 +++++++++++++++++++++++++++++++++++--------------
 src/diskio.h           |    2 -
 src/lockspace.c        |   19 ++++++++++--
 src/main.c             |    8 +++++
 src/sanlock.8          |    4 ++
 src/sanlock.conf       |    3 ++
 src/sanlock_internal.h |    3 ++
 src/task.c             |   29 ++++++++++++++-----
 12 files changed, 146 insertions(+), 41 deletions(-)

New commits:
commit adbeb34efaf1fefb40ef5b88444282572891ef7a
Author: David Teigland <teigland(a)redhat.com&gt;
Date:   Mon Jan 25 14:40:40 2016 -0600

    sanlock: man page reference to sanlock.conf

diff --git a/src/sanlock.8 b/src/sanlock.8
index c605b64..6078a5f 100644
--- a/src/sanlock.8
+++ b/src/sanlock.8
@@ -1038,6 +1038,10 @@ renewed its delta_lease for a specific length of time, then the
owner
 value in the paxos_lease becomes expired, and other hosts will use the
 paxos algorithm to acquire the paxos_lease, and set a new owner.
 
+.SH FILES
+
+/etc/sanlock/sanlock.conf
+
 .SH SEE ALSO
 .BR wdmd (8)
 


commit 0257ef138eff2c9dde4e5f90261e4a916e53b880
Author: David Teigland <teigland(a)redhat.com&gt;
Date:   Fri Jan 22 16:59:49 2016 -0600

    sanlock: tolerate longer read delays in renewal
    
    Previously, a renewal read that timed out was abandoned and
    then retried.  If the first read actually completed during
    the second (retried) read, the first would be ignored, despite
    the fact that it could be used.
    
    Now, a timed out read is given an extra io timeout interval to
    complete as part of the subsequent renewal retry.  If the first
    read completes during the first phase of the second retry read,
    it will be used.
    
    This effectively doubles the length of time that renewal reads
    can persistently take without having any negative effect on
    the operation of the lockspace.
    
    If read io was persistently taking just longer than the io
    timeout, lease renewal would never get beyond the read phase,
    and the lockspace would enter recovery mode.  Now, the read
    io can be persistently delayed by up to twice the io timeout
    before this happens.  Furthermore, the extended timeout for
    the read can be configured to be even longer, to compensate
    for reads that are persistently delayed even longer.  The
    effect of extending the read timeout is that the time allowed
    for the renewal write to complete is reduced.  The read and
    the write for a renewal must still both complete within
    the same time limit before the renewal is considered to
    have failed and the lockspace enters recovery mode.

diff --git a/src/cmd.c b/src/cmd.c
index c2f05ba..997ec21 100644
--- a/src/cmd.c
+++ b/src/cmd.c
@@ -2167,6 +2167,7 @@ static int print_state_lockspace(struct space *sp, char *str, const
char *list_n
 		 "used_retries=%u "
 		 "external_used=%d "
 		 "used_by_orphans=%d "
+		 "renewal_read_extend_sec=%u "
 		 "corrupt_result=%d "
 		 "acquire_last_result=%d "
 		 "renewal_last_result=%d "
@@ -2184,6 +2185,7 @@ static int print_state_lockspace(struct space *sp, char *str, const
char *list_n
 		 sp->used_retries,
 		 (sp->flags & SP_EXTERNAL_USED) ? 1 : 0,
 		 (sp->flags & SP_USED_BY_ORPHANS) ? 1 : 0,
+		 sp->renewal_read_extend_sec,
 		 sp->lease_status.corrupt_result,
 		 sp->lease_status.acquire_last_result,
 		 sp->lease_status.renewal_last_result,
diff --git a/src/delta_lease.c b/src/delta_lease.c
index 3d5189c..3cf98fb 100644
--- a/src/delta_lease.c
+++ b/src/delta_lease.c
@@ -474,6 +474,7 @@ int delta_lease_renew(struct task *task,
 	char **p_wbuf;
 	char *wbuf;
 	uint32_t checksum;
+	uint32_t reap_timeout_msec;
 	uint64_t host_id, id_offset, new_ts, now;
 	int rv, iobuf_len, sector_size;
 
@@ -516,9 +517,18 @@ int delta_lease_renew(struct task *task,
 			goto skip_reap;
 		}
 
-		/* only wait .5 sec when trying to reap a prev io */
+		log_space(sp, "delta_renew begin reap");
+
+		if (!sp->renewal_read_extend_sec) {
+			/* only wait .5 sec when trying to reap a prev io to clear it */
+			reap_timeout_msec = 500;
+		} else {
+			/* effectively continue/extend the read phase from the previous renewal */
+			reap_timeout_msec = sp->renewal_read_extend_sec * 1000;
+		}
+
 		rv = read_iobuf_reap(disk->fd, disk->offset,
-				     task->iobuf, iobuf_len, task, 500000000);
+				     task->iobuf, iobuf_len, task, reap_timeout_msec);
 
 		log_space(sp, "delta_renew reap %d", rv);
 
diff --git a/src/diskio.c b/src/diskio.c
index 218fab1..d5f06f2 100644
--- a/src/diskio.c
+++ b/src/diskio.c
@@ -780,7 +780,7 @@ int read_sectors(const struct sync_disk *disk, uint64_t sector_nr,
    task->read_iobuf_timeout_aicb . */
 
 int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-		    struct task *task, int ioto)
+		    struct task *task, uint32_t ioto_msec)
 {
 	struct timespec ts;
 	struct aicb *aicb;
@@ -805,7 +805,8 @@ int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int
iobuf_len,
 		return -EINVAL;
 
 	memset(&ts, 0, sizeof(struct timespec));
-	ts.tv_nsec = ioto;
+	ts.tv_sec = ioto_msec / 1000;
+	ts.tv_nsec = (ioto_msec % 1000) * 1000000;
  retry:
 	memset(&event, 0, sizeof(event));
 
diff --git a/src/diskio.h b/src/diskio.h
index db00cfe..d2c5be1 100644
--- a/src/diskio.h
+++ b/src/diskio.h
@@ -27,7 +27,7 @@ int read_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
 	       struct task *task, int ioto);
 
 int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-		    struct task *task, int ioto);
+		    struct task *task, uint32_t ioto_msec);
 
 /*
  * sector functions allocate an iobuf themselves, copy into it for read, use it
diff --git a/src/lockspace.c b/src/lockspace.c
index bc8849f..b7f2e9c 100644
--- a/src/lockspace.c
+++ b/src/lockspace.c
@@ -811,6 +811,11 @@ int add_lockspace_start(struct sanlk_lockspace *ls, uint32_t
io_timeout, struct
 	sp->set_bitmap_seconds = calc_set_bitmap_seconds(io_timeout);
 	pthread_mutex_init(&sp->mutex, NULL);
 
+	if (com.renewal_read_extend_sec_set)
+		sp->renewal_read_extend_sec = com.renewal_read_extend_sec;
+	else
+		sp->renewal_read_extend_sec = io_timeout;
+
 	for (i = 0; i < MAX_EVENT_FDS; i++)
 		sp->event_fds[i] = -1;
 
diff --git a/src/main.c b/src/main.c
index 25d0819..af7c57c 100644
--- a/src/main.c
+++ b/src/main.c
@@ -2325,6 +2325,12 @@ static void read_config_file(void)
 			memset(str, 0, sizeof(str));
 			get_val_str(line, str);
 			strncpy(com.our_host_name, str, NAME_ID_SIZE);
+
+		} else if (!strcmp(str, "renewal_read_extend_sec")) {
+			/* zero is a valid setting so we need the _set field to say it's set */
+			get_val_int(line, &val);
+			com.renewal_read_extend_sec_set = 1;
+			com.renewal_read_extend_sec = val;
 		}
 	}
 
@@ -3181,6 +3187,8 @@ int main(int argc, char *argv[])
 	com.pid = -1;
 	com.sh_retries = DEFAULT_SH_RETRIES;
 	com.quiet_fail = DEFAULT_QUIET_FAIL;
+	com.renewal_read_extend_sec_set = 0;
+	com.renewal_read_extend_sec = 0;
 
 	if (getgrnam("sanlock") && getpwnam("sanlock")) {
 		com.uname = (char *)"sanlock";
diff --git a/src/sanlock.conf b/src/sanlock.conf
index 06b8647..062692f 100644
--- a/src/sanlock.conf
+++ b/src/sanlock.conf
@@ -37,4 +37,7 @@
 #
 # our_host_name = <str>
 # command line: -e <str>
+#
+# renewal_read_extend_sec = <seconds>
+# command line: n/a
 
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h
index 9a276d1..511b448 100644
--- a/src/sanlock_internal.h
+++ b/src/sanlock_internal.h
@@ -178,6 +178,7 @@ struct space {
 	uint32_t set_bitmap_seconds;
 	uint32_t flags; /* SP_ */
 	uint32_t used_retries;
+	uint32_t renewal_read_extend_sec; /* defaults to io_timeout */
 	int align_size;
 	int renew_fail;
 	int space_dead;
@@ -319,6 +320,8 @@ struct command_line {
 	int res_count;
 	int sh_retries;
 	uint32_t force_mode;
+	int renewal_read_extend_sec_set; /* 1 if renewal_read_extend_sec is configured */
+	uint32_t renewal_read_extend_sec;
 	char our_host_name[SANLK_NAME_LEN+1];
 	char *file_path;
 	char *dump_path;


commit 6dc88282bb83994ab2c25d73681d84b73a66cc77
Author: David Teigland <teigland(a)redhat.com&gt;
Date:   Fri Jan 22 14:41:20 2016 -0600

    sanlock: improve logging for renewals

diff --git a/src/delta_lease.c b/src/delta_lease.c
index ef1cb3c..3d5189c 100644
--- a/src/delta_lease.c
+++ b/src/delta_lease.c
@@ -464,6 +464,7 @@ int delta_lease_renew(struct task *task,
 		      struct delta_extra *extra,
 		      int prev_result,
 		      int *read_result,
+		      int log_renewal_level,
 		      struct leader_record *leader_last,
 		      struct leader_record *leader_ret)
 {
@@ -473,7 +474,7 @@ int delta_lease_renew(struct task *task,
 	char **p_wbuf;
 	char *wbuf;
 	uint32_t checksum;
-	uint64_t host_id, id_offset, new_ts;
+	uint64_t host_id, id_offset, new_ts, now;
 	int rv, iobuf_len, sector_size;
 
 	if (!leader_last) {
@@ -569,14 +570,21 @@ int delta_lease_renew(struct task *task,
 		}
 	}
 
+	if (log_renewal_level != -1)
+		log_level(sp->space_id, 0, NULL, log_renewal_level, "delta_renew begin
read");
+
 	rv = read_iobuf(disk->fd, disk->offset, task->iobuf, iobuf_len, task,
sp->io_timeout);
 	if (rv) {
 		/* the next time delta_lease_renew() is called, prev_result
 		   will be this rv.  If this rv is SANLK_AIO_TIMEOUT, we'll
 		   try to reap the event */
 
-		log_erros(sp, "delta_renew read rv %d offset %llu %s",
-			  rv, (unsigned long long)disk->offset, disk->path);
+		if (rv == SANLK_AIO_TIMEOUT)
+			log_erros(sp, "delta_renew read timeout %u sec offset %llu %s",
+				  sp->io_timeout, (unsigned long long)disk->offset, disk->path);
+		else
+			log_erros(sp, "delta_renew read rv %d offset %llu %s",
+				  rv, (unsigned long long)disk->offset, disk->path);
 		return rv;
 	}
 
@@ -625,9 +633,11 @@ int delta_lease_renew(struct task *task,
 
 	new_ts = monotime();
 
-	if (leader.timestamp >= new_ts) {
+	if (log_renewal_level != -1)
+		log_level(sp->space_id, 0, NULL, log_renewal_level, "delta_renew begin write
for new ts %llu", (unsigned long long)new_ts);
+
+	if (leader.timestamp >= new_ts)
 		log_erros(sp, "delta_renew timestamp too small");
-	}
 
 	leader.timestamp = new_ts;
 	leader.checksum = 0; /* set below */
@@ -670,11 +680,18 @@ int delta_lease_renew(struct task *task,
 	if (rv != SANLK_AIO_TIMEOUT)
 		free(wbuf);
 
+	now = monotime();
+
 	if (rv < 0) {
-		log_erros(sp, "delta_renew write error %d", rv);
+		log_erros(sp, "delta_renew write time %llu error %d",
+			  (unsigned long long)(now - new_ts), rv);
 		return rv;
 	}
 
+	if (now - new_ts >= sp->io_timeout)
+		log_erros(sp, "delta_renew long write time %llu sec",
+			  (unsigned long long)(now - new_ts));
+
 	/* the paper shows doing a delay and another read here, but it seems
 	   unnecessary since we do the same at the beginning of the next renewal */
 
diff --git a/src/delta_lease.h b/src/delta_lease.h
index 968c7c7..38c469a 100644
--- a/src/delta_lease.h
+++ b/src/delta_lease.h
@@ -33,6 +33,7 @@ int delta_lease_renew(struct task *task,
 		      struct delta_extra *extra,
                       int prev_result,
 		      int *read_result,
+		      int log_renewal_level,
                       struct leader_record *leader_last,
                       struct leader_record *leader_ret);
 
diff --git a/src/direct.c b/src/direct.c
index 2dbb098..c39988c 100644
--- a/src/direct.c
+++ b/src/direct.c
@@ -251,6 +251,7 @@ static int do_delta_action(int action,
 				       NULL,
 				       -1,
 				       &read_result,
+				       0,
 				       &leader,
 				       &leader);
 		break;
diff --git a/src/diskio.c b/src/diskio.c
index 7647094..218fab1 100644
--- a/src/diskio.c
+++ b/src/diskio.c
@@ -347,9 +347,17 @@ static struct aicb *find_callback_slot(struct task *task, int ioto)
 		struct iocb *ev_iocb = event.obj;
 		struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
 		int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
+		const char *op_str;
 
-		log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld old free",
-			  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+		if (op == IO_CMD_PREAD)
+			op_str = "RD";
+		else if (op == IO_CMD_PWRITE)
+			op_str = "WR";
+		else
+			op_str = "UK";
+
+		log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld old free",
+			  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 		ev_aicb->used = 0;
 		free(ev_aicb->buf);
 		ev_aicb->buf = NULL;
@@ -373,6 +381,7 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
 	struct aicb *aicb;
 	struct iocb *iocb;
 	struct io_event event;
+	const char *op_str;
 	int rv;
 
 	if (!ioto) {
@@ -426,24 +435,31 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int
len,
 		struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
 		int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
 
+		if (op == IO_CMD_PREAD)
+			op_str = "RD";
+		else if (op == IO_CMD_PWRITE)
+			op_str = "WR";
+		else
+			op_str = "UK";
+
 		ev_aicb->used = 0;
 
 		if (ev_iocb != iocb) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld other free",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld other free",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 			free(ev_aicb->buf);
 			ev_aicb->buf = NULL;
 			goto retry;
 		}
 		if ((int)event.res < 0) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match res",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match res",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 			rv = event.res;
 			goto out;
 		}
 		if (event.res != len) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match len %d",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, len);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match len %d",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, len);
 			rv = -EMSGSIZE;
 			goto out;
 		}
@@ -466,8 +482,15 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
 
 	task->to_count++;
 
-	log_taskw(task, "aio timeout %d %p:%p:%p ioto %d to_count %d",
-		  cmd, aicb, iocb, buf, ioto, task->to_count);
+	if (cmd == IO_CMD_PREAD)
+		op_str = "RD";
+	else if (cmd == IO_CMD_PWRITE)
+		op_str = "WR";
+	else
+		op_str = "UK";
+
+	log_taskw(task, "aio timeout %s %p:%p:%p ioto %d to_count %d",
+		  op_str, aicb, iocb, buf, ioto, task->to_count);
 
 	rv = io_cancel(task->aio_ctx, iocb, &event);
 	if (!rv) {
@@ -798,31 +821,39 @@ int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int
iobuf_len,
 		struct iocb *ev_iocb = event.obj;
 		struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
 		int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
+		const char *op_str;
+
+		if (op == IO_CMD_PREAD)
+			op_str = "RD";
+		else if (op == IO_CMD_PWRITE)
+			op_str = "WR";
+		else
+			op_str = "UK";
 
 		ev_aicb->used = 0;
 
 		if (ev_iocb != iocb) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld other free r",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld other free r",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 			free(ev_aicb->buf);
 			ev_aicb->buf = NULL;
 			goto retry;
 		}
 		if ((int)event.res < 0) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match res r",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match res r",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 			rv = event.res;
 			goto out;
 		}
 		if (event.res != iobuf_len) {
-			log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match len %d r",
-				  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, iobuf_len);
+			log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match len %d r",
+				  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, iobuf_len);
 			rv = -EMSGSIZE;
 			goto out;
 		}
 
-		log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match reap",
-			  op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+		log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match reap",
+			  op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
 
 		rv = 0;
 		goto out;
diff --git a/src/lockspace.c b/src/lockspace.c
index 24f75d6..bc8849f 100644
--- a/src/lockspace.c
+++ b/src/lockspace.c
@@ -547,6 +547,7 @@ static void *lockspace_thread(void *arg_in)
 	struct space *sp;
 	struct leader_record leader;
 	uint64_t delta_begin, last_success = 0;
+	int log_renewal_level = -1;
 	int rv, delta_length, renewal_interval = 0;
 	int id_renewal_seconds, id_renewal_fail_seconds;
 	int acquire_result, delta_result, read_result;
@@ -554,6 +555,9 @@ static void *lockspace_thread(void *arg_in)
 	int stop = 0;
 	int wd_con;
 
+	if (com.debug_renew)
+		log_renewal_level = LOG_DEBUG;
+
 	sp = (struct space *)arg_in;
 
 	memset(&task, 0, sizeof(struct task));
@@ -652,7 +656,6 @@ static void *lockspace_thread(void *arg_in)
 		if (stop)
 			break;
 
-
 		/*
 		 * wait between each renewal
 		 */
@@ -681,6 +684,7 @@ static void *lockspace_thread(void *arg_in)
 		delta_result = delta_lease_renew(&task, sp, &sp->host_id_disk,
 						 sp->space_name, bitmap, &extra,
 						 delta_result, &read_result,
+						 log_renewal_level,
 						 &leader, &leader);
 		delta_length = monotime() - delta_begin;
 
@@ -732,9 +736,11 @@ static void *lockspace_thread(void *arg_in)
 		} else if (delta_length > id_renewal_seconds) {
 			log_erros(sp, "renewed %llu delta_length %d too long",
 				  (unsigned long long)last_success, delta_length);
-		} else if (com.debug_renew) {
-			log_space(sp, "renewed %llu delta_length %d interval %d",
-				  (unsigned long long)last_success, delta_length, renewal_interval);
+		} else {
+			if (com.debug_renew) {
+				log_space(sp, "renewed %llu delta_length %d interval %d",
+					  (unsigned long long)last_success, delta_length, renewal_interval);
+			}
 		}
 	}
 


commit 64fc348a616ce622ae3611835144699a2a84ed6d
Author: David Teigland <teigland(a)redhat.com&gt;
Date:   Fri Jan 22 12:00:02 2016 -0600

    sanlock: use io_destroy to clear outstanding aio
    
    When a lockspace thread attempts to clear outstanding
    aio ops, it was using io_getevents indefinitely to wait
    for completions.  Now, it uses io_getevents to clear the
    ops for up to 2 minutes, after which it uses io_destroy
    to clear them.  io_destroy may have the ability clear
    certain ops that will never have a completion.

diff --git a/src/task.c b/src/task.c
index 144f5f8..f3c10f8 100644
--- a/src/task.c
+++ b/src/task.c
@@ -68,7 +68,9 @@ void close_task_aio(struct task *task)
 	struct timespec ts;
 	struct io_event event;
 	uint64_t last_warn;
-	int rv, i, used, warn;
+	uint64_t begin;
+	uint64_t now;
+	int rv, i, used, lvl;
 
 	if (!task->use_aio)
 		goto skip_aio;
@@ -77,16 +79,19 @@ void close_task_aio(struct task *task)
 	ts.tv_sec = DEFAULT_IO_TIMEOUT;
 
 	last_warn = time(NULL);
+	begin = last_warn;
 
 	/* wait for all outstanding aio to complete before
 	   destroying aio context, freeing iocb and buffers */
 
 	while (1) {
-		warn = 0;
+		now = time(NULL);
 
-		if (time(NULL) - last_warn >= DEFAULT_IO_TIMEOUT) {
-			last_warn = time(NULL);
-			warn = 1;
+		if (now - last_warn >= (DEFAULT_IO_TIMEOUT * 6)) {
+			last_warn = now;
+			lvl = LOG_ERR;
+		} else {
+			lvl = LOG_DEBUG;
 		}
 
 		used = 0;
@@ -96,15 +101,16 @@ void close_task_aio(struct task *task)
 				continue;
 			used++;
 
-			if (!warn)
-				continue;
-			log_taske(task, "close_task_aio %d %p busy",
+			log_level(0, 0, task->name, lvl, "close_task_aio %d %p busy",
 				  i, &task->callbacks[i]);
 		}
 
 		if (!used)
 			break;
 
+		if (now - begin >= 120)
+			break;
+
 		memset(&event, 0, sizeof(event));
 
 		rv = io_getevents(task->aio_ctx, 1, 1, &event, &ts);
@@ -127,8 +133,15 @@ void close_task_aio(struct task *task)
 			ev_aicb->buf = NULL;
 		}
 	}
+
+	if (used)
+		log_taskd(task, "close_task_aio destroy %d incomplete ops", used);
+
 	io_destroy(task->aio_ctx);
 
+	if (used)
+		log_taske(task, "close_task_aio destroyed %d incomplete ops", used);
+
 	if (task->iobuf)
 		free(task->iobuf);