logging: Fix double lock of log_tgt_mutex

Recent commit introduced the "blocking-io" param to "log stderr" VTY
command, which calls log_target_file_switch_to_{stream,wqueue}.
The VTY command already locks the log_tgt_mutex mutex, since it has to
access the tgt list. However, the functions mention above also want to
lock the same mutex in order to log information. Let's drop the logging
to avoid the double lock, and update its documentation to mention it
must be called with the lock already held, as documented on other
similar functions.

The issue can be spotted when running osmo-trx-uhd:
"""
(gdb) bt
 #0  0x00007ffff75d7600 in __lll_lock_wait () from /usr/lib/libpthread.so.0
 #1  0x00007ffff75d0503 in pthread_mutex_lock () from /usr/lib/libpthread.so.0
 #2  0x00007ffff66314fb in log_tgt_mutex_lock_impl () at /git/libosmocore/src/logging.c:130
 #3  0x00007ffff6638e74 in log_check_level (subsys=8, subsys@entry=-1, level=level@entry=3) at /git/libosmocore/src/logging.c:1510
 #4  0x00007ffff6639c91 in log_target_file_switch_to_wqueue (target=target@entry=0x611000000320) at /git/libosmocore/src/logging.c:1186
 #5  0x00007ffff68565d3 in cfg_log_stderr (self=<optimized out>, vty=0x6140000018a0, argc=0, argv=<optimized out>) at /git/libosmocore/src/vty/logging_vty.c:859
 #6  0x00007ffff683db3d in cmd_execute_command_strict (vline=0x60b0000dfe80, vty=vty@entry=0x6140000018a0, cmd=cmd@entry=0x0) at /git/libosmocore/src/vty/command.c:2768
 7  0x00007ffff683e396 in config_from_file (vty=vty@entry=0x6140000018a0, fp=fp@entry=0x615000036400) at /git/libosmocore/src/vty/command.c:2880
 8  0x00007ffff684cedb in vty_read_config_filep (confp=confp@entry=0x615000036400, priv=priv@entry=0x0) at /git/libosmocore/src/vty/vty.c:1529
 9  0x00007ffff684ebfc in vty_read_config_file (file_name=0x7fffffffe7d8 "/build/new/conf/osmo-trx-uhd.cfg", priv=0x0) at /git/libosmocore/src/vty/vty.c:1920
 10 0x0000555555565270 in main (argc=3, argv=0x7fffffffe3c8) at /git/osmo-trx/Transceiver52M/osmo-trx.cpp:652
"""

Debugged by rebuilding libosmocore with "LOG_MTX_DEBUG 1":
"""
/libosmocore/src/logging.c:1510 [log_check_level] lock
/libosmocore/src/logging.c:1522 [log_check_level] unlock
/libosmocore/src/vty/logging_vty.c:844 [cfg_log_stderr] lock
/libosmocore/src/logging.c:1510 [log_check_level] lock
"""
Fixes: b72867f0e68c96ca25e1f9929ce92be0a802db6b
Related: OS#4311
Change-Id: Idb4215fa2f364e28c0bb73fb9975b6c9f50a46f6

1 files changed, 6 insertions, 36 deletions

diff --git a/src/logging.c b/src/logging.c
index 00d75c3b..9e2f5c26 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -1090,34 +1090,21 @@ struct log_target *log_target_create_file_stream(const char *fname)
 
 /*! switch from non-blocking/write-queue to blocking + buffered stream output
  *  \param[in] target log target which we should switch
- *  \return 0 on success; 1 if already switched before; negative on error */
+ *  \return 0 on success; 1 if already switched before; negative on error
+ *  Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.
+ */
 int log_target_file_switch_to_stream(struct log_target *target)
 {
 	struct osmo_wqueue *wq;
-	const char *name;
 
 	if (!target)
 		return -ENODEV;
 
-	/* this only works for file/stderr targets */
-	switch (target->type) {
-	case LOG_TGT_TYPE_FILE:
-		name = target->tgt_file.fname;
-		break;
-	case LOG_TGT_TYPE_STDERR:
-		name = "stderr";
-		break;
-	default:
-		return -EINVAL;
-	}
-
 	if (target->tgt_file.out) {
 		/* target has already been switched over */
 		return 1;
 	}
 
-	LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to blocking stream I/O\n", name);
-
 	wq = target->tgt_file.wqueue;
 	OSMO_ASSERT(wq);
 
@@ -1127,8 +1114,6 @@ int log_target_file_switch_to_stream(struct log_target *target)
 	else
 		target->tgt_file.out = fopen(target->tgt_file.fname, "a");
 	if (!target->tgt_file.out) {
-		LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as blocking stream I/O: %s\n",
-		     name, strerror(errno));
 		return -EIO;
 	}
 
@@ -1156,35 +1141,22 @@ int log_target_file_switch_to_stream(struct log_target *target)
 
 /*! switch from blocking + buffered file output to non-blocking write-queue based output.
  *  \param[in] target log target which we should switch
- *  \return 0 on success; 1 if already switched before; negative on error */
+ *  \return 0 on success; 1 if already switched before; negative on error
+ *  Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.
+ */
 int log_target_file_switch_to_wqueue(struct log_target *target)
 {
 	struct osmo_wqueue *wq;
-	const char *name;
 	int rc;
 
 	if (!target)
 		return -ENODEV;
 
-	/* this only works for file/stderr targets */
-	switch (target->type) {
-	case LOG_TGT_TYPE_FILE:
-		name = target->tgt_file.fname;
-		break;
-	case LOG_TGT_TYPE_STDERR:
-		name = "stderr";
-		break;
-	default:
-		return -EINVAL;
-	}
-
 	if (!target->tgt_file.out) {
 		/* target has already been switched over */
 		return 1;
 	}
 
-	LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to non-blocking I/O\n", name);
-
 	/* we create a ~640kB sized talloc pool within the write-queue to ensure individual
 	 * log lines (stored as msgbs) will not put result in malloc() calls, and also to
 	 * reduce the OOM probability within logging, as the pool is already allocated */
@@ -1198,8 +1170,6 @@ int log_target_file_switch_to_wqueue(struct log_target *target)
 	if (target->type == LOG_TGT_TYPE_FILE) {
 		rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
 		if (rc < 0) {
-			LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as non-blocking I/O: %s\n",
-			     name, strerror(errno));
 			talloc_free(wq);
 			return -errno;
 		}