<html>
<body>
<div style="font-family: Verdana, Arial, Helvetica, Sans-Serif;">
<table bgcolor="#f9f3c9" width="100%" cellpadding="8" style="border: 1px #c9c399 solid;">
<tr>
<td>
This is an automatically generated e-mail. To reply, visit:
<a href="https://reviewboard.asterisk.org/r/4502/">https://reviewboard.asterisk.org/r/4502/</a>
</td>
</tr>
</table>
<br />
<blockquote style="margin-left: 1em; border-left: 2px solid #d0d0d0; padding-left: 10px;">
<p style="margin-top: 0;">On March 24th, 2015, 1:52 p.m. EDT, <b>rmudgett</b> wrote:</p>
<blockquote style="margin-left: 1em; border-left: 2px solid #d0d0d0; padding-left: 10px;">
<table width="100%" border="0" bgcolor="white" style="border: 1px solid #C0C0C0; border-collapse: collapse; margin: 2px padding: 2px;">
<thead>
<tr>
<th colspan="4" bgcolor="#F0F0F0" style="border-bottom: 1px solid #C0C0C0; font-size: 9pt; padding: 4px 8px; text-align: left;">
<a href="https://reviewboard.asterisk.org/r/4502/diff/1/?file=72474#file72474line1762" style="color: black; font-weight: bold; text-decoration: underline;">/branches/13/main/logger.c</a>
<span style="font-weight: normal;">
(Diff revision 1)
</span>
</th>
</tr>
</thead>
<tbody style="background-color: #e4d9cb; padding: 4px 8px; text-align: center;">
<tr>
<td colspan="4"><pre style="font-size: 8pt; line-height: 140%; margin: 0; ">void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)</pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#b1ebb0" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2"></font></th>
<td bgcolor="#c5ffc4" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "></pre></td>
<th bgcolor="#b1ebb0" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2">1762</font></th>
<td bgcolor="#c5ffc4" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="kt">void</span> <span class="nf">ast_log_safe</span><span class="p">(</span><span class="kt">int</span> <span class="n">level</span><span class="p">,</span> <span class="k">const</span> <span class="kt">char</span> <span class="o">*</span><span class="n">file</span><span class="p">,</span> <span class="kt">int</span> <span class="n">line</span><span class="p">,</span> <span class="k">const</span> <span class="kt">char</span> <span class="o">*</span><span class="n">function</span><span class="p">,</span> <span class="k">const</span> <span class="kt">char</span> <span class="o">*</span><span class="n">fmt</span><span class="p">,</span> <span class="p">...)</span></pre></td>
</tr>
</tbody>
</table>
<pre style="white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">Why couldn't the log safe recursion check be done all the time by ast_log_full()?
Relying on users to know which log function should be used seems unreasonable for something as low level as logging. This seems more like an implementation detail that doesn't need to be exposed.
</pre>
</blockquote>
<p>On March 24th, 2015, 3:37 p.m. EDT, <b>Corey Farrell</b> wrote:</p>
<blockquote style="margin-left: 1em; border-left: 2px solid #d0d0d0; padding-left: 10px;">
<pre style="white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">Quoting Matt Jordan on ASTERISK-24833:
"I would say that any improvement that gets made should be subject to performance issues as well. Checking a threadlocal variable on every logging statement could get expensive."
I do not know what the performance hit of a threadlocal is, nor how to test for it. The idea with the separate function is that it's very rarely needed, compared to ast_log_full which is run constantly. I looked at this as the logger is responsible for ensuring it doesn't recurse by ensuring functions it calls only use ast_log_safe. There aren't many, and we shouldn't allow logger.c to start using more parts of Asterisk.
Additionally for Asterisk 11/13, it would be ineffective to check for recursion in ast_log_full. We would need to protect ast_log, along with all publicly reachable functions that can retreive the callid AO2 from threadstorage. Some functions would need to be split into a public function which checks recursion, and a private function that gets calls when recursion has already been checked.</pre>
</blockquote>
<p>On March 24th, 2015, 4:33 p.m. EDT, <b>rmudgett</b> wrote:</p>
<blockquote style="margin-left: 1em; border-left: 2px solid #d0d0d0; padding-left: 10px;">
<pre style="white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">ast_log_full() is the common base function that all logging paths get to so everything would be protected.
But since performance could be an issue then limiting which messages get blocked is more important than limiting recursion. The OOM and invalid ao2 object messages definitely need to be blocked. However, I'm not sure any others would need to be blocked even if called by the logging_thread.</pre>
</blockquote>
</blockquote>
<pre style="margin-left: 1em; white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">The problem with checking from ast_log_full (besides performance) is that any check in that function comes after ast_log has already retreived the AO2 callid. So a recursive loop can happen before ast_log_full is called.
The change to utils.c is not needed, I'll remove it on the next update. I still believe the change to strings.c is needed as it is effectively an OOM message which can be caused by calls ast_str_set/ast_str_append (logger routines use this).</pre>
<br />
<p>- Corey</p>
<br />
<p>On March 24th, 2015, 4:31 p.m. EDT, Corey Farrell wrote:</p>
<table bgcolor="#fefadf" width="100%" cellspacing="0" cellpadding="8" style="background-image: url('https://reviewboard.asterisk.org/static/rb/images/review_request_box_top_bg.ab6f3b1072c9.png'); background-position: left top; background-repeat: repeat-x; border: 1px black solid;">
<tr>
<td>
<div>Review request for Asterisk Developers.</div>
<div>By Corey Farrell.</div>
<p style="color: grey;"><i>Updated March 24, 2015, 4:31 p.m.</i></p>
<div style="margin-top: 1.5em;">
<b style="color: #575012; font-size: 10pt; margin-top: 1.5em;">Bugs: </b>
<a href="https://issues.asterisk.org/jira/browse/ASTERISK-24155">ASTERISK-24155</a>
</div>
<div style="margin-top: 1.5em;">
<b style="color: #575012; font-size: 10pt;">Repository: </b>
Asterisk
</div>
<h1 style="color: #575012; font-size: 10pt; margin-top: 1.5em;">Description </h1>
<table width="100%" bgcolor="#ffffff" cellspacing="0" cellpadding="10" style="border: 1px solid #b8b5a0">
<tr>
<td>
<pre style="margin: 0; padding: 0; white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">This introduces a new logger routine ast_log_safe. This routine should be used for all error messages in code that can be run as a result of ast_log. ast_log_safe does nothing if run recursively or from the logger thread. All error logging in astobj2.c, strings.c and utils.h have been switched to ast_log_safe. One ast_log from stringfields code in utils.c was also changed.
I've also added support for raw threadstorage. This provides direct access to the void* pointer in threadstorage. In ast_log_safe I use NULL to signify that this thread is not already running ast_log_safe, (void*)1 when it is already running. This was done since it's critical that ast_log_safe do nothing that could log during recursion checking.
This review shows the version 13 patch. Version 11 didn't have the backtrace check for MALLOC_FAILURE_MSG, and trunk uses 'ast_callid' instead of 'struct ast_callid *'. Patches for each version are on JIRA.
The idea to use threadstorage to protect certain error logging came from the patch posted by Timo Teräs.</pre>
</td>
</tr>
</table>
<h1 style="color: #575012; font-size: 10pt; margin-top: 1.5em;">Testing </h1>
<table width="100%" bgcolor="#ffffff" cellspacing="0" cellpadding="10" style="border: 1px solid #b8b5a0">
<tr>
<td>
<pre style="margin: 0; padding: 0; white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">Verified with 'nm -g main/astobj2.o' that ast_log_safe was being used.
Tested by further modifying Asterisk with added calls to ast_log_safe().
* In main() after fully booted.
* In ast_log_safe() after setting in_safe_log.
* From the logger thread.
Only the message after fully booted was shown in the logs, all others were ignored.</pre>
</td>
</tr>
</table>
<h1 style="color: #575012; font-size: 10pt; margin-top: 1.5em;">Diffs</b> </h1>
<ul style="margin-left: 3em; padding-left: 0;">
<li>/branches/13/main/utils.c <span style="color: grey">(433360)</span></li>
<li>/branches/13/main/strings.c <span style="color: grey">(433360)</span></li>
<li>/branches/13/main/logger.c <span style="color: grey">(433360)</span></li>
<li>/branches/13/main/hashtab.c <span style="color: grey">(433360)</span></li>
<li>/branches/13/main/astobj2.c <span style="color: grey">(433360)</span></li>
<li>/branches/13/include/asterisk/utils.h <span style="color: grey">(433360)</span></li>
<li>/branches/13/include/asterisk/threadstorage.h <span style="color: grey">(433360)</span></li>
<li>/branches/13/include/asterisk/logger.h <span style="color: grey">(433360)</span></li>
</ul>
<p><a href="https://reviewboard.asterisk.org/r/4502/diff/" style="margin-left: 3em;">View Diff</a></p>
</td>
</tr>
</table>
</div>
</body>
</html>