<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/2594/">https://reviewboard.asterisk.org/r/2594/</a>
</td>
</tr>
</table>
<br />
<div>
<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/2594/diff/3/?file=39147#file39147line11546" style="color: black; font-weight: bold; text-decoration: underline;">branches/11/channels/chan_iax2.c</a>
<span style="font-weight: normal;">
(Diff revision 3)
</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; ">immediatedial:</pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#e9eaa8" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2">11531</font></th>
<td bgcolor="#fdfebc" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>if <span class="hl">(</span>(iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_READY) <span class="hl">||</span></pre></td>
<th bgcolor="#e9eaa8" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2">11546</font></th>
<td bgcolor="#fdfebc" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>if (iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_MREADY) {</pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#ebb1ba" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2">11532</font></th>
<td bgcolor="#ffc5ce" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span> (iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_MREADY)) {</pre></td>
<th bgcolor="#ebb1ba" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2"></font></th>
<td bgcolor="#ffc5ce" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "></pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#f0f0f0" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2">11533</font></th>
<td bgcolor="#ffffff" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>/* They're both ready, now release them. */</pre></td>
<th bgcolor="#f0f0f0" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2">11547</font></th>
<td bgcolor="#ffffff" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>/* They're both ready, now release them. */</pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#ebb1ba" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2">11534</font></th>
<td bgcolor="#ffc5ce" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>if (iaxs[fr->callno]->transferring == TRANSFER_MREADY) {</pre></td>
<th bgcolor="#ebb1ba" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2"></font></th>
<td bgcolor="#ffc5ce" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "></pre></td>
</tr>
</tbody>
<tbody>
<tr>
<th bgcolor="#f0f0f0" style="border-right: 1px solid #C0C0C0;" align="right"><font size="2">11535</font></th>
<td bgcolor="#ffffff" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>ast_verb(3, "Attempting media bridge of %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",</pre></td>
<th bgcolor="#f0f0f0" style="border-left: 1px solid #C0C0C0; border-right: 1px solid #C0C0C0;" align="right"><font size="2">11548</font></th>
<td bgcolor="#ffffff" width="50%"><pre style="font-size: 8pt; line-height: 140%; margin: 0; "><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span><span class="tb"> </span>ast_verb(3, "Attempting media bridge of %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",</pre></td>
</tr>
</tbody>
</table>
<pre style="margin-left: 2em; white-space: pre-wrap; white-space: -moz-pre-wrap; white-space: -pre-wrap; white-space: -o-pre-wrap; word-wrap: break-word;">I'm not sure I understand why this change was made.
I can see the race condition without first obtaining the lock; however, why should the behavior of TRANSFER_READY be changed? With this code change, a TRANSFER_READY doesn't transition to TRANSFER_MEDIA. Additionally, we don't handle the 'any other state is a release' condition any longer.
This change may be completely correct, but based on the problem description, I'm not sure why it's needed or what other side effects it may have.</pre>
</div>
<br />
<p>- Matt</p>
<br />
<p>On June 5th, 2013, 10:52 a.m. UTC, Alec Davis 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.png'); background-position: left top; background-repeat: repeat-x; border: 1px black solid;">
<tr>
<td>
<div>Review request for Asterisk Developers.</div>
<div>By Alec Davis.</div>
<p style="color: grey;"><i>Updated June 5, 2013, 10:52 a.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-21409">ASTERISK-21409</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;">1). When touching the bridgecallno, we need to lock it.
2). stop_stuff() which calls iax2_destroy_helper()
Assumes the lock on the pvt is already held, when iax2_destroy_helper() is called.
Thus we need to lock the bridgecallno pvt before we call stop_stuff(iaxs[fr->callno]->bridgecallno);
3). When evaluating the state of 'callno->transferring' of the current leg, we can't change it to READY unless the bridgecallno is locked.
Why, if we are interrupted by the other call leg before 'transferring = TRANSFER_RELEASED', the interrupt will find that it is READY and that the bridgecallno is also READY so Releases the legs.
Then the first call leg in this example, finishes execution, and Releases the legs AGAIN!!!!!!!
Interleaving thread execution gets interesting as well - see timeline below from June 5.
Debug captures when it went wrong.
[May 31 14:44:01] VERBOSE[30820] chan_iax2.c: -- Channel 'IAX2/auckland-13262' ready to transfer
[May 31 14:44:01] VERBOSE[30824][C-00000536] chan_iax2.c: -- Channel 'IAX2/auckland-20457' ready to transfer
[May 31 14:44:01] VERBOSE[30824][C-00000536] chan_iax2.c: -- Releasing IAX2/auckland-20457 and IAX2/auckland-13262
[May 31 14:44:01] VERBOSE[30820] chan_iax2.c: -- Releasing IAX2/auckland-13262 and IAX2/auckland-20457
[May 31 14:44:01] DEBUG[30824][C-00000536] sched.c: Attempted to delete nonexistent schedule entry 209951!
[May 31 14:44:01] ERROR[30824][C-00000536] lock.c: chan_iax2.c line 1918 (iax2_destroy_helper): mutex '&iaxsl[pvt->callno]' freed more times than we've locked!
[May 31 14:44:01] ERROR[30824][C-00000536] lock.c: chan_iax2.c line 1918 (iax2_destroy_helper): Error releasing mutex: Operation not permitted
[Jun 5 19:53:43] VERBOSE[25606][C-00000000] chan_iax2.c: -- Channel 'IAX2/auckland-19065' ready to transfer
[Jun 5 19:53:43] VERBOSE[25604][C-00000000] chan_iax2.c: -- Channel 'IAX2/auckland-20047' ready to transfer
[Jun 5 19:53:43] VERBOSE[25606][C-00000000] chan_iax2.c: -- Releasing IAX2/auckland-19065 and IAX2/auckland-20047
[Jun 5 19:53:43] VERBOSE[25604][C-00000000] chan_iax2.c: -- Releasing IAX2/auckland-20047 and IAX2/auckland-19065
[Jun 5 19:53:43] VERBOSE[25606][C-00000000] chan_iax2.c: -- Channel 'IAX2/auckland-19065' finished transfer
[Jun 5 19:53:43] DEBUG[25604][C-00000000] sched.c: Attempted to delete nonexistent schedule entry 17!
[Jun 5 19:53:43] VERBOSE[25604][C-00000000] chan_iax2.c: -- Channel 'IAX2/auckland-20047' finished transfer
A time line of 2 threads interleaving that shows how the Jun 5 capture may have come about.
The execution path seems to switch threads as we print/log data.
thread 25606 thread 25604
====================== =======================
if US == BEGIN
US = READY
"ready to transfer"
if US == BEGIN
US = READY
"ready to transfer"
if THEY == READY
"Releasing .."
if THEY == READY
"Releasing .."
THEY = RELEASED
US = RELEASED
stopstuff(US)
stopstuff(THEM)
"finished transfer"
THEY = RELEASED
US = RELEASED
stopstuff(US)
stopstuff(THEM) (sched.c: Attempted to delete nonexistent schedule entry 17!)
"finished transfer"
</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;">Yes. Between sites. many test calls and real calls being transferred back down the same trunk</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/11/channels/chan_iax2.c <span style="color: grey">(387927)</span></li>
</ul>
<p><a href="https://reviewboard.asterisk.org/r/2594/diff/" style="margin-left: 3em;">View Diff</a></p>
</td>
</tr>
</table>
</div>
</body>
</html>