<p>laforge <strong>submitted</strong> this change.</p><p><a href="https://gerrit.osmocom.org/c/libosmocore/+/26089">View Change</a></p><div style="white-space:pre-wrap">Approvals:
laforge: Looks good to me, approved
Jenkins Builder: Verified
</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">logging: Fix double lock of log_tgt_mutex<br><br>Recent commit introduced the "blocking-io" param to "log stderr" VTY<br>command, which calls log_target_file_switch_to_{stream,wqueue}.<br>The VTY command already locks the log_tgt_mutex mutex, since it has to<br>access the tgt list. However, the functions mention above also want to<br>lock the same mutex in order to log information. Let's drop the logging<br>to avoid the double lock, and update its documentation to mention it<br>must be called with the lock already held, as documented on other<br>similar functions.<br><br>The issue can be spotted when running osmo-trx-uhd:<br>"""<br>(gdb) bt<br> #0 0x00007ffff75d7600 in __lll_lock_wait () from /usr/lib/libpthread.so.0<br> #1 0x00007ffff75d0503 in pthread_mutex_lock () from /usr/lib/libpthread.so.0<br> #2 0x00007ffff66314fb in log_tgt_mutex_lock_impl () at /git/libosmocore/src/logging.c:130<br> #3 0x00007ffff6638e74 in log_check_level (subsys=8, subsys@entry=-1, level=level@entry=3) at /git/libosmocore/src/logging.c:1510<br> #4 0x00007ffff6639c91 in log_target_file_switch_to_wqueue (target=target@entry=0x611000000320) at /git/libosmocore/src/logging.c:1186<br> #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<br> #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<br> 7 0x00007ffff683e396 in config_from_file (vty=vty@entry=0x6140000018a0, fp=fp@entry=0x615000036400) at /git/libosmocore/src/vty/command.c:2880<br> 8 0x00007ffff684cedb in vty_read_config_filep (confp=confp@entry=0x615000036400, priv=priv@entry=0x0) at /git/libosmocore/src/vty/vty.c:1529<br> 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<br> 10 0x0000555555565270 in main (argc=3, argv=0x7fffffffe3c8) at /git/osmo-trx/Transceiver52M/osmo-trx.cpp:652<br>"""<br><br>Debugged by rebuilding libosmocore with "LOG_MTX_DEBUG 1":<br>"""<br>/libosmocore/src/logging.c:1510 [log_check_level] lock<br>/libosmocore/src/logging.c:1522 [log_check_level] unlock<br>/libosmocore/src/vty/logging_vty.c:844 [cfg_log_stderr] lock<br>/libosmocore/src/logging.c:1510 [log_check_level] lock<br>"""<br>Fixes: b72867f0e68c96ca25e1f9929ce92be0a802db6b<br>Related: OS#4311<br>Change-Id: Idb4215fa2f364e28c0bb73fb9975b6c9f50a46f6<br>---<br>M src/logging.c<br>1 file changed, 6 insertions(+), 36 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/src/logging.c b/src/logging.c</span><br><span>index 00d75c3..9e2f5c2 100644</span><br><span>--- a/src/logging.c</span><br><span>+++ b/src/logging.c</span><br><span>@@ -1090,34 +1090,21 @@</span><br><span> </span><br><span> /*! switch from non-blocking/write-queue to blocking + buffered stream output</span><br><span> * \param[in] target log target which we should switch</span><br><span style="color: hsl(0, 100%, 40%);">- * \return 0 on success; 1 if already switched before; negative on error */</span><br><span style="color: hsl(120, 100%, 40%);">+ * \return 0 on success; 1 if already switched before; negative on error</span><br><span style="color: hsl(120, 100%, 40%);">+ * Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.</span><br><span style="color: hsl(120, 100%, 40%);">+ */</span><br><span> int log_target_file_switch_to_stream(struct log_target *target)</span><br><span> {</span><br><span> struct osmo_wqueue *wq;</span><br><span style="color: hsl(0, 100%, 40%);">- const char *name;</span><br><span> </span><br><span> if (!target)</span><br><span> return -ENODEV;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- /* this only works for file/stderr targets */</span><br><span style="color: hsl(0, 100%, 40%);">- switch (target->type) {</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(0, 100%, 40%);">- name = target->tgt_file.fname;</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(0, 100%, 40%);">- name = "stderr";</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- default:</span><br><span style="color: hsl(0, 100%, 40%);">- return -EINVAL;</span><br><span style="color: hsl(0, 100%, 40%);">- }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> if (target->tgt_file.out) {</span><br><span> /* target has already been switched over */</span><br><span> return 1;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to blocking stream I/O\n", name);</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> wq = target->tgt_file.wqueue;</span><br><span> OSMO_ASSERT(wq);</span><br><span> </span><br><span>@@ -1127,8 +1114,6 @@</span><br><span> else</span><br><span> target->tgt_file.out = fopen(target->tgt_file.fname, "a");</span><br><span> if (!target->tgt_file.out) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as blocking stream I/O: %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- name, strerror(errno));</span><br><span> return -EIO;</span><br><span> }</span><br><span> </span><br><span>@@ -1156,35 +1141,22 @@</span><br><span> </span><br><span> /*! switch from blocking + buffered file output to non-blocking write-queue based output.</span><br><span> * \param[in] target log target which we should switch</span><br><span style="color: hsl(0, 100%, 40%);">- * \return 0 on success; 1 if already switched before; negative on error */</span><br><span style="color: hsl(120, 100%, 40%);">+ * \return 0 on success; 1 if already switched before; negative on error</span><br><span style="color: hsl(120, 100%, 40%);">+ * Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.</span><br><span style="color: hsl(120, 100%, 40%);">+ */</span><br><span> int log_target_file_switch_to_wqueue(struct log_target *target)</span><br><span> {</span><br><span> struct osmo_wqueue *wq;</span><br><span style="color: hsl(0, 100%, 40%);">- const char *name;</span><br><span> int rc;</span><br><span> </span><br><span> if (!target)</span><br><span> return -ENODEV;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- /* this only works for file/stderr targets */</span><br><span style="color: hsl(0, 100%, 40%);">- switch (target->type) {</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_TGT_TYPE_FILE:</span><br><span style="color: hsl(0, 100%, 40%);">- name = target->tgt_file.fname;</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_TGT_TYPE_STDERR:</span><br><span style="color: hsl(0, 100%, 40%);">- name = "stderr";</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- default:</span><br><span style="color: hsl(0, 100%, 40%);">- return -EINVAL;</span><br><span style="color: hsl(0, 100%, 40%);">- }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> if (!target->tgt_file.out) {</span><br><span> /* target has already been switched over */</span><br><span> return 1;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DLGLOBAL, LOGL_INFO, "Switching log target '%s' to non-blocking I/O\n", name);</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> /* we create a ~640kB sized talloc pool within the write-queue to ensure individual</span><br><span> * log lines (stored as msgbs) will not put result in malloc() calls, and also to</span><br><span> * reduce the OOM probability within logging, as the pool is already allocated */</span><br><span>@@ -1198,8 +1170,6 @@</span><br><span> if (target->type == LOG_TGT_TYPE_FILE) {</span><br><span> rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);</span><br><span> if (rc < 0) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DLGLOBAL, LOGL_ERROR, "Cannot open log target '%s' as non-blocking I/O: %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- name, strerror(errno));</span><br><span> talloc_free(wq);</span><br><span> return -errno;</span><br><span> }</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/c/libosmocore/+/26089">change 26089</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/c/libosmocore/+/26089"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: libosmocore </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: Idb4215fa2f364e28c0bb73fb9975b6c9f50a46f6 </div>
<div style="display:none"> Gerrit-Change-Number: 26089 </div>
<div style="display:none"> Gerrit-PatchSet: 2 </div>
<div style="display:none"> Gerrit-Owner: pespin <pespin@sysmocom.de> </div>
<div style="display:none"> Gerrit-Reviewer: Jenkins Builder </div>
<div style="display:none"> Gerrit-Reviewer: laforge <laforge@osmocom.org> </div>
<div style="display:none"> Gerrit-MessageType: merged </div>