[Home]

Summary:ASTERISK-13839: Asterisk exits randomly when on Originate command
Reporter:Emmanuel BUU (neutrino88)Labels:
Date Opened:2009-03-26 07:57:19Date Closed:2011-06-07 14:00:23
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_local
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Hello,

Our Asterisk platform exits spontanously twice a day.
This happends under the following conditions:

1- an external application issues an Originate Manager command with a Local
2- THe Dialplan associated with the Local channel calls an outside SIP trunk carrier
3- when the call is answered, in some cases, Astersik exits;

There is no core file and from the GDB Capture, we can see that the process actually exits.

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

Extract of dialplan invoked by Originate command

context filterNat
{
       _0[1-56789]XXXXXXXX =>
       {
               Background(queue-thankyou,m);
               Dial(SIP/${EXTEN}@acropolis,90,m(sonnerie_relais));
               NoOp(${DIALSTATUS});

       };
Comments:By: Emmanuel BUU (neutrino88) 2009-03-26 07:59:15

Here are some traces of such a stop


<--- SIP read from 217.64.49.10:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 86.66.0.18:5090;branch=z9hG4bK3da591a0;received=86.66.0.18;rport=5090
From: "xxxxxxxxx" <sip:anonymous@acropolis.fr>;tag=as3088bb3a
To: <sip:0562919249@217.64.49.10>;tag=as18d76027
Call-ID: 2176cbaa3be91d33437b376f2a7ca63f@acropolis.fr
CSeq: 102 INVITE
User-Agent: MARS
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:0562919249@217.64.49.10>
Content-Type: application/sdp
Content-Length: 237

v=0
o=root 3151 3152 IN IP4 217.64.49.10
s=session
c=IN IP4 217.64.49.10
t=0 0
m=audio 8444 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

<------------->
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 0: SIP/2.0 200 OK (14)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 1: Via: SIP/2.0/UDP 86.66.0.18:5090;branch=z9hG4bK3da591a0;received=86.66.0.18;rport=5090 (86)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 2: From: "xxxxxxxxxx" <sip:anonymous@acropolis.fr>;tag=as3088bb3a (65)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 3: To: <sip:0562919249@217.64.49.10>;tag=as18d76027 (48)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 4: Call-ID: 2176cbaa3be91d33437b376f2a7ca63f@acropolis.fr (54)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 5: CSeq: 102 INVITE (16)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 6: User-Agent: MARS (16)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 8: Contact: <sip:0562919249@217.64.49.10> (38)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 9: Content-Type: application/sdp (29)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 10: Content-Length: 237 (19)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5237 parse_request: Header 11:  (0)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: v=0 (3)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: o=root 3151 3152 IN IP4 217.64.49.10 (36)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: s=session (9)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: c=IN IP4 217.64.49.10 (21)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: t=0 0 (5)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: m=audio 8444 RTP/AVP 0 8 101 (28)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: a=rtpmap:8 PCMA/8000 (20)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: a=fmtp:101 0-16 (15)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:5269 parse_request: Line: a=silenceSupp:off - - - - (25)
--- (11 headers 11 lines) ---
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:2239 __sip_ack: Acked pending invite 102
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:2275 __sip_ack: Stopping retransmission on '2176cbaa3be91d33437b376f2a7ca63f@acropolis.fr' of Request 102: Match Found
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:13417 handle_response_invite: SIP response 200 to standard invite
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 101
Found audio codec with Dynamic payload : 101.
Peer audio RTP is at port 217.64.49.10:8444
Found description format PCMU for codec ID 0
Found audio description format PCMU for ID 0
Found description format PCMA for codec ID 8
Found audio description format PCMA for ID 8
Found description format telephone-event for codec ID 101
Found audio description format telephone-event for ID 101
[Mar 26 13:27:23] WARNING[9798]: chan_sip.c:5538 parse_video_fmtp: Got unsupported audio a:fmtp in SDP offer for codec ID 101
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6074 process_sdp: T38 state changed to 0 on channel SIP/acropolis-0138b5e0
[Mar 26 13:27:23] DEBUG[9798]: capability.c:398 ast_compute_max_audio_bw: Computing max bandwidth for format 0000000c.
[Mar 26 13:27:23] DEBUG[9798]: capability.c:418 ast_compute_max_audio_bw: Max bandwidth for format 0000000c is 64000 bps.
Peer audio RTP is at port 217.64.49.10:8444
Peer text RTP is at port 217.64.49.10:27651
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6218 process_sdp: GDM : Peer text RTP is at port 217.64.49.10:27651
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6224 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6231 process_sdp: We have an owner, now see if we need to change this call
[Mar 26 13:27:23] DEBUG[9798]: channel.c:2768 set_format: chan=SIP/acropolis-0138b5e0 format=00000004 (with video & text = 00000004) native=00000004 in dir. read
[Mar 26 13:27:23] DEBUG[9798]: channel.c:2768 set_format: chan=SIP/acropolis-0138b5e0 format=00000004 (with video & text = 00000004) native=00000004 in dir. write
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6254 process_sdp: Finally native format for chan is 0x4 (ulaw)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6255 process_sdp: Finally jointcapability format for chan is 0xc (ulaw|alaw)
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:3342 update_call_counter: Updating call counter for outgoing call
[Mar 26 13:27:23] DEBUG[9798]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/acropolis
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:9404 build_route: build_route: Contact hop: <sip:0562919249@217.64.49.10>
list_route: hop: <sip:0562919249@217.64.49.10>
[Mar 26 13:27:23] DEBUG[9798]: chan_sip.c:6648 reqprep: Strict routing enforced for session 2176cbaa3be91d33437b376f2a7ca63f@acropolis.fr
set_destination: Parsing <sip:0562919249@217.64.49.10> for address/port to send to
set_destination: set destination to 217.64.49.10, port 5060
Transmitting (NAT) to 217.64.49.10:5060:
ACK sip:0562919249@217.64.49.10 SIP/2.0
Via: SIP/2.0/UDP 86.66.0.18:5090;branch=z9hG4bK7c0ca055;rport
From: "xxxxxxxx" <sip:anonymous@acropolis.fr>;tag=as3088bb3a
To: <sip:0562919249@217.64.49.10>;tag=as18d76027
Contact: <sip:anonymous@86.66.0.18:5090>
Call-ID: 2176cbaa3be91d33437b376f2a7ca63f@acropolis.fr
CSeq: 102 ACK
User-Agent: Visio 4
Max-Forwards: 70
Content-Length: 0


---
[Mar 26 13:27:23] DEBUG[9780]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - acropolis
[Mar 26 13:27:23] DEBUG[9780]: chan_sip.c:17301 sip_devicestate: Checking device state for peer acropolis
[Mar 26 13:27:23] DEBUG[9780]: devicestate.c:287 do_state_change: Changing state for SIP/acropolis - state 2 (In use)
[Mar 26 13:27:23] DEBUG[9782]: app_queue.c:668 handle_statechange: Device 'SIP/acropolis' changed to state '2' (In use) but we don't care because they're not a member of any queu.
[Mar 26 13:27:23] DEBUG[15162]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/acropolis-0138b5e0
[Mar 26 13:27:23] DEBUG[15162]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/acropolis
[Mar 26 13:27:23] DEBUG[9780]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - acropolis-0138b5e0
[Mar 26 13:27:23] DEBUG[15162]: cdr.c:709 ast_cdr_answer: CDR answer: sending packet for channel SIP/acropolis-0138b5e0
   -- SIP/acropolis-0138b5e0 answered Local/0562919249@filterNat-b067,2
[Mar 26 13:27:23] DEBUG[15162]: rtp.c:1523 ast_rtp_early_bridge: Channel 'Local/0562919249@filterNat-b067,2' has no RTP, not doing anything
   -- Stopped music on hold on Local/0562919249@filterNat-b067,2
[Mar 26 13:27:23] DEBUG[9780]: chan_sip.c:17301 sip_devicestate: Checking device state for peer acropolis-0138b5e0
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2768 set_format: chan=Local/0562919249@filterNat-b067,2 format=00000040 (with video & text = 00000040) native=00200040 in dir. write
[Mar 26 13:27:23] DEBUG[15162]: channel.c:3201 ast_channel_make_compatible: src chan Local/0562919249@filterNat-b067,2 with format 00200040 to dst chan SIP/acropolis-0138b5e0 wit format 00000004
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2768 set_format: chan=Local/0562919249@filterNat-b067,2 format=00000004 (with video & text = 00000004) native=00200040 in dir. read
[Mar 26 13:27:23] DEBUG[15162]: translate.c:275 ast_translator_build_path: Building translator path from 00000040 to 00000004
[Mar 26 13:27:23] DEBUG[15162]: translate.c:284 ast_translator_build_path: Step from path from 6 to 2
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2807 set_format: Set channel Local/0562919249@filterNat-b067,2 to read format ulaw
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2768 set_format: chan=SIP/acropolis-0138b5e0 format=00000004 (with video & text = 00000004) native=00000004 in dir. write
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2768 set_format: chan=SIP/acropolis-0138b5e0 format=00000040 (with video & text = 00000040) native=00000004 in dir. read
[Mar 26 13:27:23] DEBUG[15162]: translate.c:275 ast_translator_build_path: Building translator path from 00000004 to 00000040
[Mar 26 13:27:23] DEBUG[15162]: translate.c:284 ast_translator_build_path: Step from path from 2 to 6
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2807 set_format: Set channel SIP/acropolis-0138b5e0 to read format slin
[Mar 26 13:27:23] DEBUG[15162]: channel.c:2768 set_format: chan=Local/0562919249@filterNat-b067,2 format=00000040 (with video & text = 00000040) native=00200040 in dir. write
[Mar 26 13:27:23] DEBUG[15162]: channel.c:3306 ast_channel_masquerade: Planning to masquerade channel SIP/acropolis-0138b5e0 into the structure of Local/0562919249@filterNat-b0671
[Mar 26 13:27:23] DEBUG[15163]: channel.c:2575 ast_write: Deadlock avoided for write to channel 'Local/0562919249@filterNat-b067,1'
[Mar 26 13:27:23] DEBUG[15162]: channel.c:3320 ast_channel_masquerade: Done planning to masquerade channel SIP/acropolis-0138b5e0 into the structure of Local/0562919249@filterNatb067,1
[Mar 26 13:27:23] DEBUG[15163]: channel.c:3429 ast_do_masquerade: Actually Masquerading SIP/acropolis-0138b5e0(6) into the structure of Local/0562919249@filterNat-b067,1(6)
[Mar 26 13:27:23] DEBUG[15163]: channel.c:3441 ast_do_masquerade: Got clone lock for masquerade on 'SIP/acropolis-0138b5e0' at 0x138fc40
[Mar 26 13:27:23] DEBUG[15162]: chan_local.c:312 local_write: Not posting to queue since already masked on 'Local/0562919249@filterNat-b067,2'
visio4*CLI>
Disconnected from Asterisk server
By: Emmanuel BUU (neutrino88) 2009-03-26 08:00:28

gdb capture upon stop

[New Thread 0x4026f950 (LWP 15161)]
[New Thread 0x400ec950 (LWP 15162)]
[New Thread 0x4036d950 (LWP 15163)]
[Thread 0x4026f950 (LWP 15161) exited]
[New Thread 0x4026f950 (LWP 15164)]
[Thread 0x4026f950 (LWP 15164) exited]
[New Thread 0x4026f950 (LWP 15165)]
[Thread 0x4026f950 (LWP 15165) exited]
[Thread 0x4195d950 (LWP 14783) exited]
[Thread 0x4036d950 (LWP 15163) exited]
[Thread 0x400ec950 (LWP 15162) exited]
[Thread 0x41341950 (LWP 14782) exited]
[Thread 0x4119d950 (LWP 14751) exited]
[Thread 0x41107950 (LWP 13922) exited]
[Thread 0x42035950 (LWP 9778) exited]
[Thread 0x41c48950 (LWP 9779) exited]
[Thread 0x413cb950 (LWP 9780) exited]
[Thread 0x407c9950 (LWP 9781) exited]
[Thread 0x354950 (LWP 9782) exited]
[Thread 0x390950 (LWP 9783) exited]
[Thread 0x3cc950 (LWP 9784) exited]
[Thread 0x571950 (LWP 9785) exited]
[Thread 0x5ad950 (LWP 9786) exited]
[Thread 0x5e9950 (LWP 9787) exited]
[Thread 0x625950 (LWP 9788) exited]
[Thread 0x661950 (LWP 9789) exited]
[Thread 0x69d950 (LWP 9790) exited]
[Thread 0x6d9950 (LWP 9791) exited]
[Thread 0x715950 (LWP 9792) exited]
[Thread 0x4769950 (LWP 9793) exited]
[Thread 0x11d9950 (LWP 9794) exited]
[Thread 0x1215950 (LWP 9795) exited]
[Thread 0x3d97950 (LWP 9796) exited]
[Thread 0x1251950 (LWP 9797) exited]
[Thread 0x36c9950 (LWP 9798) exited]
[Thread 0x33fe950 (LWP 9799) exited]
[Thread 0x3917950 (LWP 9800) exited]
[Thread 0x128d950 (LWP 9801) exited]
[Thread 0x12c9950 (LWP 9802) exited]
[Thread 0x417b3950 (LWP 9804) exited]
[Thread 0x41161950 (LWP 9805) exited]
[Thread 0x41d89950 (LWP 9872) exited]
[Thread 0x41479950 (LWP 9803) exited]

Program exited with code 0177.
(gdb)
The program is not being run.
(gdb) where
No stack.
By: Emmanuel BUU (neutrino88) 2009-03-26 08:03:21

This is a trace in call that is CORRECTLY processed

[Mar 26 14:01:10] DEBUG[16346] channel.c: Planning to masquerade channel SIP/acropolis-010807e0 into the structure of Local/0613021703@filterNat-07bd,1
[Mar 26 14:01:10] DEBUG[16346] channel.c: Done planning to masquerade channel SIP/acropolis-010807e0 into the structure of Local/0613021703@filterNat-07bd,1
[Mar 26 14:01:10] DEBUG[16346] chan_local.c: Not posting to queue since already masked on 'Local/0613021703@filterNat-07bd,2'
[Mar 26 14:01:10] DEBUG[16347] channel.c: Actually Masquerading SIP/acropolis-010807e0(6) into the structure of Local/0613021703@filterNat-07bd,1(6)
[Mar 26 14:01:10] DEBUG[16347] channel.c: Got clone lock for masquerade on 'SIP/acropolis-010807e0' at 0x10ed470
[Mar 26 14:01:10] DEBUG[16347] channel.c: chan=SIP/acropolis-010807e0 format=00000040 (with video & text = 00000040) native=00000004 in dir. write
[Mar 26 14:01:10] DEBUG[16347] translate.c: Building translator path from 00000040 to 00000004
[Mar 26 14:01:10] DEBUG[16347] translate.c: Step from path from 6 to 2
[Mar 26 14:01:10] DEBUG[16347] channel.c: Set channel SIP/acropolis-010807e0 to write format slin
[Mar 26 14:01:10] DEBUG[16347] channel.c: chan=SIP/acropolis-010807e0 format=00000040 (with video & text = 00000040) native=00000004 in dir. read
[Mar 26 14:01:10] DEBUG[16347] translate.c: Building translator path from 00000004 to 00000040
[Mar 26 14:01:10] DEBUG[16347] translate.c: Step from path from 2 to 6
[Mar 26 14:01:10] DEBUG[16347] channel.c: Set channel SIP/acropolis-010807e0 to read format slin
[Mar 26 14:01:10] DEBUG[16347] channel.c: Putting channel SIP/acropolis-010807e0 in 64/64 formats
[Mar 26 14:01:10] DEBUG[16347] chan_sip.c: SIP Fixup: New owner for dialogue 51889efb3e4d743519b8f8d40647a979@acropolis.fr: SIP/acropolis-010807e0 (Old parent: Local/0613021703@filterNat-07bd,1<ZOMBIE>)
[Mar 26 14:01:10] DEBUG[16347] channel.c: Released clone lock on 'Local/0613021703@filterNat-07bd,1<ZOMBIE>'
[Mar 26 14:01:10] DEBUG[16347] channel.c: Done Masquerading SIP/acropolis-010807e0 (6)
[Mar 26 14:01:10] DEBUG[16346] channel.c: Didn't get a frame from channel: Local/0613021703@filterNat-07bd,2
[Mar 26 14:01:10] DEBUG[16346] channel.c: Bridge stops bridging channels Local/0613021703@filterNat-07bd,2 and Local/0613021703@filterNat-07bd,1<ZOMBIE>
[Mar 26 14:01:10] DEBUG[16346] channel.c: Hanging up zombie 'Local/0613021703@filterNat-07bd,1<ZOMBIE>'
[Mar 26 14:01:10] DEBUG[16346] devicestate.c: Notification of state change to be queued on device/channel Local/0613021703@filterNat-07bd,1<ZOMBIE>
[Mar 26 14:01:10] DEBUG[16346] devicestate.c: Notification of state change to be queued on device/channel Local/0613021703@filterNat
[Mar 26 14:01:10] DEBUG[16346] rtp.c: Channel 'Local/0613021703@filterNat-07bd,2' has no RTP, not doing anything
[Mar 26 14:01:10] DEBUG[16346] app_dial.c: Exiting with DIALSTATUS=ANSWER.
By: Emmanuel BUU (neutrino88) 2009-03-31 08:37:11

Please, close this bug.
It was due to a patch for 1.4.23 applied on asterisk 1.4.19.

a function was not defined in chan_local.c

it was strange that chan_local succeed to load even if this function was not define.
By: Leif Madsen (lmadsen) 2009-04-09 10:58:42

Closed per reporter.

In the future when you report an issue, it is very bad practice to not mention you have a non-vanilla system. Make sure you mention ANY changes you have made to Asterisk so the developers can better track down your issue. Thanks!