osmocom
/
libosmocore
mirror of https://gerrit.osmocom.org/libosmocore
11
0
Fork 0
Code Issues Releases Wiki Activity

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: b72867f0e6
Related: OS#4311
Change-Id: Idb4215fa2f364e28c0bb73fb9975b6c9f50a46f6
This commit is contained in:
Pau Espin 2021-11-03 17:31:47 +01:00
parent 36c69ed256
commit 843a84c425
1 changed files with 6 additions and 36 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

42
src/logging.c
View File

@ -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;
}