<p>Neels Hofmeyr <strong>merged</strong> this change.</p><p><a href="https://gerrit.osmocom.org/10631">View Change</a></p><div style="white-space:pre-wrap">Approvals:
Jenkins Builder: Verified
Harald Welte: Looks good to me, approved
</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">log: add 'last' option to 'logging print file'<br><br>Allow printing the source file information *after* the log information.<br><br>Add target->print_filename_pos, log_set_print_filename_pos() and enum<br>log_filename_pos, and the optional 'last' keyword to the 'logging print file'<br>vty command. (An enum in case we want to add other positions later.)<br><br>Rationale: on log lines, the logging context is usually printed first in the<br>logging text. Without the source file information, this logging context pretty<br>much aligns in an easily readable way. When adding the source file information,<br>each line's logging context info is shifted right by a pretty much random<br>amount and it is hard to spot recurring logging contexts.<br><br>One solution is to switch off source file info, of course, but that's not an<br>option when actively hacking on bugs and new features.<br><br>For example, it is unnecessarily hard to spot lchan FSM related log lines in<br>this osmo-bsc log snippet:<br><br>DRSL NOTICE mgw_endpoint_fsm.c:603 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance<br>DRSL NOTICE fsm.c:381 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated<br>DMSC NOTICE mgw_endpoint_fsm.c:603 SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT<br>DCHAN DEBUG lchan_rtp_fsm.c:741 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED<br>DCHAN DEBUG lchan_rtp_fsm.c:520 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance<br>DCHAN DEBUG fsm.c:381 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated<br>DCHAN DEBUG lchan_rtp_fsm.c:520 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED<br>DCHAN DEBUG lchan_fsm.c:1232 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK<br>DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR)<br>DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance<br>DRSL NOTICE fsm.c:381 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated<br>DCHAN DEBUG lchan_fsm.c:1196 lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN<br>DCHAN DEBUG lchan_fsm.c:354 lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state<br>DLMGCP DEBUG mgcp_client.c:741 Tx MGCP msg to MGCP GW: 'DLCX 3 2@mgw MGCP 1.0'<br>DLMGCP DEBUG mgcp_client.c:743 Sending msg to MGCP GW size: 66<br>DRLL NOTICE mgcp_client_fsm.c:422 MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP<br><br>Placing the source file info behind the log text makes it much easier to<br>follow, while the source file info is still available:<br><br>DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance (mgw_endpoint_fsm.c:603)<br>DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated (fsm.c:381)<br>DMSC NOTICE SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT (mgw_endpoint_fsm.c:603)<br>DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:741)<br>DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance (lchan_rtp_fsm.c:520)<br>DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated (fsm.c:381)<br>DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:520)<br>DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK (lchan_fsm.c:1232)<br>DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (handover_fsm.c:745)<br>DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance (handover_fsm.c:745)<br>DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated (fsm.c:381)<br>DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN (lchan_fsm.c:1196)<br>DCHAN DEBUG lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state (lchan_fsm.c:354)<br>DLMGCP DEBUG Tx MGCP msg to MGCP GW: 'DLCX 3 12@mgw MGCP 1.0' (mgcp_client.c:741)<br>DLMGCP DEBUG Sending msg to MGCP GW size: 67 (mgcp_client.c:743)<br>DRLL NOTICE MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP (mgcp_client_fsm.c:422)<br><br>Implementation: for 'last', insert source file info only when an '\n' is found<br>at the end of the log line composition buffer, so that LOGP()...LOGPC()<br>constructs also print source file info only when a log line actually ends.<br><br>Change-Id: I393907b3c9e0cc1145e102328adad0a83ee13a9f<br>---<br>M include/osmocom/core/logging.h<br>M src/logging.c<br>M src/vty/logging_vty.c<br>3 files changed, 71 insertions(+), 17 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h</span><br><span>index 3cae63d..8464043 100644</span><br><span>--- a/include/osmocom/core/logging.h</span><br><span>+++ b/include/osmocom/core/logging.h</span><br><span>@@ -228,6 +228,12 @@</span><br><span> LOG_FILENAME_BASENAME,</span><br><span> };</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+/*! Where on a log line source file and line should be logged. */</span><br><span style="color: hsl(120, 100%, 40%);">+enum log_filename_pos {</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_FILENAME_POS_HEADER_END,</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_FILENAME_POS_LINE_END,</span><br><span style="color: hsl(120, 100%, 40%);">+};</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> /*! structure representing a logging target */</span><br><span> struct log_target {</span><br><span> struct llist_head entry; /*!< linked list */</span><br><span>@@ -313,6 +319,8 @@</span><br><span> bool print_category_hex;</span><br><span> /* Should we print the source file and line, and in which way? */</span><br><span> enum log_filename_type print_filename2;</span><br><span style="color: hsl(120, 100%, 40%);">+ /* Where on a log line to put the source file info. */</span><br><span style="color: hsl(120, 100%, 40%);">+ enum log_filename_pos print_filename_pos;</span><br><span> };</span><br><span> </span><br><span> /* use the above macros */</span><br><span>@@ -335,6 +343,7 @@</span><br><span> void log_set_print_timestamp(struct log_target *target, int);</span><br><span> void log_set_print_filename(struct log_target *target, int);</span><br><span> void log_set_print_filename2(struct log_target *target, enum log_filename_type lft);</span><br><span style="color: hsl(120, 100%, 40%);">+void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos);</span><br><span> void log_set_print_category(struct log_target *target, int);</span><br><span> void log_set_print_category_hex(struct log_target *target, int);</span><br><span> void log_set_print_level(struct log_target *target, int);</span><br><span>diff --git a/src/logging.c b/src/logging.c</span><br><span>index edb2b56..de0f2b0 100644</span><br><span>--- a/src/logging.c</span><br><span>+++ b/src/logging.c</span><br><span>@@ -406,21 +406,24 @@</span><br><span> goto err;</span><br><span> OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span> }</span><br><span style="color: hsl(0, 100%, 40%);">- switch (target->print_filename2) {</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_FILENAME_NONE:</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_FILENAME_PATH:</span><br><span style="color: hsl(0, 100%, 40%);">- ret = snprintf(buf + offset, rem, "%s:%d ", file, line);</span><br><span style="color: hsl(0, 100%, 40%);">- if (ret < 0)</span><br><span style="color: hsl(0, 100%, 40%);">- goto err;</span><br><span style="color: hsl(0, 100%, 40%);">- OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(0, 100%, 40%);">- case LOG_FILENAME_BASENAME:</span><br><span style="color: hsl(0, 100%, 40%);">- ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line);</span><br><span style="color: hsl(0, 100%, 40%);">- if (ret < 0)</span><br><span style="color: hsl(0, 100%, 40%);">- goto err;</span><br><span style="color: hsl(0, 100%, 40%);">- OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(0, 100%, 40%);">- break;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->print_filename_pos == LOG_FILENAME_POS_HEADER_END) {</span><br><span style="color: hsl(120, 100%, 40%);">+ switch (target->print_filename2) {</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_NONE:</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_PATH:</span><br><span style="color: hsl(120, 100%, 40%);">+ ret = snprintf(buf + offset, rem, "%s:%d ", file, line);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (ret < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ goto err;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_BASENAME:</span><br><span style="color: hsl(120, 100%, 40%);">+ ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (ret < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ goto err;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span> }</span><br><span> }</span><br><span> ret = vsnprintf(buf + offset, rem, format, ap);</span><br><span>@@ -428,6 +431,31 @@</span><br><span> goto err;</span><br><span> OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ /* For LOG_FILENAME_POS_LAST, print the source file info only when the caller ended the log</span><br><span style="color: hsl(120, 100%, 40%);">+ * message in '\n'. If so, nip the last '\n' away, insert the source file info and re-append an</span><br><span style="color: hsl(120, 100%, 40%);">+ * '\n'. All this to allow LOGP("start..."); LOGPC("...end\n") constructs. */</span><br><span style="color: hsl(120, 100%, 40%);">+ if (target->print_filename_pos == LOG_FILENAME_POS_LINE_END</span><br><span style="color: hsl(120, 100%, 40%);">+ && offset > 0 && buf[offset-1] == '\n') {</span><br><span style="color: hsl(120, 100%, 40%);">+ switch (target->print_filename2) {</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_NONE:</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_PATH:</span><br><span style="color: hsl(120, 100%, 40%);">+ offset --;</span><br><span style="color: hsl(120, 100%, 40%);">+ ret = snprintf(buf + offset, rem, " (%s:%d)\n", file, line);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (ret < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ goto err;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ case LOG_FILENAME_BASENAME:</span><br><span style="color: hsl(120, 100%, 40%);">+ offset --;</span><br><span style="color: hsl(120, 100%, 40%);">+ ret = snprintf(buf + offset, rem, " (%s:%d)\n", const_basename(file), line);</span><br><span style="color: hsl(120, 100%, 40%);">+ if (ret < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+ goto err;</span><br><span style="color: hsl(120, 100%, 40%);">+ OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ break;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> if (target->use_color) {</span><br><span> ret = snprintf(buf + offset, rem, "\033[0;m");</span><br><span> if (ret < 0)</span><br><span>@@ -677,6 +705,17 @@</span><br><span> target->print_filename2 = lft;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+/*! Set the position where on a log line the source file info should be logged.</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] target Log target to be affected.</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] pos A LOG_FILENAME_POS_* enum value.</span><br><span style="color: hsl(120, 100%, 40%);">+ * LOG_FILENAME_POS_DEFAULT logs just before the caller supplied log message.</span><br><span style="color: hsl(120, 100%, 40%);">+ * LOG_FILENAME_POS_LAST logs only at the end of a log line, where the caller issued an '\n' to end the</span><br><span style="color: hsl(120, 100%, 40%);">+ */</span><br><span style="color: hsl(120, 100%, 40%);">+void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ target->print_filename_pos = pos;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> /*! Enable or disable printing of the category name</span><br><span> * \param[in] target Log target to be affected</span><br><span> * \param[in] print_catname Enable (1) or disable (0) filenames</span><br><span>diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c</span><br><span>index 1194914..8c8a332 100644</span><br><span>--- a/src/vty/logging_vty.c</span><br><span>+++ b/src/vty/logging_vty.c</span><br><span>@@ -246,12 +246,14 @@</span><br><span> </span><br><span> DEFUN(logging_prnt_file,</span><br><span> logging_prnt_file_cmd,</span><br><span style="color: hsl(0, 100%, 40%);">- "logging print file (0|1|basename)",</span><br><span style="color: hsl(120, 100%, 40%);">+ "logging print file (0|1|basename) [last]",</span><br><span> LOGGING_STR "Log output settings\n"</span><br><span> "Configure log message\n"</span><br><span> "Don't prefix each log message\n"</span><br><span> "Prefix each log message with the source file and line\n"</span><br><span style="color: hsl(0, 100%, 40%);">- "Prefix each log message with the source file's basename (strip leading paths) and line\n")</span><br><span style="color: hsl(120, 100%, 40%);">+ "Prefix each log message with the source file's basename (strip leading paths) and line\n"</span><br><span style="color: hsl(120, 100%, 40%);">+ "Log source file info at the end of a log line. If omitted, log source file info just"</span><br><span style="color: hsl(120, 100%, 40%);">+ " before the log text.\n")</span><br><span> {</span><br><span> struct log_target *tgt = osmo_log_vty2tgt(vty);</span><br><span> </span><br><span>@@ -259,6 +261,10 @@</span><br><span> return CMD_WARNING;</span><br><span> </span><br><span> log_set_print_filename2(tgt, get_string_value(logging_print_file_args, argv[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ if (argc > 1)</span><br><span style="color: hsl(120, 100%, 40%);">+ log_set_print_filename_pos(tgt, LOG_FILENAME_POS_LINE_END);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ log_set_print_filename_pos(tgt, LOG_FILENAME_POS_HEADER_END);</span><br><span> return CMD_SUCCESS;</span><br><span> }</span><br><span> </span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/10631">change 10631</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/10631"/><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-MessageType: merged </div>
<div style="display:none"> Gerrit-Change-Id: I393907b3c9e0cc1145e102328adad0a83ee13a9f </div>
<div style="display:none"> Gerrit-Change-Number: 10631 </div>
<div style="display:none"> Gerrit-PatchSet: 1 </div>
<div style="display:none"> Gerrit-Owner: Neels Hofmeyr <nhofmeyr@sysmocom.de> </div>
<div style="display:none"> Gerrit-Reviewer: Harald Welte <laforge@gnumonks.org> </div>
<div style="display:none"> Gerrit-Reviewer: Jenkins Builder (1000002) </div>
<div style="display:none"> Gerrit-Reviewer: Neels Hofmeyr <nhofmeyr@sysmocom.de> </div>