[Home]

Summary:ASTERISK-08458: Cannot pass audio after transfer, intermittent segfault
Reporter:Kevin Otte (kjotte)Labels:
Date Opened:2006-12-29 19:51:54.000-0600Date Closed:2007-01-22 18:20:27.000-0600
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk-kaboom.txt
( 1) coredebug.txt
( 2) file-pass2.txt
( 3) noreinvite.txt
( 4) sipdebug.txt
Description:After upgrading from 1.2.13 to 1.4, attempting to transfer a call results in one way audio.  Additionally, the console is rather chatty about it, and asterisk intermittently segfaults.  See "Additional information" for a log of events.

The logs are from a 1.4.0 tarball compiled with no optimization.  Thanks to bkruse for his assistance.

****** ADDITIONAL INFORMATION ******

Order of events:
- Call remote party, both can hear each other
- Initiate transfer by calling other handset
- Called handset can hear calling handset
- Once transfer is complete, remote party can hear me, but I cannot hear remote party

    -- Executing [6013@local:1] Macro("SIP/sipura1-08194c48", "stdexten|6013|SIP/cmpalmer") in new stack
   -- Executing [s@macro-stdexten:1] Dial("SIP/sipura1-08194c48", "SIP/cmpalmer|20") in new stack
   -- Called cmpalmer
   -- SIP/cmpalmer-081db5c8 is ringing
   -- SIP/cmpalmer-081db5c8 answered SIP/sipura1-08194c48
   -- Packet2Packet bridging SIP/sipura1-08194c48 and SIP/cmpalmer-081db5c8
   -- Started music on hold, class 'default', on SIP/cmpalmer-081db5c8
[Dec 29 20:36:46] WARNING[11228]: interface.c:215 decodeMP3: Junk at the beginning of frame 49443303
   -- Executing [6003@local:1] Dial("SIP/sipura1-082007d8", "SIP/sipura2|30") in new stack
   -- Called sipura2
   -- SIP/sipura2-08205530 is ringing
   -- SIP/sipura2-08205530 answered SIP/sipura1-082007d8
   -- Packet2Packet bridging SIP/sipura1-082007d8 and SIP/sipura2-08205530
   -- Stopped music on hold on SIP/cmpalmer-081db5c8
   -- Packet2Packet bridging SIP/sipura1-08194c48 and SIP/cmpalmer-081db5c8
(last line repeats an indeterminate number of times)
[Dec 29 20:37:11] WARNING[11171]: chan_sip.c:12310 handle_response: Notify answer on an owned channel?[Dec 29 20:37:11] NOTICE[11228]: io.c:251 ast_io_remove: Unable to remove unknown id 0x81e3110
   -- Packet2Packet bridging SIP/sipura1-08194c48 and SIP/cmpalmer-081db5c8
(last line repeats an indeterminate number of times)
   -- Packet2Packet bridging SIP/cmpalmer-081db5c8 and SIP/sipura2-08205530
At this point asterisk may or may not segfault.

---
When remote party attempts to call in:

[Dec 29 20:42:30] ERROR[11171]: chan_sip.c:14652 sipsock_read: We could NOT get the channel lock for SIP/cmpalmer-08194c48!
[Dec 29 20:43:55] ERROR[11171]: chan_sip.c:14653 sipsock_read: SIP transaction failed: 44764baf-bbf4f469-c5ead5fc@192.168.10.14
 == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'SIP/cmpalmer-08194c48' in macro 'stdexten'
 == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'SIP/cmpalmer-08194c48'
   -- Executing [6000@local:1] Macro("SIP/cmpalmer-081e43a8", "stdexten|6001|SIP/sipura1&SIP/sipura2&SIP/cisco&SIP/nivex&IAX2/nivex") in new stack
   -- Executing [s@macro-stdexten:1] Dial("SIP/cmpalmer-081e43a8", "SIP/sipura1&SIP/sipura2&SIP/cisco&SIP/nivex&IAX2/nivex|20") in new stack
   -- Called sipura1
   -- Called sipura2
   -- Called cisco
[Dec 29 20:43:57] WARNING[11376]: app_dial.c:1081 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Dec 29 20:43:57] WARNING[11376]: app_dial.c:1081 dial_exec_full: Unable to create channel of type 'IAX2' (cause 3 - No route to destination)
   -- SIP/sipura1-081e5928 is ringing
   -- SIP/sipura2-081dcb48 is ringing
   -- SIP/cisco-081f2750 is ringing
   -- SIP/cisco-081f2750 answered SIP/cmpalmer-081e43a8
   -- Packet2Packet bridging SIP/cmpalmer-081e43a8 and SIP/cisco-081f2750
Segmentation fault
Comments:By: Kevin Otte (kjotte) 2006-12-29 19:58:51.000-0600

Can now reliably make the thing segfault:

- Perform transfer, get no audio.
- Hang up
- Remote calls back
- As soon as I answer the call, segfault

What configs, compiler options, etc would you like?
By: Kevin Otte (kjotte) 2006-12-29 20:27:55.000-0600

Perhaps I spoke too soon.  We had two or three consistent segfaults, but now it is not segfaulting again.  I have tried using both safe_asterisk and invoking asterisk -vvvvc directly.  The dropping of audio and chatty console is still quite consistent however.
By: Joshua C. Colp (jcolp) 2006-12-29 23:50:18.000-0600

Fixed in 1.4 as of revision 49066 and trunk as of revision 49067. Thanks!
By: Kevin Otte (kjotte) 2006-12-30 12:55:36.000-0600

I have built and installed from the specified SVN revision and the problem is still present :(
By: Joshua C. Colp (jcolp) 2006-12-30 12:56:58.000-0600

Then I need to see the current output, so attach it as a file please.
By: Kevin Otte (kjotte) 2006-12-30 16:11:48.000-0600

In order to ease testing I am now using phones all on my internal network. I have commented out all nat= and canreinvite= directives.

The sequence in the attached file repeats numerous times filling the console.  Hanging up the lines involved did not stop the output.  Had stop asterisk.

For reference, "cisco" is a Cisco 7960, "sipura1" and "sipura2" are ports on a Sipura SPA-2000.

I have tried transfers from and to the various different peers and all seem to produce this behavior.

Segfaults are still intermittent, and I cannot get it to dump core, but I can reliably reproduce these error messages.
By: Joshua C. Colp (jcolp) 2006-12-30 21:58:53.000-0600

Changing those options changed the code path followed, therefore not hitting my changes. Please go for canreinvite=no so that packet2packet bridging is used. If your stuff then works fine I will apply the same fix to native bridging.
By: Kevin Otte (kjotte) 2006-12-30 22:20:44.000-0600

I have attached the output of the procedure in 'noreinvite.txt'.  Not looking good.
By: Joshua C. Colp (jcolp) 2006-12-30 22:24:08.000-0600

Do core set debug 9 and make sure debug is set to go to console in logger.conf and add what it says.
By: Kevin Otte (kjotte) 2006-12-30 23:25:57.000-0600

Procedure as it sits now:

- 'cisco' calls 'sipura1'
- 'sipura1' flashes hook and initiates an attended transfer to 'sipura2'
- 'sipura1' and 'sipura2' talk to each other
- 'sipura1' flashes hook, all three parties talk to each other (I think.  With that many handsets and just one person, it is hard to tell where all the audio is going)
- 'sipura1' hangs up, audio becomes only one direction ('cisco' can hear 'sipura2') and the error messages occur
By: Serge Vecher (serge-v) 2007-01-02 10:57:50.000-0600

Alright, let me give ya a couple of pointers here for a good debug log:

1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterisk with the following command:
  'asterisk -Tvvvvvdddddngc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
5) Trim startup information and attach verbosedebug.txt to the issue.
By: Kevin Otte (kjotte) 2007-01-02 17:04:03.000-0600

serge-v: will take the trimming of startup info under advisement, but all other debug levels were set per file's instructions.
By: Serge Vecher (serge-v) 2007-01-03 08:19:47.000-0600

well, set verbose was not set in file-pass2.txt and I see no sip debug either.
By: Joshua C. Colp (jcolp) 2007-01-15 23:20:02.000-0600

Okay I made some changes to the way bridging happens in revision 50032 so give that a whirl.
By: Joshua C. Colp (jcolp) 2007-01-22 18:20:27.000-0600

Since there has been no reply back in a week I'm going to assuming that revision 50032 fixed this. Please reply back if not. Thanks!