logger.c: Fix deadlocks due to blocked writes.

When a large amount of data is being logged,
libc_write will get stuck because the file
descriptors for remote console logging are
blocking. We now make them nonblocking
whenever we write to them, and this resolves
that issue.

Granted, we may lose some messages on remote
consoles by doing this, but if that's happening,
there's likely another bug triggering an
avalanche of log messages that needs investigating.

Other related improvements that improve dealing
with large amounts of I/O:

* bbs_write can fail to write all of the bytes.
  We retry this in a loop (as we should), but
  instead of a tight loop or an arbitrarily
  less tight loop, use the POLLOUT event
  to time the write optimally.
* If a pseudoterminal write operation returns -1,
  shut down the PTY.

Fixes #13

bbs/logger.c

@@ -32,6 +32,7 @@
 #include <sys/stat.h> /* use mkdir */
 #include <sys/types.h>
 #include <pthread.h>
+#include <poll.h>
 
 #include "include/utils.h" /* use bbs_gettid, bbs_tvnow */
 #include "include/linkedlists.h"
@@ -439,9 +440,12 @@ void __attribute__ ((format (gnu_printf, 6, 7))) __bbs_log(enum bbs_log_level lo
 		term_puts(fullbuf);
 		RWLIST_RDLOCK(&remote_log_fds);
 		RWLIST_TRAVERSE(&remote_log_fds, rfd, entry) {
+			/* Prevent libc_write from blocking if there's a ton of logging going on. */
+			bbs_unblock_fd(rfd->fd);
 			if (fd_logging[rfd->fd]) {
 				write(rfd->fd, fullbuf, (size_t) bytes);
 			}
+			bbs_block_fd(rfd->fd);
 		}
 		RWLIST_UNLOCK(&remote_log_fds);
 		if (fulldynamic) {

bbs/pty.c

@@ -136,12 +136,12 @@ static void *pty_master_fd(void *varg)
 	struct pty_fds *ptyfds = varg;
 	struct pollfd fds[2];
 	char buf[4096]; /* According to termios(3) man page, the canonical mode buffer of the PTY is 4096, so this should always be large enough */
-	size_t bytes_read, bytes_wrote;
+	ssize_t bytes_read, bytes_wrote;
 
 	/* Save relevant fields. */
 	fds[0].fd = ptyfds->fd;
 	fds[1].fd = ptyfds->amaster;
-	fds[0].events = fds[1].events = POLLIN;
+	fds[0].events = fds[1].events = POLLIN | POLLPRI | POLLERR | POLLNVAL;
 	free(ptyfds);
 
 	bbs_debug(10, "Starting generic PTY master for %d <=> %d\n", fds[1].fd, fds[0].fd);
@@ -162,27 +162,37 @@ static void *pty_master_fd(void *varg)
 			continue;
 		}
 		if (fds[0].revents & POLLIN) { /* Got input on socket -> pty */
-			bytes_read = (size_t) read(fds[0].fd, buf, sizeof(buf));
+			bytes_read = read(fds[0].fd, buf, sizeof(buf));
 			if (bytes_read <= 0) {
 				close(fds[1].fd); /* Close the other side */
 				close(fds[0].fd); /* Close our side, since nobody else will */
 				break; /* We'll read 0 bytes upon disconnect */
 			}
-			bytes_wrote = (size_t) write(fds[1].fd, buf, bytes_read);
+			bytes_wrote = write(fds[1].fd, buf, (size_t) bytes_read);
 			if (bytes_wrote != bytes_read) {
-				bbs_error("Expected to write %ld bytes, only wrote %ld\n", bytes_read, bytes_wrote);
+				bbs_error("Expected to write %ld bytes, only wrote %ld (%s)\n", bytes_read, bytes_wrote, strerror(errno));
+				if (bytes_wrote == -1) {
+					close(fds[1].fd);
+					close(fds[0].fd);
+					break;
+				}
 			}
 		} else if (fds[1].revents & POLLIN) { /* Got input from pty -> socket */
-			bytes_read = (size_t) read(fds[1].fd, buf, sizeof(buf) - 1);
+			bytes_read = read(fds[1].fd, buf, sizeof(buf) - 1);
 			if (bytes_read <= 0) {
 				bbs_debug(10, "pty master read returned %ld (%s)\n", bytes_read, strerror(errno));
 				close(fds[0].fd); /* Close the other side */
 				close(fds[1].fd); /* Close our side, since nobody else will */
 				break; /* We'll read 0 bytes upon disconnect */
 			}
-			bytes_wrote = (size_t) write(fds[0].fd, buf, bytes_read);
+			bytes_wrote = write(fds[0].fd, buf, (size_t) bytes_read);
 			if (bytes_wrote != bytes_read) {
-				bbs_error("Expected to write %ld bytes, only wrote %ld\n", bytes_read, bytes_wrote);
+				bbs_error("Expected to write %ld bytes, only wrote %ld (%s)\n", bytes_read, bytes_wrote, strerror(errno));
+				if (bytes_wrote == -1) {
+					close(fds[1].fd);
+					close(fds[0].fd);
+					break;
+				}
 			}
 		} else {
 			break;

bbs/socket.c

@@ -1929,8 +1929,13 @@ int bbs_node_write(struct bbs_node *node, const char *buf, size_t len)
 
 int bbs_write(int fd, const char *buf, size_t len)
 {
+	struct pollfd pfd;
 	size_t left = len;
 	size_t written = 0;
+
+	pfd.fd = fd;
+	pfd.events = POLLOUT;
+
 	for (;;) {
 		ssize_t res = write(fd, buf, left);
 		if (res <= 0) {
@@ -1943,7 +1948,10 @@ int bbs_write(int fd, const char *buf, size_t len)
 		if (left <= 0) {
 			break;
 		}
-		usleep(10); /* Avoid tight loop */
+		/* Instead of just usleep'ing for an arbitrary time, poll to wait until this file descriptor is writable again.
+		 * If it's still not writable after 10 ms, we'll just try again anyways. */
+		pfd.revents = 0;
+		res = poll(&pfd, 1, 10); /* Avoid tight loop */
 	}
 	return (int) written;
 }

tests/test_imap.c

@@ -655,12 +655,16 @@ static int run(void)
 	dprintf(client1, "e13 ENABLE QRESYNC" ENDL);
 	CLIENT_EXPECT(client1, "QRESYNC");
 
+	usleep(10000);
+
 	dprintf(client1, "e14 SELECT INBOX (QRESYNC (%u 1))" ENDL, uidvalidity);
 	CLIENT_EXPECT_EVENTUALLY(client1, "FETCH"); /* Should get all flag changes since MODSEQ 1 */
 	CLIENT_DRAIN(client1);
 
+	/* Added this NOOP to resolve e15 failing in the CI (but not locally). e15 wouldn't be received by the IMAP server,
+	 * and I guess this gives us some wiggle room there to compensate */
 	SWRITE(client1, "e15a NOOP" ENDL);
-	CLIENT_EXPECT(client1, "e15a OK");
+	CLIENT_EXPECT_EVENTUALLY(client1, "e15a OK");
 
 	dprintf(client1, "e15 SELECT INBOX (QRESYNC (%u 1))" ENDL, uidvalidity);
 	CLIENT_EXPECT_EVENTUALLY(client1, "VANISHED"); /* Repeat, to make sure we also got a VANISHED response */