readline.c: Fix reading when delimiter is split across reads.

If the first part of the delimiter is read into the end of
the buffer, and only later is there enough room in the
buffer to read further, even though things will get shifted
up to the front of the buffer properly, after reading the
rest of the delimiter, the code was only scanning for the
full delimiter starting at what was just read. This works
if the delimiter is only a single character, but does not
work for multi-byte delimiters (e.g. CR LF). This was observed
to cause readline to block improperly, where it didn't think
the delimiter had been received, even though it had, since
it needed to start looking for the full delimiter starting
from a character before.

This is now fixed, and tests have also been added to ensure
the correct behavior (these failed originally, but now pass).

bbs/readline.c

@@ -52,7 +52,7 @@ void bbs_readline_flush(struct readline_data *rldata)
 	rldata->leftover = 0;
 }
 
-static char *readline_pre_read(struct readline_data *restrict rldata, const char *delim, ssize_t *resptr)
+static char *readline_pre_read(struct readline_data *restrict rldata, const char *delim, size_t delimlen, ssize_t *resptr)
 {
 	char *firstdelim = NULL;
 
@@ -70,7 +70,7 @@ static char *readline_pre_read(struct readline_data *restrict rldata, const char
 		rldata->left = rldata->len - res;
 		/* If we already have a delimiter, no need to proceed further. */
 		/* Use memmem instead of strstr to accomodate binary data */
-		firstdelim = memmem(rldata->buf, res, delim, strlen(delim)); /* Use buf, not pos, since pos is the beginning of the buffer that remains at this point. */
+		firstdelim = memmem(rldata->buf, res, delim, delimlen); /* Use buf, not pos, since pos is the beginning of the buffer that remains at this point. */
 		res = rldata->leftover = 0;
 		rldata->leftover = 0;
 		*resptr = (ssize_t) res;
@@ -80,7 +80,7 @@ static char *readline_pre_read(struct readline_data *restrict rldata, const char
 			 * but bbs_readline_append can return without calling readline_post_read,
 			 * so we should not reset pos to buf if the next chunk is incomplete. */
 #ifdef EXTRA_DEBUG
-			bbs_debug(8," Resetting buffer\n");
+			bbs_debug(8, "Resetting buffer\n");
 #endif
 			readline_buffer_reset(rldata);
 		}
@@ -126,15 +126,24 @@ ssize_t bbs_readline(int fd, struct readline_data *restrict rldata, const char *
 {
 	ssize_t res;
 	char *firstdelim;
+	size_t delimlen;
 
-	firstdelim = readline_pre_read(rldata, delim, &res);
+	delimlen = strlen(delim);
+	firstdelim = readline_pre_read(rldata, delim, delimlen, &res);
 
 	while (!firstdelim) {
+		char *searchstart;
 #ifdef EXTRA_CHECKS
+#ifdef INTENSIVE_EXTRA_CHECKS
+		char *t = memchr(rldata->buf, '\0', rldata->len);
+		int left = (int) (t - rldata->buf);
+		bbs_assert(!memmem(rldata->buf, (size_t) left, delim, delimlen));
+#endif /* INTENSIVE_EXTRA_CHECKS */
 		bbs_assert(rldata->pos + rldata->left - 1 <= rldata->buf + rldata->len); /* If we're going to corrupt the stack and crash anyways, might as well assert. */
-#endif
+#endif /* EXTRA_CHECKS */
 		if (rldata->left - 1 < 2) {
-			bbs_warning("Buffer (size %lu) has been exhausted\n", rldata->len); /* The using application needs to allocate a larger buffer */
+			bbs_warning("Buffer (size %lu) has been exhausted, %lu byte%s remaining\n", rldata->len, rldata->left, ESS(rldata->left)); /* The using application needs to allocate a larger buffer */
+			bbs_assert(!strstr(rldata->pos, delim));
 			return -3;
 		}
 		res = bbs_poll_read(fd, timeout, rldata->pos, (size_t) rldata->left - 1); /* Subtract 1 for NUL */
@@ -143,10 +152,31 @@ ssize_t bbs_readline(int fd, struct readline_data *restrict rldata, const char *
 			return res - 1; /* see the doxygen notes: we should return 0 only if we read just the delimiter. */
 		}
 		rldata->pos[res] = '\0'; /* Safe. Null terminate so we can use string functions. */
-		firstdelim = strstr(rldata->pos, delim); /* Find the first occurence of the delimiter, if present. */
+
+		/* If the delimiter is longer than 1 character, and we previously
+		 * read part of the delimiter in a previous read, so firstdelim was NULL
+		 * at the top of this loop, but we just read the second half of the delimiter
+		 * in this read, then we can't just start searching from rldata->pos,
+		 * since that would be at the middle of the delimiter.
+		 * Instead, back up D - 1 characters, where D is the length of the delimiter,
+		 * to ensure we don't miss the start of it, as long as we don't go back
+		 * the beginning of rldata->buf itself. */
+		if (delimlen > 1) {
+			searchstart = rldata->pos - (delimlen - 1);
+			if (searchstart < rldata->buf) {
+				searchstart = rldata->buf;
+			}
+		} else {
+			searchstart = rldata->pos;
+		}
+
+		firstdelim = strstr(searchstart, delim); /* Find the first occurence of the delimiter, if present. */
 		/* Update our position */
 		rldata->pos += (size_t) res;
 		rldata->left -= (size_t) res;
+#ifdef EXTRA_DEBUG
+		bbs_debug(10, "Just read %ld bytes from file descriptor %d, %lu bytes remain\n", res, fd, rldata->left);
+#endif
 	}
 
 	return readline_post_read(rldata, delim, firstdelim, res);
@@ -162,7 +192,7 @@ static ssize_t __bbs_readline_getn(int fd, int destfd, struct dyn_str *restrict
 	 * The actual delimiter we provide to readline_pre_read doesn't matter here, it can be anything,
 	 * since we don't use the result.
 	 * We only check rldata->pos afterwards to determine how much data is already in the buffer. */
-	readline_pre_read(rldata, "\n", &res);
+	readline_pre_read(rldata, "\n", STRLEN("\n"), &res);
 	left_in_buffer = (size_t) (rldata->pos - rldata->buf);
 #ifdef EXTRA_DEBUG
 	bbs_debug(8, "Up to %lu/%lu bytes can be satisfied from existing buffer\n", left_in_buffer, n);
@@ -342,7 +372,7 @@ int bbs_readline_get_until(int fd, struct dyn_str *dynstr, struct readline_data
 	 * The actual delimiter we provide to readline_pre_read doesn't matter here, it can be anything,
 	 * since we don't use the result.
 	 * We only check rldata->pos afterwards to determine how much data is already in the buffer. */
-	readline_pre_read(rldata, "\n", &res);
+	readline_pre_read(rldata, "\n", STRLEN("\n"), &res);
 
 	left_in_buffer = (size_t) (rldata->pos - rldata->buf);
 	if (left_in_buffer && !readline_get_until_process(dynstr, rldata, left_in_buffer, maxlen)) {
@@ -373,7 +403,7 @@ int bbs_readline_append(struct readline_data *restrict rldata, const char *restr
 	ssize_t unused;
 	int drain = 0;
 
-	firstdelim = readline_pre_read(rldata, delim, &unused);
+	firstdelim = readline_pre_read(rldata, delim, strlen(delim), &unused);
 	if (firstdelim) {
 		*ready = 1;
 		drain = 1;

modules/mod_tests.c

@@ -307,6 +307,45 @@ static int test_readline_helper(void)
 	return res;
 }
 
+/*! \brief As long as a single line fits in the buffer, buffer exhaustion should not happen */
+static int test_readline_buffer_size(void)
+{
+	int mres, res = -1;
+	char buf[12];
+	int pfd[2];
+	struct readline_data rldata;
+
+	if (pipe(pfd)) {
+		bbs_error("pipe failed: %s\n", strerror(errno));
+		return -1;
+	}
+
+	bbs_readline_init(&rldata, buf, sizeof(buf));
+
+	SWRITE(pfd[1], "abc.\r\n"
+		"def.\r\n");
+	SWRITE(pfd[1], ".");
+
+#define EXPECT_LINE(l) \
+	mres = (int) bbs_readline(pfd[0], &rldata, "\r\n", 300); \
+	bbs_test_assert_equals((int) STRLEN(l), mres); \
+	bbs_test_assert_str_equals(buf, l);
+
+	EXPECT_LINE("abc.");
+	EXPECT_LINE("def.");
+	/* Don't actually try to read this line, since it wasn't terminated.
+	 * But the above should at least parse properly. */
+	/* EXPECT_LINE("."); */
+
+#undef EXPECT_LINE
+	res = 0;
+
+cleanup:
+	close(pfd[0]);
+	close(pfd[1]);
+	return res;
+}
+
 static int test_readline_append(void)
 {
 	int mres;
@@ -688,6 +727,7 @@ static struct bbs_unit_test tests[] =
 	{ "String Remove Substring", test_str_remove_substring },
 	{ "LF to CR LF Conversion", test_lf_crlf },
 	{ "Readline Helper", test_readline_helper },
+	{ "Readline Buffer Size", test_readline_buffer_size },
 	{ "Readline Append", test_readline_append },
 	{ "Readline getn", test_readline_getn },
 	{ "Readline Boundary", test_readline_boundary },

nets/net_ws.c

@@ -921,12 +921,15 @@ static void ws_handler(struct bbs_node *node, struct http_session *http, int rfd
 		pfds[1].fd = ws.pollfd;
 		pfds[0].revents = pfds[1].revents = 0;
 
+#define DEBUG_POLL
+
 		/* We need to ping the client at least every max_websocket_timeout_ms. */
 		this_poll_start = time(NULL);
 		elapsed_sec = this_poll_start - lastping;
 		max_ms = (int) (max_websocket_timeout_ms - SEC_MS(elapsed_sec));
 #ifdef DEBUG_POLL
-		bbs_debug(10, "ws.pollms: %d, %d s / %ld ms have elapsed since last ping, %d ms is max allowed\n", ws.pollms, elapsed_sec, app_ms_elapsed, max_ms);
+		bbs_debug(9, "app poll elapsed: %d/%d, ws timeout: %d, -> max actual poll: %d, %lu s since last ping\n",
+			app_ms_elapsed / 1000, ws.pollms / 1000, max_websocket_timeout_ms / 1000, max_ms / 1000, elapsed_sec);
 #endif
 		if (ws.pollms >= 0) {
 			pollms = ws.pollms - app_ms_elapsed;
@@ -964,8 +967,15 @@ static void ws_handler(struct bbs_node *node, struct http_session *http, int rfd
 		if (pfds[0].revents) {
 			res = wss_read(client, SEC_MS(55), 1); /* Pass in 1 since we already know poll returned activity for this fd */
 			if (res < 0) {
-				bbs_debug(3, "Failed to read WebSocket frame\n");
-				bbs_debug(7, "ws.pollms: %d, %ld s / %d ms have elapsed since last ping, %d ms is max allowed\n", ws.pollms, elapsed_sec, app_ms_elapsed, max_ms);
+				/* Since the poll was ended short, calculate how much time elapsed. */
+				time_t now = time(NULL);
+				time_t elapsed = now - this_poll_start;
+				app_ms_elapsed += (int) SEC_MS(elapsed);
+
+				/* Connection closed abruptly (uncleanly). Probably shouldn't happen under normal conditions. */
+				bbs_warning("Failed to read WebSocket frame, server closed connection?\n");
+				bbs_debug(9, "app poll elapsed: %d/%d, ws timeout: %d, -> max actual poll: %d, %lu s since last ping\n",
+					app_ms_elapsed / 1000, ws.pollms / 1000, max_websocket_timeout_ms / 1000, max_ms / 1000, elapsed_sec);
 				if (wss_error_code(client)) {
 					wss_close(client, wss_error_code(client));
 				} /* else, if client already closed, don't try writing any further */
@@ -1056,7 +1066,7 @@ static void ws_handler(struct bbs_node *node, struct http_session *http, int rfd
 				 * but I haven't convinced myself that's not just an excuse :)
 				 */
 #ifdef DEBUG_POLL
-				bbs_debug(9, "%d ms have now elapsed into poll (%d ms just now)\n", app_ms_elapsed, pollms);
+				bbs_debug(9, "%d s have now elapsed into poll (%d s just now)\n", app_ms_elapsed / 1000, pollms / 1000);
 #endif
 			}
 

tests/test_smtp_mta.c

@@ -175,6 +175,40 @@ static int run(void)
 	SWRITE(clientfd, "." ENDL); /* EOM */
 	CLIENT_EXPECT(clientfd, "554"); /* Mail loop detected */
 
+	/* Test messages that are exactly as long as the readline buffer. */
+	SWRITE(clientfd, "RSET" ENDL);
+	CLIENT_EXPECT(clientfd, "250");
+	SWRITE(clientfd, "EHLO " TEST_EXTERNAL_DOMAIN ENDL);
+	CLIENT_EXPECT_EVENTUALLY(clientfd, "250 ");
+	SWRITE(clientfd, "MAIL FROM:<" TEST_EMAIL_EXTERNAL ">\r\n");
+	CLIENT_EXPECT(clientfd, "250");
+	SWRITE(clientfd, "RCPT TO:<" TEST_EMAIL ">\r\n");
+	CLIENT_EXPECT(clientfd, "250");
+	SWRITE(clientfd, "DATA\r\n");
+	CLIENT_EXPECT(clientfd, "354");
+	SWRITE(clientfd, "Subject: Test\r\n"
+		"Content-Type: text/plain; charset=utf-8; format=flowed\r\n"
+		"Content-Transfer-Encoding: 8bit\r\n"
+		"Content-Language: en-US\r\n"
+		"\r\n"
+		"Hello,\r\n"
+		"\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"This is a test message. This is a test message. This is a test message.\r\n"
+		"Should be appx. 1,001 characters when we're done.\r\n"
+		"Bye.\r\n");
+	SWRITE(clientfd, "." ENDL); /* EOM */
+	CLIENT_EXPECT(clientfd, "250");
+
 #define CHAR_31 "abc def ghi jkl mno prs tuv wxy"
 #define CHAR_248 CHAR_31 CHAR_31 CHAR_31 CHAR_31 CHAR_31 CHAR_31 CHAR_31 CHAR_31
 #define CHAR_992 CHAR_248 CHAR_248 CHAR_248 CHAR_248
@@ -190,14 +224,18 @@ static int run(void)
 	CLIENT_EXPECT(clientfd, "250");
 	SWRITE(clientfd, "DATA\r\n");
 	CLIENT_EXPECT(clientfd, "354");
-	SWRITE(clientfd, "Date: Thu, 21 May 1998 05:33:29 -0700" ENDL);
+	SWRITE(clientfd, "Date: Thu, 21 May 1998 05:33:30 -0700" ENDL);
 	SWRITE(clientfd, ENDL);
 	SWRITE(clientfd, "Test" ENDL);
 	SWRITE(clientfd, CHAR_992 ENDL); /* This is okay */
 	SWRITE(clientfd, CHAR_992 CHAR_31 ENDL); /* This is not okay */
 	SWRITE(clientfd, "." ENDL); /* EOM */
 	CLIENT_EXPECT(clientfd, "550"); /* Mail loop detected */
 
+	/* The SMTP server disconnects when line length is exceeded,
+	 * since that's the only sane thing that can be done,
+	 * so we need to reconnect now. */
+
 	/* Test pregreeting */
 	close(clientfd);
 	clientfd = test_make_socket(25);