bbs, mods, nets: Logging improvements, miscellaneous bug fixes.

Bug Fixes:
* socket.c: Prevent null dereference for interfaces without IP addresses.
* mod_asterisk_ami: Fix faulty reconnect logic.
* mod_asterisk_ami: Ensure log file is created with correct permissions.
* mod_asterisk_queues: Completely purge agent membership on disconnect.

Improvements:
* Convert many warnings and errors to debugs, where appropriate.
* thread.c: Avoid spurious "thread not waiting to be joined" messages.
* module.c: Avoid spurious warnings due to dependencies.
* utils.c: Log error message from eaccess if it fails.
* mod_ncurses: Improve menu display.
* nets: Remove redundant log messages.
* socket.c, net_smtp: Increase debug level of spammy messages (those
  that occur lots of times, simply due to a large amount of data being processed).

bbs/config.c

@@ -323,7 +323,7 @@ static struct bbs_config *config_parse(const char *name)
 	}
 	if (access(fullname, R_OK)) {
 		/* Config files are optional, not mandatory, so this is a warning only, not an error. */
-		bbs_warning("Config file %s does not exist\n", fullname);
+		bbs_notice("Config file %s does not exist\n", fullname);
 		return NULL;
 	}
 	fp = fopen(fullname, "r");

bbs/module.c

@@ -348,11 +348,15 @@ static struct bbs_module *load_dlopen(const char *resource_in, const char *so_ex
 	if (resource_being_loaded) {
 		const char *dlerror_msg = S_IF(dlerror());
 
-		bbs_warning("Module %s didn't register itself during load?\n", resource_in);
+		if (!suppress_logging) {
+			bbs_warning("Module %s didn't register itself during load?\n", resource_in);
+		}
 
 		resource_being_loaded = NULL;
 		if (mod->lib) {
-			bbs_error("Module '%s' did not register itself during load\n", resource_in);
+			if (!suppress_logging) {
+				bbs_error("Module '%s' did not register itself during load\n", resource_in);
+			}
 			logged_dlclose(resource_in, mod->lib);
 		} else if (!suppress_logging) {
 			bbs_error("Error loading module '%s': %s\n", resource_in, dlerror_msg);
@@ -374,14 +378,20 @@ static struct bbs_module *load_dynamic_module(const char *resource_in, unsigned
 	size_t resource_in_len = strlen(resource_in);
 	const char *so_ext = "";
 	struct bbs_module *mod;
+	int retry;
 
 	if (resource_in_len < 4 || strcasecmp(resource_in + resource_in_len - 3, ".so")) {
 		so_ext = ".so";
 	}
 
 	snprintf(fn, sizeof(fn), "%s/%s%s", BBS_MODULE_DIR, resource_in, so_ext);
 
-	mod = load_dlopen(resource_in, so_ext, fn, RTLD_NOW | RTLD_LOCAL, suppress_logging);
+	/* If we're going to try loading dependencies and then call load_dlopen again,
+	 * any warnings can be ignored the first time, since they were probably due
+	 * to missing symbols (and if not, we'll try again anyways, and log that time). */
+	retry = stringlist_contains(&modules_preload, resource_in);
+
+	mod = load_dlopen(resource_in, so_ext, fn, RTLD_NOW | RTLD_LOCAL, suppress_logging || retry);
 	if (!mod) {
 		/* XXX. Here, we consider the case of modules that are both depended on by other modules
 		 * and themselves depend on yet other modules.
@@ -404,7 +414,7 @@ static struct bbs_module *load_dynamic_module(const char *resource_in, unsigned
 		 * Also, this is no longer safe from accidental infinte recursion. We will crash (stack overflow) if there is a dependency loop here.
 		 * If we have a better way of handling this in the future, this hack can be removed:
 		 */
-		if (stringlist_contains(&modules_preload, resource_in)) {
+		if (retry) {
 			/* Only bother checking if it's a preload module.
 			 * Otherwise, checking dependencies now isn't going to do anything for us.
 			 * Also only do this during autoload (the preload list will be emptied once autoload finishes).
@@ -881,7 +891,8 @@ static int on_file_preload(const char *dir_name, const char *filename, void *obj
 	UNUSED(obj);
 
 	if (mod) {
-		bbs_error("Module %s is already loaded\n", filename);
+		/* Could happen due to the auto-preloading that can happen if trying to resolve dependencies. */
+		bbs_debug(1, "Module %s is already loaded\n", filename);
 		return 0; /* Always return 0 or otherwise we'd abort the entire autoloading process */
 	}
 

bbs/socket.c

@@ -1012,7 +1012,12 @@ int bbs_get_local_ip(char *buf, size_t len)
 	}
 
 	for (iface = iflist; res && iface; iface = iface->ifa_next) {
-		int af = iface->ifa_addr->sa_family;
+		int af;
+		if (!iface->ifa_addr) {
+			/* This can be NULL for interfaces without an IP address assigned. */
+			continue;
+		}
+		af = iface->ifa_addr->sa_family;
 		switch (af) {
 			case AF_INET:
 				sinaddr = ((struct sockaddr_in *) iface->ifa_addr);
@@ -2253,7 +2258,9 @@ ssize_t bbs_sendfile(int out_fd, int in_fd, off_t *offset, size_t count)
 		if (res == (ssize_t) count) {
 			break;
 		}
-		bbs_debug(2, "Wanted to write %lu bytes but was only able to write %ld this round\n", count, res); /* Keep trying */
+		/* It's typical for sendfile to only send 8,192 bytes at a time,
+		 * so for sending much more than that, this can be a very spammy message. */
+		bbs_debug(10, "Wanted to write %lu bytes but was only able to write %ld this round\n", count, res); /* Keep trying */
 		count -= (size_t) res;
 	}
 

bbs/thread.c

@@ -305,6 +305,7 @@ int __bbs_pthread_join(pthread_t thread, void **retval, const char *file, const
 	if (!waiting_join) {
 #ifdef __linux__
 		struct timespec ts;
+		int waits = 0;
 		/* This is suspicious... we may end up hanging if the thread doesn't exit imminently */
 		/* Don't immediately emit a warning, because the thread may be just about to exit
 		 * and thus wasn't waitingjoin when we checked. This prevents superflous warnings,
@@ -314,8 +315,19 @@ int __bbs_pthread_join(pthread_t thread, void **retval, const char *file, const
 		}
 		ts.tv_sec = 1; /* Wait up to a second */
 		res = pthread_timedjoin_np(thread, retval ? retval : &tmp, &ts); /* This is not POSIX portable */
-		if (res && res == ETIMEDOUT) {
-			/* The thread hasn't exited yet. At this point, it's more likely that something is actually wrong. */
+		while (res == ETIMEDOUT && ++waits < 200) {
+			/* It seems pthread_timedjoin_np doesn't always wait and sometimes returns immediately,
+			 * in which case it's possible that no time has actually passed.
+			 * If this is the case, then manually sleep and check again first. */
+			/* Wait a few hundred ms. Okay to make a blocking call since pthread_join is expected to possibly block anyways.
+			 * Still split up into multiple waits to avoid sleeping longer than is really needed... */
+			bbs_safe_sleep(25);
+			res = pthread_timedjoin_np(thread, retval ? retval : &tmp, &ts);
+		}
+		if (res == ETIMEDOUT) {
+			/* The thread hasn't exited yet. At this point, it's more likely that something is actually wrong.
+			 * This isn't always the case, for threads that might take a long time to clean up and exit,
+			 * but most of the time, it shouldn't take more than a second. */
 			bbs_warning("Thread %d is not currently waiting to be joined\n", lwp);
 			/* Now, proceed as normal and do a ~blocking pthread_join */
 			/* Seems that after using pthread_timedjoin_np, you can't do a blocking pthread_join anymore? So loop */

bbs/tls.c

@@ -312,6 +312,11 @@ static int cli_tls(struct bbs_cli_args *a)
 	return 0;
 }
 
+/* Note:
+ * Many frequent TLS-level warnings or errors have been made debug messages here,
+ * because they happen frequently due to client issues.
+ * Most of the time, we're not really concerned with these since there's nothing we can do about that. */
+
 /*! \brief Single thread to handle I/O for all TLS connections (which are mainly buffered in chunks anyways) */
 static void *ssl_io_thread(void *unused)
 {
@@ -483,14 +488,14 @@ static void *ssl_io_thread(void *unused)
 					switch (err) {
 						case SSL_ERROR_NONE:
 						case SSL_ERROR_WANT_READ:
-							bbs_debug(7, "SSL_read for %p returned %d (%s)\n", ssl, ores, ssl_strerror(err));
+							bbs_debug(10, "SSL_read for %p returned %d (%s)\n", ssl, ores, ssl_strerror(err));
 							continue; /* Move on to other connections, come back to this one later */
 						case SSL_ERROR_SYSCALL:
 						case SSL_ERROR_ZERO_RETURN:
 						case SSL_ERROR_SSL:
 							if (err == SSL_ERROR_SSL) {
 								ERR_error_string_n(ERR_get_error(), err_msg, sizeof(err_msg));
-								bbs_error("TLS error: %s\n", err_msg);
+								bbs_debug(1, "TLS error: %s\n", err_msg);
 							}
 							/* This socket is done for, do not retry to read more data,
 							 * e.g. client has closed the connection but server has yet to close its end, and we're in the middle */
@@ -582,15 +587,13 @@ static void *ssl_io_thread(void *unused)
 									MARK_DEAD(ssl);
 									needcreate = 1;
 									break;
-								case SSL_ERROR_NONE:
 								case SSL_ERROR_SYSCALL:
 								case SSL_ERROR_ZERO_RETURN:
 								case SSL_ERROR_SSL:
-									bbs_warning("Wanted to write %d bytes to %p but wrote %ld?\n", ores, ssl, wres);
-									if (err == SSL_ERROR_SSL) {
-										ERR_error_string_n(ERR_get_error(), err_msg, sizeof(err_msg));
-										bbs_error("TLS error: %s\n", err_msg);
-									}
+									ERR_error_string_n(ERR_get_error(), err_msg, sizeof(err_msg));
+									bbs_warning("TLS error: wanted to write %d bytes to %p but wrote %ld? (%s)\n", ores, ssl, wres, err_msg);
+									/* Fall through */
+								case SSL_ERROR_NONE:
 									/* This socket is done for, do not retry to read more data,
 									 * e.g. client has closed the connection but server has yet to close its end, and we're in the middle */
 									MARK_DEAD(ssl);
@@ -712,7 +715,7 @@ SSL *ssl_new_accept(struct bbs_node *node, int fd, int *rfd, int *wfd)
 			goto accept; /* This just works out to be cleaner than using any kind of loop here */
 		}
 		pthread_rwlock_unlock(&ssl_cert_lock);
-		bbs_error("SSL error %d: %d (%s = %s)\n", res, sslerr, ssl_strerror(sslerr), ERR_error_string(ERR_get_error(), NULL));
+		bbs_debug(1, "SSL error %d: %d (%s = %s)\n", res, sslerr, ssl_strerror(sslerr), ERR_error_string(ERR_get_error(), NULL));
 		SSL_free(ssl);
 		/* If TLS setup fails, it's probably garbage traffic and safe to penalize: */
 		if (node) {
@@ -877,7 +880,7 @@ int ssl_close(SSL *ssl)
 	sres = SSL_shutdown(ssl);
 	if (sres < 0) {
 		int err = SSL_get_error(ssl, sres);
-		bbs_warning("SSL shutdown failed: %s\n", ssl_strerror(err));
+		bbs_debug(1, "SSL shutdown failed: %s\n", ssl_strerror(err));
 	} else if (!sres) {
 		/* We sent a close notify, but haven't received one from the peer.
 		 * To be properly conformant, a client should send us a close notify,

bbs/utils.c

@@ -771,9 +771,12 @@ int bbs_file_exists(const char *path)
 
 int bbs_ensure_directory_exists(const char *path)
 {
-	if (eaccess(path, R_OK)) {
+	if (eaccess(path, R_OK | X_OK)) {
+		int derr = errno;
 		if (mkdir(path, 0700)) {
-			bbs_error("mkdir(%s) failed: %s\n", path, strerror(errno));
+			/* The directory probably already exists, but we can't access it for some reason. */
+			bbs_warning("mkdir(%s) failed: %s\n", path, strerror(errno));
+			bbs_error("Can't access directory %s: %s\n", path, strerror(derr));
 			return -1;
 		}
 	}
@@ -782,15 +785,18 @@ int bbs_ensure_directory_exists(const char *path)
 
 int bbs_ensure_directory_exists_recursive(const char *path)
 {
-	if (eaccess(path, R_OK)) {
+	if (eaccess(path, R_OK | X_OK)) {
+		int derr = errno;
 		/* Recursively create parents as needed */
 		if (bbs_str_count(path, '/') > 2) {
 			char parent[PATH_MAX];
 			safe_strncpy(parent, path, sizeof(parent));
 			bbs_ensure_directory_exists_recursive(dirname(parent));
 		}
 		if (mkdir(path, 0700)) {
-			bbs_error("mkdir(%s) failed: %s\n", path, strerror(errno));
+			/* The directory probably already exists, but we can't access it for some reason. */
+			bbs_warning("mkdir(%s) failed: %s\n", path, strerror(errno));
+			bbs_error("Can't access directory %s: %s\n", path, strerror(derr));
 			return -1;
 		}
 	}