Review Board 1.7.16


IAX2: fix race condition when transferrring.

Review Request #2594 - Created June 4, 2013 and submitted

Alec Davis
1.8 to trunk
ASTERISK-21409
Reviewers
asterisk-dev
Asterisk
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"

Yes. Between sites. many test calls and real calls being transferred back down the same trunk

Changes between revision 1 and 4

1 2 3 4
1 2 3 4

  1. branches/11/channels/chan_iax2.c: Loading...
branches/11/channels/chan_iax2.c
Diff Revision 1 Diff Revision 4
[20] 11506 lines
[+20] [+] immediatedial:
11507
					iax_ie_append_byte(&ied0, IAX_IE_CAUSECODE, AST_CAUSE_FACILITY_NOT_SUBSCRIBED);
11507
					iax_ie_append_byte(&ied0, IAX_IE_CAUSECODE, AST_CAUSE_FACILITY_NOT_SUBSCRIBED);
11508
					send_command_final(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_REJECT, 0, ied0.buf, ied0.pos, -1);
11508
					send_command_final(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_REJECT, 0, ied0.buf, ied0.pos, -1);
11509
				}
11509
				}
11510
				break;
11510
				break;
11511
			case IAX_COMMAND_TXREJ:
11511
			case IAX_COMMAND_TXREJ:
11512
				iaxs[fr->callno]->transferring = TRANSFER_NONE;
11512
				iaxs[fr->callno]->transferring = 0;
11513
				ast_verb(3, "Channel '%s' unable to transfer\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>");
11513
				ast_verb(3, "Channel '%s' unable to transfer\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>");
11514
				memset(&iaxs[fr->callno]->transfer, 0, sizeof(iaxs[fr->callno]->transfer));
11514
				memset(&iaxs[fr->callno]->transfer, 0, sizeof(iaxs[fr->callno]->transfer));
11515
				if (iaxs[fr->callno]->bridgecallno) {
11515
				if (iaxs[fr->callno]->bridgecallno) {
11516
					if (iaxs[iaxs[fr->callno]->bridgecallno]->transferring) {
11516
					if (iaxs[iaxs[fr->callno]->bridgecallno]->transferring) {
11517
						iaxs[iaxs[fr->callno]->bridgecallno]->transferring = TRANSFER_NONE;
11517
						iaxs[iaxs[fr->callno]->bridgecallno]->transferring = 0;
11518
						send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXREJ, 0, NULL, 0, -1);
11518
						send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXREJ, 0, NULL, 0, -1);
11519
					}
11519
					}
11520
				}
11520
				}
11521
				break;
11521
				break;
11522
			case IAX_COMMAND_TXREADY:
11522
			case IAX_COMMAND_TXREADY:
[+20] [20] 4 lines
[+20] immediatedial:
11527
					if (!iaxs[fr->callno]) {
11527
					if (!iaxs[fr->callno]) {
11528
						break;
11528
						break;
11529
					}
11529
					}
11530
				}
11530
				}
11531

    
   
11531

   
11532
				if (iaxs[fr->callno]->transferring == TRANSFER_MBEGIN) {
11532
				if ((iaxs[fr->callno]->transferring == TRANSFER_BEGIN) ||

    
   
11533
				    (iaxs[fr->callno]->transferring == TRANSFER_MBEGIN)) {

    
   
11534
					if (iaxs[fr->callno]->transferring == TRANSFER_MBEGIN)
11533
					iaxs[fr->callno]->transferring = TRANSFER_MREADY;
11535
						iaxs[fr->callno]->transferring = TRANSFER_MREADY;
11534
				} else if (iaxs[fr->callno]->transferring == TRANSFER_BEGIN) {
11536
					else
11535
					iaxs[fr->callno]->transferring = TRANSFER_READY;
11537
						iaxs[fr->callno]->transferring = TRANSFER_READY;
11536
				} else {

   
11537
					if (iaxs[fr->callno]->bridgecallno) {

   
11538
	      					ast_mutex_unlock(&iaxsl[iaxs[fr->callno]->bridgecallno]);

   
11539
					}

   
11540
					break;

   
11541
				}

   
11542

    
   

   
11543
				ast_verb(3, "Channel '%s' ready to transfer\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>");
11538
					ast_verb(3, "Channel '%s' ready to transfer\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>");
11544

    
   

   
11545
				if (iaxs[fr->callno]->bridgecallno) {
11539
					if (iaxs[fr->callno]->bridgecallno) {
11546
					if (iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_MREADY) {
11540
						if ((iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_READY) ||

    
   
11541
						    (iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_MREADY)) {
11547
						/* They're both ready, now release them. */
11542
							/* They're both ready, now release them. */

    
   
11543
							if (iaxs[fr->callno]->transferring == TRANSFER_MREADY) {
11548
						ast_verb(3, "Attempting media bridge of %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",
11544
								ast_verb(3, "Attempting media bridge of %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",
11549
							iaxs[iaxs[fr->callno]->bridgecallno]->owner ? ast_channel_name(iaxs[iaxs[fr->callno]->bridgecallno]->owner) : "<Unknown>");
11545
										iaxs[iaxs[fr->callno]->bridgecallno]->owner ? ast_channel_name(iaxs[iaxs[fr->callno]->bridgecallno]->owner) : "<Unknown>");
11550

    
   
11546

   
11551
						iaxs[iaxs[fr->callno]->bridgecallno]->transferring = TRANSFER_MEDIA;
11547
								iaxs[iaxs[fr->callno]->bridgecallno]->transferring = TRANSFER_MEDIA;
11552
						iaxs[fr->callno]->transferring = TRANSFER_MEDIA;
11548
								iaxs[fr->callno]->transferring = TRANSFER_MEDIA;
11553

    
   
11549

   
11554
						memset(&ied0, 0, sizeof(ied0));
11550
								memset(&ied0, 0, sizeof(ied0));
11555
						memset(&ied1, 0, sizeof(ied1));
11551
								memset(&ied1, 0, sizeof(ied1));
11556

    
   

   
11557
						iax_ie_append_short(&ied0, IAX_IE_CALLNO, iaxs[iaxs[fr->callno]->bridgecallno]->peercallno);
11552
								iax_ie_append_short(&ied0, IAX_IE_CALLNO, iaxs[iaxs[fr->callno]->bridgecallno]->peercallno);
11558
						iax_ie_append_short(&ied1, IAX_IE_CALLNO, iaxs[fr->callno]->peercallno);
11553
								iax_ie_append_short(&ied1, IAX_IE_CALLNO, iaxs[fr->callno]->peercallno);
11559

    
   

   
11560
						send_command(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_TXMEDIA, 0, ied0.buf, ied0.pos, -1);
11554
								send_command(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_TXMEDIA, 0, ied0.buf, ied0.pos, -1);
11561
						send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXMEDIA, 0, ied1.buf, ied1.pos, -1);
11555
								send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXMEDIA, 0, ied1.buf, ied1.pos, -1);
11562

    
   
11556
							} else {
11563
					} else if (iaxs[iaxs[fr->callno]->bridgecallno]->transferring == TRANSFER_READY) {

   
11564
						/* They're both ready, now release them. */

   
11565
						ast_verb(3, "Releasing %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",
11557
								ast_verb(3, "Releasing %s and %s\n", iaxs[fr->callno]->owner ? ast_channel_name(iaxs[fr->callno]->owner) : "<Unknown>",
11566
							iaxs[iaxs[fr->callno]->bridgecallno]->owner ? ast_channel_name(iaxs[iaxs[fr->callno]->bridgecallno]->owner) : "<Unknown>");
11558
										iaxs[iaxs[fr->callno]->bridgecallno]->owner ? ast_channel_name(iaxs[iaxs[fr->callno]->bridgecallno]->owner) : "<Unknown>");
11567

    
   
11559

   
11568
						iaxs[iaxs[fr->callno]->bridgecallno]->transferring = TRANSFER_RELEASED;
11560
								iaxs[iaxs[fr->callno]->bridgecallno]->transferring = TRANSFER_RELEASED;
11569
						iaxs[fr->callno]->transferring = TRANSFER_RELEASED;
11561
								iaxs[fr->callno]->transferring = TRANSFER_RELEASED;
11570

    
   

   
11571
						ast_set_flag64(iaxs[iaxs[fr->callno]->bridgecallno], IAX_ALREADYGONE);
11562
								ast_set_flag64(iaxs[iaxs[fr->callno]->bridgecallno], IAX_ALREADYGONE);
11572
						ast_set_flag64(iaxs[fr->callno], IAX_ALREADYGONE);
11563
								ast_set_flag64(iaxs[fr->callno], IAX_ALREADYGONE);
11573

    
   
11564

   
11574
						/* Stop doing lag & ping requests */
11565
								/* Stop doing lag & ping requests */
11575
						stop_stuff(fr->callno);
11566
								stop_stuff(fr->callno);
11576
						stop_stuff(iaxs[fr->callno]->bridgecallno);
11567
								stop_stuff(iaxs[fr->callno]->bridgecallno);
11577

    
   
11568

   
11578
						memset(&ied0, 0, sizeof(ied0));
11569
								memset(&ied0, 0, sizeof(ied0));
11579
						memset(&ied1, 0, sizeof(ied1));
11570
								memset(&ied1, 0, sizeof(ied1));
11580

    
   

   
11581
						iax_ie_append_short(&ied0, IAX_IE_CALLNO, iaxs[iaxs[fr->callno]->bridgecallno]->peercallno);
11571
								iax_ie_append_short(&ied0, IAX_IE_CALLNO, iaxs[iaxs[fr->callno]->bridgecallno]->peercallno);
11582
						iax_ie_append_short(&ied1, IAX_IE_CALLNO, iaxs[fr->callno]->peercallno);
11572
								iax_ie_append_short(&ied1, IAX_IE_CALLNO, iaxs[fr->callno]->peercallno);
11583

    
   

   
11584
						send_command(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_TXREL, 0, ied0.buf, ied0.pos, -1);
11573
								send_command(iaxs[fr->callno], AST_FRAME_IAX, IAX_COMMAND_TXREL, 0, ied0.buf, ied0.pos, -1);
11585
						send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXREL, 0, ied1.buf, ied1.pos, -1);
11574
								send_command(iaxs[iaxs[fr->callno]->bridgecallno], AST_FRAME_IAX, IAX_COMMAND_TXREL, 0, ied1.buf, ied1.pos, -1);

    
   
11575
							}
11586

    
   
11576

   
11587
					}
11577
						}
11588
      					ast_mutex_unlock(&iaxsl[iaxs[fr->callno]->bridgecallno]);

   
11589
				}
11578
					}

    
   
11579
				}

    
   
11580
				if (iaxs[fr->callno]->bridgecallno) {

    
   
11581
					ast_mutex_unlock(&iaxsl[iaxs[fr->callno]->bridgecallno]);

    
   
11582
				} 
11590
				break;
11583
				break;
11591
			case IAX_COMMAND_TXREQ:
11584
			case IAX_COMMAND_TXREQ:
11592
				try_transfer(iaxs[fr->callno], &ies);
11585
				try_transfer(iaxs[fr->callno], &ies);
11593
				break;
11586
				break;
11594
			case IAX_COMMAND_TXCNT:
11587
			case IAX_COMMAND_TXCNT:
[+20] [20] 3489 lines
  1. branches/11/channels/chan_iax2.c: Loading...

https://reviewboard.asterisk.org/ runs on a server provided by Digium, Inc. and uses bandwidth donated to the open source Asterisk community by API Digital Communications in Huntsville, AL USA.
Please report problems with this site to asteriskteam@digium.com.