| Summary: | ASTERISK-12346: [patch] 183 response although progressinband=never | ||||
| Reporter: | klaus3000 (klaus3000) | Labels: | |||
| Date Opened: | 2008-07-09 07:03:58 | Date Closed: | 2009-09-18 09:49:48 | ||
| Priority: | Minor | Regression? | No | ||
| Status: | Closed/Complete | Components: | Channels/chan_dahdi | ||
| Versions: | Frequency of Occurrence | ||||
| Related Issues: |
| ||||
| Environment: | Attachments: | ( 0) 20090316__bug13034.diff.txt ( 1) patch_trunk_183progress_klaus3000.txt ( 2) prematuremedia.diff ( 3) sip-rtp.pcap ( 4) trace1_PROCEEDING_without_PROGRESSINDIKATOR.txt ( 5) trace2_PROCEEDING_with_PROGRESSINDIKATOR.txt ( 6) trace3_without_PROGRESSINDIKATOR.txt | |||
| Description: | Hi! Scenario with Asterisk 1.4.21.1: SIP Client ----> chan_sip:Dial(zap):chan_zap ---> ISDN very simple dialplan: [fromklaus] exten => _1X.,1,NoOp(1... SIP: Outgoing Call: Asterisk->HiCom) exten => _1X.,n,Dial(Zap/g1/${EXTEN:1}) Immediately after sending the SETUP message, Asterisk responds with 183 Session Progress. Thus, the SIP client is waiting for inband audio, but there is no inband audio available. progressinband=never sip.conf: [klaus] type=peer username=klaus host=dynamic context=fromklaus canreinvite=no progressinband=never actually I tried all progressinband settings without any difference ****** ADDITIONAL INFORMATION ****** <--- SIP read from 83.136.33.3:15742 ---> INVITE sip:111@1.2.3.4 SIP/2.0 Via: SIP/2.0/UDP 10.10.0.51:15742;branch=z9hG4bK-d8754z-a543af0d627b743b-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:klaus@83.136.33.3:15742;transport=udp> To: "111"<sip:111@1.2.3.4> From: <sip:klaus@1.2.3.4>;tag=004f0f23 Call-ID: Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Proxy-Authorization: Digest username="klaus",realm="asterisk",nonce="6598035c",uri="sip:111@1.2.3.4",response="ab5ae6ad222df665c442e6f0834e396a",algorithm=MD5 User-Agent: eyeBeam release 1100z stamp 47739 Content-Length: 407 v=0 o=- 5 2 IN IP4 83.136.33.3 s=CounterPath eyeBeam 1.5 c=IN IP4 83.136.33.3 t=0 0 m=audio 31516 RTP/AVP 0 8 101 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv a=x-rtp-session-id:D881D09BB8F04FC2BF2AA269299957E7 m=video 38172 RTP/AVP 115 a=fmtp:115 QCIF=1 CIF=1 I=1 J=1 T=1 MaxBR=4520 a=rtpmap:115 H263-1998/90000 a=sendrecv a=x-rtp-session-id:C35C1F2779D142558498EEDC14743D6D <-------------> [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 0: INVITE sip:111@1.2.3.4 SIP/2.0 (36) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.0.51:15742;branch=z9hG4bK-d8754z-a543af0d627b743b-1---d8754z-;rport (90) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 2: Max-Forwards: 70 (16) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 3: Contact: <sip:klaus@83.136.33.3:15742;transport=udp> (52) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 4: To: "111"<sip:111@1.2.3.4> (32) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 5: From: <sip:klaus@1.2.3.4>;tag=004f0f23 (44) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 6: Call-ID: Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. (53) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 7: CSeq: 2 INVITE (14) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 9: Content-Type: application/sdp (29) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 10: Proxy-Authorization: Digest username="klaus",realm="asterisk",nonce="6598035c",uri="sip:111@1.2.3.4",response="ab5ae6ad222df665c442e6f0834e396a",algorithm=MD5 (164) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 11: User-Agent: eyeBeam release 1100z stamp 47739 (45) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 12: Content-Length: 407 (19) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4832 parse_request: Header 13: (0) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: v=0 (3) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: o=- 5 2 IN IP4 83.136.33.3 (26) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: s=CounterPath eyeBeam 1.5 (25) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: c=IN IP4 83.136.33.3 (20) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: t=0 0 (5) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: m=audio 31516 RTP/AVP 0 8 101 (29) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=fmtp:101 0-15 (15) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=sendrecv (10) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=x-rtp-session-id:D881D09BB8F04FC2BF2AA269299957E7 (51) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: m=video 38172 RTP/AVP 115 (25) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=fmtp:115 QCIF=1 CIF=1 I=1 J=1 T=1 MaxBR=4520 (46) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=rtpmap:115 H263-1998/90000 (28) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=sendrecv (10) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4864 parse_request: Line: a=x-rtp-session-id:C35C1F2779D142558498EEDC14743D6D (51) --- (13 headers 15 lines) --- [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4620 find_call: = Found Their Call ID: Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. Their Tag 004f0f23 Our tag: as6bf4e0f9 [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:15348 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 83.136.33.3 : 15742 (NAT) Using INVITE request as basis request - Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. Found peer 'klaus' [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:2756 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 101 Found RTP video format 115 Peer audio RTP is at port 83.136.33.3:31516 Got unsupported a:fmtp in SDP offer Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer Found unknown media description format H263-1998 for ID 115 [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:5476 process_sdp: T38 state changed to 0 on channel <none> Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 83.136.33.3:31516 [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:5556 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:14017 handle_request_invite: Checking SIP call limits for device klaus [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:3210 update_call_counter: Updating call counter for incoming call Looking for 111 in fromklaus (domain 1.2.3.4) [Jul 9 15:58:16] DEBUG[17864]: frame.c:1298 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4044 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4045 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4046 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jul 9 15:58:16] DEBUG[17864]: frame.c:1298 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4047 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:4070 sip_new: This channel will not be able to handle video. [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:8373 build_route: build_route: Contact hop: <sip:klaus@83.136.33.3:15742;transport=udp> list_route: hop: <sip:klaus@83.136.33.3:15742;transport=udp> [Jul 9 15:58:16] DEBUG[17864]: chan_sip.c:14096 handle_request_invite: SIP/klaus-08d7b9d0: New call is still down.... Trying... <--- Transmitting (no NAT) to 83.136.33.3:15742 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 83.136.33.3:15742;branch=z9hG4bK-d8754z-a543af0d627b743b-1---d8754z-;received=83.136.33.3;rport=15742 From: <sip:klaus@1.2.3.4>;tag=004f0f23 To: "111"<sip:111@1.2.3.4> Call-ID: Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: <sip:111@1.2.3.4> Content-Length: 0 <------------> [Jul 9 15:58:16] DEBUG[17864]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/klaus-08d7b9d0 [Jul 9 15:58:16] DEBUG[17864]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/klaus [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - klaus-08d7b9d0 [Jul 9 15:58:16] DEBUG[17861]: chan_sip.c:16011 sip_devicestate: Checking device state for peer klaus-08d7b9d0 [Jul 9 15:58:16] DEBUG[17889]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [111@fromklaus:1] NoOp("SIP/klaus-08d7b9d0", "1... SIP: Outgoing Call: Asterisk->HiCom") in new stack [Jul 9 15:58:16] DEBUG[17889]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [111@fromklaus:2] Dial("SIP/klaus-08d7b9d0", "Zap/g1/11") in new stack [Jul 9 15:58:16] DEBUG[17889]: chan_zap.c:7902 zt_request: Using channel 1 [Jul 9 15:58:16] DEBUG[17889]: rtp.c:1584 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Jul 9 15:58:16] DEBUG[17889]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jul 9 15:58:16] DEBUG[17889]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jul 9 15:58:16] DEBUG[17889]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jul 9 15:58:16] DEBUG[17889]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPURI. -- Making new call for cr 32770 -- Requested transfer capability: 0x00 - SPEECH > Protocol Discriminator: Q.931 (8) len=29 > Call Ref: len= 2 (reference 2/0x2) (Originator) > Message type: SETUP (5) > [04 03 80 90 a3] > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:287 do_state_change: Changing state for SIP/klaus-08d7b9d0 - state 4 (Invalid) > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - klaus > User information layer 1: A-Law (35) > [18 03 a9 83 81] [Jul 9 15:58:16] DEBUG[17861]: chan_sip.c:16011 sip_devicestate: Checking device state for peer klaus > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 > ChanSel: Reserved [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:287 do_state_change: Changing state for SIP/klaus - state 1 (Not in use) > Ext: 1 Coding: 0 Number Specified Channel Type: 3 > Ext: 1 Channel: 1 ] > [6c 07 00 81 6b 6c 61 75 73] [Jul 9 15:58:16] DEBUG[17866]: app_queue.c:659 handle_statechange: Device 'SIP/klaus-08d7b9d0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. > Calling Number (len= 9) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) > Presentation: Presentation permitted, user number passed network screening (1) 'klaus' ] > [70 03 80 31 31] > Called Number (len= 5) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '11' ] q931.c:3087 q931_setup: call 32770 on channel 1 enters state 1 (Call Initiated) [Jul 9 15:58:16] DEBUG[17866]: app_queue.c:659 handle_statechange: Device 'SIP/klaus' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 9 15:58:16] DEBUG[17889]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1 [Jul 9 15:58:16] DEBUG[17889]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1 -- Called g1/11 [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown) [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Jul 9 15:58:16] DEBUG[17866]: app_queue.c:659 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jul 9 15:58:16] DEBUG[17861]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Jul 9 15:58:16] DEBUG[17889]: channel.c:2808 set_format: Set channel Zap/1-1 to read format ulaw [Jul 9 15:58:16] DEBUG[17889]: channel.c:2808 set_format: Set channel SIP/klaus-08d7b9d0 to read format alaw [Jul 9 15:58:16] DEBUG[17866]: app_queue.c:659 handle_statechange: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Accepting overlap call from 'klaus' to '11' on channel 0/1, span 2 -- Starting simple switch on 'Zap/32-1' < Protocol Discriminator: Q.931 (8) len=14 < Call Ref: len= 2 (reference 2/0x2) (Terminator) < Message type: SETUP ACKNOWLEDGE (13) < [18 03 a9 83 81] < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 < ChanSel: Reserved < Ext: 1 Coding: 0 Number Specified Channel Type: 3 < Ext: 1 Channel: 1 ] < [1e 02 81 82] < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) < Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ] -- Processing IE 24 (cs0, Channel Identification) -- Processing IE 30 (cs0, Progress Indicator) q931.c:3844 q931_receive: call 32770 on channel 1 enters state 2 (Overlap sending) [Jul 9 15:58:16] DEBUG[17889]: chan_sip.c:6758 transmit_response_with_sdp: Setting framing from config on incoming call [Jul 9 15:58:16] DEBUG[17889]: chan_sip.c:6522 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jul 9 15:58:16] DEBUG[17889]: chan_sip.c:6523 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 1.2.3.4 port 14252 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 9 15:58:16] DEBUG[17889]: chan_sip.c:6654 add_sdp: -- Done with adding codecs to SDP [Jul 9 15:58:16] DEBUG[17889]: channel.c:2342 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=85) [Jul 9 15:58:16] DEBUG[17889]: chan_sip.c:6699 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) <--- Transmitting (no NAT) to 83.136.33.3:15742 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 83.136.33.3:15742;branch=z9hG4bK-d8754z-a543af0d627b743b-1---d8754z-;received=83.136.33.3;rport=15742 From: <sip:klaus@1.2.3.4>;tag=004f0f23 To: "111"<sip:111@1.2.3.4>;tag=as6cbf2a8c Call-ID: Y2EyOTdiNWU5YmEyMTAxM2ZmYWU3NDQ4NDczMTI4NGM. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: <sip:111@1.2.3.4> Content-Type: application/sdp Content-Length: 266 v=0 o=root 17858 17858 IN IP4 1.2.3.4 s=session c=IN IP4 1.2.3.4 t=0 0 m=audio 14252 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 - - - - a=ptime:20 a=sendrecv <------------> | ||||
| Comments: | By: Olle Johansson (oej) 2008-07-09 15:09:31 I remember seeing this bug report before. When we start receiving frames before an answer, we send 183. There's something going on. Anyone that remembers? By: Olle Johansson (oej) 2008-07-09 15:11:49 q931.c:3844 q931_receive: call 32770 on channel 1 enters state 2 (Overlap sending) This occurs before we decide that we have media from the ISDN that we want to send to the SIP phone. Is there an AST_FRAME that triggers this? By: klaus3000 (klaus3000) 2008-07-09 17:53:26 Hi Olle! I do not know how to debug this. I only that this (or similar) happens often (I also had this issue with IAX-->ISDN) and the result is the missing ringback tone on the VoIP side. By: Olle Johansson (oej) 2008-07-10 03:58:39 Neither do I, as this seems to be an issue on the ISDN side. I would suggest that you turn on "rtp debug" just to check if there's any media frames being sent. By: Russell Bryant (russell) 2008-10-05 18:46:49 chan_sip will send the 183 when it gets a VOICE, VIDEO, or TEXT frame. My first thought was that we should be respecting the progressinband option here. However, I think the bigger question is, why is no media actually getting to the endpoint? By: klaus3000 (klaus3000) 2008-10-30 11:38:18 > However, I think the bigger question is, why is no media actually getting to the endpoint? I think this one is easy - there is no media. As you see in the Q.931 response messages there is no indication that there will be inband audio - which means: there is no inband audio. Thus, why is 183 sent? MAybe because core receive a frame from chan_zap. Thus, why does chan_zap send a frame to core when there is no inband audio? By: Leif Madsen (lmadsen) 2009-02-02 14:48:12.000-0600 I'm acknowledging this issue, although I'm not sure who I can assign it to :) By: Olle Johansson (oej) 2009-02-03 01:39:36.000-0600 I've seen this in customer installations too. I would suggest file or russellb, since they know the audio systems inside the core, which is required to solve this issue. Sorry, but I have no direct access to the systems for debugging. They have Digium PRI cards connected to legacy PBX systems. By: Olle Johansson (oej) 2009-02-03 14:51:18.000-0600 I have a full debug from a system where this happens. I see audio being sent to the SIP device after the 183, but before the PRI sets the channel to ALERTING. At alerting the SIP channel sends an 180 Ringing, which is correct. Unfortunately there's no debug in SIP_WRITE() so I don't see the types of frames that arrives, I only see ALAW audio frames being sent in RTP debug, which leads me to the conclusion that for some reason there's audio coming in on the PRI side (with an old legacy PBX connected). The audio comes after PRI debug says that call enters state 1 (call initiated). The next PRI even seems to be CALL PROCEEDING, but at that time, we've already sent a lot of RTP packets. I am not allowed to apply and changes to this system and can't release the log file for public access, as this is a production system. By: klaus3000 (klaus3000) 2009-02-03 15:03:07.000-0600 > which leads me to the conclusion that for some reason there's audio coming in on the PRI side isn't this always the case? The B channel does not tell you if there is data on the channel or not. You just read 8bits, 8000 times per seconds. In this case, were Asterisk starts reading but the switch does not send audio data on the B channel, it is probably 000000.... I have a test system available if you want to to test patches By: Olle Johansson (oej) 2009-02-04 05:40:15.000-0600 klaus: Contact me over SIP, IM or any other means so I can get access. Thanks! By: Joshua C. Colp (jcolp) 2009-02-10 09:02:53.000-0600 The PRI traffic though would tell you that inband audio progress is available. In that case I believe chan_dahdi queues up a progress frame to be sent to the other side. Whether there is actually audio though despite what the other side says... well, apparently there isn't. Quite interesting. oej: Were you able to get access and poke about? By: Alex Hermann (alexh) 2009-02-16 05:36:34.000-0600 I noticed the same issue on SS7 and SIP channels. After the Dial(), Asterisk sends out a "100 Trying" followed by a "183 Progress" even though no progress has been received from the SS7 or callee-SIP side. By: Leif Madsen (lmadsen) 2009-02-19 09:19:26.000-0600 oej: did you happen to ever get with klaus? By: Olle Johansson (oej) 2009-02-19 09:35:16.000-0600 No, he was unavailble for a long time. Maybe he's back next week. I also failed to get access to a system for real testing and debugging. Will try again. By: Leif Madsen (lmadsen) 2009-02-19 09:49:04.000-0600 Thanks for the update oej. I guess we'll wait for the original reporter to get back to us. By: klaus3000 (klaus3000) 2009-02-19 12:09:32.000-0600 I am still busy this week - but next week I should have time to debug this. By: Olle Johansson (oej) 2009-02-19 12:16:53.000-0600 Great. I put some pressure I might get some access during off-hours soon. By: Olle Johansson (oej) 2009-02-20 02:35:32.000-0600 After a lot of discussion, I've decided to create a branch called "no-premature-183" with an option to disable this behaviour in chan_sip. We won't send any frames until we actually have proceeding or alerting from the other end. I don't know why chan_sip does that, but doesn't like breaking it. This could also be an option in zaptel/dahdi so that no frames are sent INTO your pbx, but that's for someone else to patch and it would propably be a better solution. My world is chan_sip :-) We still want to figure out WHY this happens, what kind of frames equipment send. See http://lists.digium.com/pipermail/asterisk-commits/2009-February/031041.html By: Olle Johansson (oej) 2009-02-20 02:51:34.000-0600 If what Klaus says earlier is correct, we should propably have a filter that removes empty inbound frames before call progress or alerting. By: Olle Johansson (oej) 2009-02-20 03:06:41.000-0600 Uploaded a patch for testing. Not tested here, since I haven't got that kind of system in-house. This is the patch that hides in the branch. By: klaus3000 (klaus3000) 2009-02-20 06:09:50.000-0600 Just a note: Actually the B-channel on ISDN is not opened just by receiving a ALERTING or PROGRESS message, but only if these messages have the flag "inband information available" By: klaus3000 (klaus3000) 2009-02-23 04:35:39.000-0600 Hi! I made 2 traces to analyze the current bahavior (1.4.23). I added some debug messages in app_dial (wait for answer, staring with "Klaus") to see what control frames are received from the outgoing channel. The intersting thing is: The 183 from the SIP channel is sent immediately without receiving any control frame from the outgoing channel. This looks like a bug in chan_sip. Further I try to understand what triggers early media inside of Asterisk - is it AST_CONTROL_PROGRESS? If yes, then the ALERTING with Progress Indicator "inband available" should generate AST_CONTROL_PROGRESS too (see trace 1). 1st trace: > SETUP < CALL PROCEEDING w/o PI < ALERTING w/ PI 2nd trace: > SETUP < CALL PROCEEDING w PI < ALERTING w/o PI 3rd trace: > SETUP < ALERTING w/o PI By: Olle Johansson (oej) 2009-02-23 04:41:55.000-0600 chan_sip (for some to me unknown reason) sends 183 as soon as we receive any frame - not just a control frame. My patch changes that behaviour. AST_CONTROL_PROGRESS is sent AFTER we've sent 183. There are frames that are sent on RTP *BEFORE* ISDN side forces AST_CONTROL_PROGRESS. Try to capture those frames, please! By: klaus3000 (klaus3000) 2009-02-23 05:36:09.000-0600 Hi Olle! I have uploaded the pcap file. This is a call to a mobile number (see trace 2). The inband information is available ~9 seconds (human time measurement) after INVITE. By: Olle Johansson (oej) 2009-02-23 05:43:50.000-0600 Did the patch do any good? By: klaus3000 (klaus3000) 2009-02-23 06:56:07.000-0600 Hi Olle! it is not possible to understand if prematuremedia=yes activates or deactivates the 183. You use prematuremedia global_prematuremediafilter " No premature media:" YES/NO Either call it prematuremedia (yes means current behavior, no means fixed behavior) or call it prematuremediafilter (no mean current behavior, yes means fixed behavior) By: klaus3000 (klaus3000) 2009-02-23 06:57:10.000-0600 the logic in the sip.conf option and the naming of the variables should be consistent (avoid double negotiations like "no premature media: no") By: klaus3000 (klaus3000) 2009-02-23 07:03:21.000-0600 Using your patch the 183 is supressed, but I get another 100 trying after CALL PROCEEDING (additional to the one just sent after the INVITE is received) < Protocol Discriminator: Q.931 (8) len=5 < Call Ref: len= 2 (reference 3/0x3) (Terminator) < Message type: CALL PROCEEDING (2) q931.c:3641 q931_receive: call 32771 on channel 1 enters state 3 (Outgoing call Proceeding) Klaus: received AST_CONTROL_PROCEEDING on channel DAHDI/1-1 -- DAHDI/1-1 is proceeding passing it to SIP/klaus-08863120 <--- Transmitting (NAT) to 83.136.33.3:46922 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.0.51:46922;branch=z9hG4bK-d8754z-b14d2667ea26c136-1---d8754z-;received=83.136.33.3;rport=46922 From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=31219905 To: "01505641636"<sip:01505641636@83.136.32.165> Call-ID: MjUzMTljOTA5ZTAxYzVlZjcyMDNkNzE3ZGZjNTY5NmQ. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: <sip:01505641636@83.136.32.165> Content-Length: 0 By: Olle Johansson (oej) 2009-02-23 07:48:41.000-0600 It's just a raw patch... Not a proposal of any kind yet. Did the call go through as you wanted without any affects on the call? By: klaus3000 (klaus3000) 2009-02-23 08:09:35.000-0600 > Did the call go through as you wanted without any affects on the call? As far I can see: yes Although your patch solves the issue (the doubled 100 trying should be removed) IMO it is strange that usually a 183 is sent but nobody knows why this piece of code is there at all. By: Joshua C. Colp (jcolp) 2009-02-23 08:12:19.000-0600 I suspect it is so that every application/place that has a noanswer option doesn't have to indicate progress (and I'm pretty sure they don't). They can just throw audio frames at chan_sip and it will take care of sending progress on its own. By: Olle Johansson (oej) 2009-02-23 08:17:02.000-0600 Oh, so my patch will break the noanwer option to some apps. Bad. I thought there was a reason somewhere. Thanks file! We need to find out how these frames ARRIVE on the ISDN side then. By: klaus3000 (klaus3000) 2009-02-23 09:01:52.000-0600 On the ISDN side there is no "frame" which arrives. There is a B channel where you get 8bit every 125us. The D-channel tells you when you should start reading from the B channel. Thus, on the ISDN side, only signalling may start eary media. By: Olle Johansson (oej) 2009-02-23 09:07:24.000-0600 Let me rephrase: Chan_zap or chan_dahdi is sending frames to the bridge before we get any signalling that starts early media on the D channel, which is causing this behaviour. What is the content of these frames? Just zeros as you guessed earlier or something else? By: Olle Johansson (oej) 2009-02-23 09:09:32.000-0600 Maybe it's time to move this bug away from chan_sip ??? :-) By: klaus3000 (klaus3000) 2009-02-23 09:18:15.000-0600 Oh yes. app_dial receives AST_FRAME_VOICE from the DAHDI channel. Thus, it appears that chan_sip is unguilty - chan_dadhi is buggy By: klaus3000 (klaus3000) 2009-02-23 09:41:17.000-0600 looking at dahdi_read() in chan_dahdi it looks like as the reading from the pri channel is performed always - without checking if the B channel is in "early" or "connected" state. By: klaus3000 (klaus3000) 2009-02-23 09:41:35.000-0600 we should this handover to the DAHDI guys By: Olle Johansson (oej) 2009-02-23 09:43:39.000-0600 Absolutely, since we SIP guys have found that they have a problem! By: klaus3000 (klaus3000) 2009-03-12 10:49:26 Are there any DAHDI guys which can help us fixing this? By: Tilghman Lesher (tilghman) 2009-03-16 16:45:58 I wonder if this patch might prevent any frames from being sent until the PRI is truly in a proceeding state. Caveat emptor: this code is not tested. By: klaus3000 (klaus3000) 2009-03-17 06:05:50 The patch from Olle tried to fix it in chan_sip. But as we discovered this breaks early media from applications. Thus the patch does not help. The problem is in chan_dahdi and needs to be fixed there. By: Olle Johansson (oej) 2009-03-17 06:15:18 ...but tilghman's patch is in chan_dahdi, Klaus? By: klaus3000 (klaus3000) 2009-03-18 08:45:47 I tested 20090316__bug13034.diff.txt. Some things are better, some are worse: 1st test: SIP->Asterisk->PSTN number starts ringing Problem: The received ALERTING contains "inband information available", thus early media should be established, thus, both 180 and 183 should be sent. <--- SIP read from UDP:11.222.33.3:39768 ---> INVITE sip:01505641636@11.222.32.165 SIP/2.0 Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-c6208f1845013a5f-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:fooba@11.222.33.3:39768;transport=udp> To: "01505641636"<sip:01505641636@11.222.32.165> From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=09187459 Call-ID: NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: eyeBeam release 1102q stamp 51814 Authorization: Digest username="fooba",realm="asterisk",nonce="2e53d80a",uri="sip:01505641636@11.222.32.165",response="fcd911cd133e25f",algorithm=MD5 Content-Length: 231 v=0 o=- 6 2 IN IP4 11.222.33.3 s=CounterPath eyeBeam 1.5 c=IN IP4 11.222.33.3 t=0 0 m=audio 5706 RTP/AVP 0 8 18 101 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 0 [ 44]: INVITE sip:01505641636@11.222.32.165 SIP/2.0 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-c6208f1845013a5f-1---d8754z-;rport [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 3 [ 52]: Contact: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 4 [ 48]: To: "01505641636"<sip:01505641636@11.222.32.165> [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 5 [ 58]: From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=09187459 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 6 [ 53]: Call-ID: NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 7 [ 14]: CSeq: 2 INVITE [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 10 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 11 [166]: Authorization: Digest username="fooba",realm="asterisk",nonce="2e53d80a",uri="sip:01505641636@11.222.32.165",response="fd5b443800b041cd133e25f",algorithm=MD5 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 12 [ 19]: Content-Length: 231 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Header 13 [ 0]: [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 0 [ 3]: v=0 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 1 [ 26]: o=- 6 2 IN IP4 11.222.33.3 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 2 [ 25]: s=CounterPath eyeBeam 1.5 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 3 [ 20]: c=IN IP4 11.222.33.3 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 4 [ 5]: t=0 0 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 5 [ 31]: m=audio 5706 RTP/AVP 0 8 18 101 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 6 [ 20]: a=fmtp:18 annexb=yes [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 7 [ 15]: a=fmtp:101 0-15 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Body 10 [ 10]: a=sendrecv [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: --- (13 headers 11 lines) --- [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Sending to 11.222.33.3 : 39768 (NAT) [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Initializing initreq for method INVITE - callid NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Using INVITE request as basis request - NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found peer 'fooba' for 'fooba' from 11.222.33.3:39768 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Setting NAT on RTP to On [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Setting NAT on VRTP to On [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Setting NAT on UDPTL to On [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found RTP audio format 0 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found RTP audio format 8 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found RTP audio format 18 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found RTP audio format 101 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Peer doesn't provide T.38 UDPTL [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Peer audio RTP is at port 11.222.33.3:5706 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Got unsupported a:fmtp:18 annexb=yes in SDP offer [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Got unsupported a:fmtp:101 0-15 in SDP offer [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found audio description format G729 for ID 18 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Found audio description format telephone-event for ID 101 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Capabilities: us - 0xc7ffffe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729) [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Peer audio RTP is at port 11.222.33.3:5706 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: We're settling with these formats: 0x10c (ulaw|alaw|g729) [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Checking SIP call limits for device fooba [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Updating call counter for incoming call [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Call from peer 'fooba' is 1 out of 5 [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: Looking for 01505641636 in direct (domain 11.222.32.165) [Mar 18 14:43:51] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for SIP - fooba [Mar 18 14:43:51] DEBUG[8835] chan_sip.c: Checking device state for peer fooba [Mar 18 14:43:51] DEBUG[8835] devicestate.c: Changing state for SIP/fooba - state 2 (In use) [Mar 18 14:43:51] DEBUG[8835] devicestate.c: device 'SIP/fooba' state '2' [Mar 18 14:43:51] DEBUG[8856] frame.c: Could not find preferred codec - Going for the best codec [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: *** Joint capabilities are 0x10c (ulaw|alaw|g729) [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Processing device state change for 'SIP/fooba' [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: *** Our capabilities are 0xc7ffffe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14) [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'SIP/fooba' [Mar 18 14:43:51] DEBUG[8856] frame.c: Could not find preferred codec - Going for the best codec [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate state for device 'SIP/fooba' has changed to 'In use' [Mar 18 14:43:51] DEBUG[8863] app_queue.c: Device 'SIP/fooba' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: build_route: Contact hop: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: list_route: hop: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: SIP/fooba-09e2ce40: New call is still down.... Trying... [Mar 18 14:43:51] VERBOSE[8856] chan_sip.c: <--- Transmitting (NAT) to 11.222.33.3:39768 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-c6208f1845013a5f-1---d8754z-;received=11.222.33.3;rport=39768 From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=09187459 To: "01505641636"<sip:01505641636@11.222.32.165> Call-ID: NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r180641M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: <sip:01505641636@11.222.32.165> Content-Length: 0 <------------> [Mar 18 14:43:51] DEBUG[8856] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 11.222.33.3:39768 [Mar 18 14:43:51] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for SIP - fooba [Mar 18 14:43:51] DEBUG[8835] chan_sip.c: Checking device state for peer fooba [Mar 18 14:43:51] DEBUG[8835] devicestate.c: Changing state for SIP/fooba - state 2 (In use) [Mar 18 14:43:51] DEBUG[8835] devicestate.c: device 'SIP/fooba' state '2' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Processing device state change for 'SIP/fooba' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'SIP/fooba' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate state for device 'SIP/fooba' has not changed from 'In use' [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'NoOp' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:1] NoOp("SIP/fooba-09e2ce40", "HINT=") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Function result is '0' [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'NoOp' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:2] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=0") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'Set' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:3] Set("SIP/fooba-09e2ce40", "GROUP()=TRUNK") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Function result is '1' [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'NoOp' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:4] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=1") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'Set' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:5] Set("SIP/fooba-09e2ce40", "GROUP()=TRUNK") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Function result is '1' [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'NoOp' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:6] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=1") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'NoOp' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:7] NoOp("SIP/fooba-09e2ce40", "BILLINGID=12345") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'Set' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:8] Set("SIP/fooba-09e2ce40", "__TRANSFER_CONTEXT=transferContext") in new stack [Mar 18 14:43:51] DEBUG[9052] pbx.c: Launching 'Dial' [Mar 18 14:43:51] VERBOSE[9052] pbx.c: -- Executing [01505641636@direct:9] Dial("SIP/fooba-09e2ce40", "Dahdi/g2/01505641636") in new stack [Mar 18 14:43:51] DEBUG[9052] chan_dahdi.c: Using channel 1 [Mar 18 14:43:51] DEBUG[9052] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 18 14:43:51] DEBUG[9052] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Mar 18 14:43:51] DEBUG[9052] devicestate.c: device 'DAHDI/1-1' state '2' [Mar 18 14:43:51] DEBUG[9052] rtp.c: Channel 'DAHDI/1-1' has no RTP, not doing anything [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable DIALEDTIME. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable ANSWEREDTIME. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable DIALEDPEERNAME. [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Processing device state change for 'DAHDI/1-1' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'DAHDI/1-1' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate state for device 'DAHDI/1-1' has not changed from 'In use' [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable DIALSTATUS. [Mar 18 14:43:51] DEBUG[9052] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable BILLINGID. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable NOTRUFCLI. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable SIPCALLID. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable SIPDOMAIN. [Mar 18 14:43:51] DEBUG[9052] channel.c: Not copying variable SIPURI. [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: -- Making new call for cr 32781 [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: -- Requested transfer capability: 0x00 - SPEECH [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Protocol Discriminator: Q.931 (8) len=44 [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Call Ref: len= 2 (reference 13/0xD) (Originator) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Message type: SETUP (5) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > [04 03 80 90 a3] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > User information layer 1: A-Law (35) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > [18 03 a9 83 81] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > ChanSel: As indicated in following octets [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Ext: 1 Channel: 1 ] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > [6c 0d 21 80 36 39 39 31 31 31 36 30 30 33 36] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Calling Number (len=15) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Presentation: Presentation permitted, user number not screened (0) '69911160036' ] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > [70 0c 80 30 31 35 30 35 36 34 31 36 33 36] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: > Called Number (len=14) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '01505641636' ] [Mar 18 14:43:51] VERBOSE[9052] chan_dahdi.c: q931.c:3092 q931_setup: call 32781 on channel 1 enters state 1 (Call Initiated) [Mar 18 14:43:51] VERBOSE[9052] app_dial.c: -- Called g2/01505641636 [Mar 18 14:43:51] DEBUG[9052] channel.c: Set channel DAHDI/1-1 to read format ulaw [Mar 18 14:43:51] DEBUG[9052] channel.c: Set channel SIP/fooba-09e2ce40 to read format alaw [Mar 18 14:43:51] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for DAHDI - 1 [Mar 18 14:43:51] DEBUG[8835] devicestate.c: Changing state for DAHDI/1 - state 2 (In use) [Mar 18 14:43:51] DEBUG[8835] devicestate.c: device 'DAHDI/1' state '2' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Processing device state change for 'DAHDI/1' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'DAHDI/1' [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:43:51] DEBUG[8834] devicestate.c: Aggregate state for device 'DAHDI/1' has changed to 'In use' [Mar 18 14:43:51] DEBUG[8863] app_queue.c: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=10 [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 13/0xD) (Terminator) [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Message type: SETUP ACKNOWLEDGE (13) [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < [18 03 a9 83 81] [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < ChanSel: As indicated in following octets [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Channel: 1 ] [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: -- Processing IE 24 (cs0, Channel Identification) [Mar 18 14:43:51] VERBOSE[8840] chan_dahdi.c: q931.c:3849 q931_receive: call 32781 on channel 1 enters state 2 (Overlap sending) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=5 [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 13/0xD) (Terminator) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Message type: CALL PROCEEDING (2) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: q931.c:3641 q931_receive: call 32781 on channel 1 enters state 3 (Outgoing call Proceeding) [Mar 18 14:43:52] DEBUG[8840] chan_dahdi.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 [Mar 18 14:43:52] VERBOSE[9052] app_dial.c: -- DAHDI/1-1 is proceeding passing it to SIP/fooba-09e2ce40 [Mar 18 14:43:52] VERBOSE[9052] chan_sip.c: <--- Transmitting (NAT) to 11.222.33.3:39768 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-c6208f1845013a5f-1---d8754z-;received=11.222.33.3;rport=39768 From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=09187459 To: "01505641636"<sip:01505641636@11.222.32.165> Call-ID: NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r180641M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: <sip:01505641636@11.222.32.165> Content-Length: 0 <------------> [Mar 18 14:43:52] DEBUG[9052] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 11.222.33.3:39768 [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=9 [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 13/0xD) (Terminator) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Message type: ALERTING (1) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < [1e 02 84 88] [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the remote user (4) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: -- Processing IE 30 (cs0, Progress Indicator) [Mar 18 14:43:52] VERBOSE[8840] chan_dahdi.c: q931.c:3554 q931_receive: call 32781 on channel 1 enters state 4 (Call Delivered) [Mar 18 14:43:52] DEBUG[8840] chan_dahdi.c: No echo cancellation requested [Mar 18 14:43:52] VERBOSE[9052] app_dial.c: -- DAHDI/1-1 is ringing [Mar 18 14:43:52] VERBOSE[9052] chan_sip.c: <--- Transmitting (NAT) to 11.222.33.3:39768 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-c6208f1845013a5f-1---d8754z-;received=11.222.33.3;rport=39768 From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=09187459 To: "01505641636"<sip:01505641636@11.222.32.165>;tag=as0caf9042 Call-ID: NWFjMGVjZWYyMWEwYmMyOTI4MmU1ZGRkOTExNTRjYzM. CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r180641M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: <sip:01505641636@11.222.32.165> Content-Length: 0 <------------> [Mar 18 14:43:52] DEBUG[9052] chan_sip.c: Trying to put 'SIP/2.0 18' onto UDP socket destined for 11.222.33.3:39768 [Mar 18 14:43:52] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for DAHDI - 1 [Mar 18 14:43:52] DEBUG[8835] devicestate.c: Changing state for DAHDI/1 - state 6 (Ringing) [Mar 18 14:43:52] DEBUG[8835] devicestate.c: device 'DAHDI/1' state '6' [Mar 18 14:43:52] DEBUG[8834] devicestate.c: Processing device state change for 'DAHDI/1' [Mar 18 14:43:52] DEBUG[8834] devicestate.c: Adding per-server state of 'Ringing' for 'DAHDI/1' [Mar 18 14:43:52] DEBUG[8834] devicestate.c: Aggregate devstate result is 6 [Mar 18 14:43:52] DEBUG[8834] devicestate.c: Aggregate state for device 'DAHDI/1' has changed to 'Ringing' [Mar 18 14:43:52] DEBUG[8863] app_queue.c: Device 'DAHDI/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. 2nd test: SIP->Asterisk->GSM phone which is offline - thus the mobile operator sends early media "the user is currently not available". Problem: Asterisk sends 183, but does not send RTP packets to the SIP client <--- SIP read from UDP:11.222.33.3:39768 ---> INVITE sip:069911160036@11.222.32.165 SIP/2.0 Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-2009612eaa1b1d37-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:fooba@11.222.33.3:39768;transport=udp> To: "fooba"<sip:069911160036@11.222.32.165> From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=b166b067 Call-ID: YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: eyeBeam release 1102q stamp 51814 Authorization: Digest username="fooba",realm="asterisk",nonce="21f257c2",uri="sip:069911160036@11.222.32.165",response="2f1fbf02ed04d0cfd1e2bf18ac89bb1d",algorithm=MD5 Content-Length: 232 v=0 o=- 4 2 IN IP4 11.222.33.3 s=CounterPath eyeBeam 1.5 c=IN IP4 11.222.33.3 t=0 0 m=audio 10792 RTP/AVP 0 8 18 101 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 0 [ 45]: INVITE sip:069911160036@11.222.32.165 SIP/2.0 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-2009612eaa1b1d37-1---d8754z-;rport [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 3 [ 52]: Contact: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 4 [ 43]: To: "fooba"<sip:069911160036@11.222.32.165> [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 5 [ 58]: From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=b166b067 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 6 [ 53]: Call-ID: YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 7 [ 14]: CSeq: 2 INVITE [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 10 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 11 [167]: Authorization: Digest username="fooba",realm="asterisk",nonce="21f257c2",uri="sip:069911160036@11.222.32.165",response="2f1fbf02ed04d0cfd1e2bf18ac89bb1d",algorithm=MD5 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 12 [ 19]: Content-Length: 232 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Header 13 [ 0]: [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 0 [ 3]: v=0 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 1 [ 26]: o=- 4 2 IN IP4 11.222.33.3 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 2 [ 25]: s=CounterPath eyeBeam 1.5 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 3 [ 20]: c=IN IP4 11.222.33.3 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 4 [ 5]: t=0 0 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 5 [ 32]: m=audio 10792 RTP/AVP 0 8 18 101 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 6 [ 20]: a=fmtp:18 annexb=yes [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 7 [ 15]: a=fmtp:101 0-15 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Body 10 [ 10]: a=sendrecv [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: --- (13 headers 11 lines) --- [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Sending to 11.222.33.3 : 39768 (NAT) [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Initializing initreq for method INVITE - callid YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Using INVITE request as basis request - YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found peer 'fooba' for 'fooba' from 11.222.33.3:39768 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Setting NAT on RTP to On [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Setting NAT on VRTP to On [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Setting NAT on UDPTL to On [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found RTP audio format 0 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found RTP audio format 8 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found RTP audio format 18 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found RTP audio format 101 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Peer doesn't provide T.38 UDPTL [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Peer audio RTP is at port 11.222.33.3:10792 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Got unsupported a:fmtp:18 annexb=yes in SDP offer [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Got unsupported a:fmtp:101 0-15 in SDP offer [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found audio description format G729 for ID 18 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Found audio description format telephone-event for ID 101 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Capabilities: us - 0xc7ffffe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729) [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Peer audio RTP is at port 11.222.33.3:10792 [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: We're settling with these formats: 0x10c (ulaw|alaw|g729) [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Checking SIP call limits for device fooba [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Updating call counter for incoming call [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Call from peer 'fooba' is 1 out of 5 [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: Looking for 069911160036 in direct (domain 11.222.32.165) [Mar 18 14:42:47] DEBUG[8856] frame.c: Could not find preferred codec - Going for the best codec [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: *** Joint capabilities are 0x10c (ulaw|alaw|g729) [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: *** Our capabilities are 0xc7ffffe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14) [Mar 18 14:42:47] DEBUG[8856] frame.c: Could not find preferred codec - Going for the best codec [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: build_route: Contact hop: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: list_route: hop: <sip:fooba@11.222.33.3:39768;transport=udp> [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: SIP/fooba-09e2ce40: New call is still down.... Trying... [Mar 18 14:42:47] VERBOSE[8856] chan_sip.c: <--- Transmitting (NAT) to 11.222.33.3:39768 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-2009612eaa1b1d37-1---d8754z-;received=11.222.33.3;rport=39768 From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=b166b067 To: "fooba"<sip:069911160036@11.222.32.165> Call-ID: YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r180641M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: <sip:069911160036@11.222.32.165> Content-Length: 0 <------------> [Mar 18 14:42:47] DEBUG[8856] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 11.222.33.3:39768 [Mar 18 14:42:47] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for SIP - fooba [Mar 18 14:42:47] DEBUG[8835] chan_sip.c: Checking device state for peer fooba [Mar 18 14:42:47] DEBUG[8835] devicestate.c: Changing state for SIP/fooba - state 2 (In use) [Mar 18 14:42:47] DEBUG[8835] devicestate.c: device 'SIP/fooba' state '2' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Processing device state change for 'SIP/fooba' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'SIP/fooba' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate state for device 'SIP/fooba' has changed to 'In use' [Mar 18 14:42:47] DEBUG[8863] app_queue.c: Device 'SIP/fooba' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 18 14:42:47] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for SIP - fooba [Mar 18 14:42:47] DEBUG[8835] chan_sip.c: Checking device state for peer fooba [Mar 18 14:42:47] DEBUG[8835] devicestate.c: Changing state for SIP/fooba - state 2 (In use) [Mar 18 14:42:47] DEBUG[8835] devicestate.c: device 'SIP/fooba' state '2' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Processing device state change for 'SIP/fooba' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'SIP/fooba' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate state for device 'SIP/fooba' has not changed from 'In use' [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'NoOp' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:1] NoOp("SIP/fooba-09e2ce40", "HINT=") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Function result is '0' [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'NoOp' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:2] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=0") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'Set' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:3] Set("SIP/fooba-09e2ce40", "GROUP()=TRUNK") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Function result is '1' [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'NoOp' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:4] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=1") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'Set' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:5] Set("SIP/fooba-09e2ce40", "GROUP()=TRUNK") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Function result is '1' [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'NoOp' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:6] NoOp("SIP/fooba-09e2ce40", "TRUNK_COUNT=1") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'NoOp' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:7] NoOp("SIP/fooba-09e2ce40", "BILLINGID=12345") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'Set' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:8] Set("SIP/fooba-09e2ce40", "__TRANSFER_CONTEXT=transferContext") in new stack [Mar 18 14:42:47] DEBUG[9044] pbx.c: Launching 'Dial' [Mar 18 14:42:47] VERBOSE[9044] pbx.c: -- Executing [069911160036@direct:9] Dial("SIP/fooba-09e2ce40", "Dahdi/g2/069911160036") in new stack [Mar 18 14:42:47] DEBUG[9044] chan_dahdi.c: Using channel 1 [Mar 18 14:42:47] DEBUG[9044] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 18 14:42:47] DEBUG[9044] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Mar 18 14:42:47] DEBUG[9044] devicestate.c: device 'DAHDI/1-1' state '2' [Mar 18 14:42:47] DEBUG[9044] rtp.c: Channel 'DAHDI/1-1' has no RTP, not doing anything [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable DIALEDTIME. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable ANSWEREDTIME. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable DIALEDPEERNAME. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable DIALSTATUS. [Mar 18 14:42:47] DEBUG[9044] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable BILLINGID. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable NOTRUFCLI. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable SIPCALLID. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable SIPDOMAIN. [Mar 18 14:42:47] DEBUG[9044] channel.c: Not copying variable SIPURI. [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: -- Making new call for cr 32780 [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: -- Requested transfer capability: 0x00 - SPEECH [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Protocol Discriminator: Q.931 (8) len=45 [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Call Ref: len= 2 (reference 12/0xC) (Originator) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Message type: SETUP (5) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > [04 03 80 90 a3] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > User information layer 1: A-Law (35) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > [18 03 a9 83 81] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > ChanSel: As indicated in following octets [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Ext: 1 Channel: 1 ] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > [6c 0d 21 80 36 39 39 31 31 31 36 30 30 33 36] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Calling Number (len=15) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Presentation: Presentation permitted, user number not screened (0) '69911160036' ] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > [70 0d 80 30 36 39 39 31 31 31 36 30 30 33 36] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: > Called Number (len=15) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '069911160036' ] [Mar 18 14:42:47] VERBOSE[9044] chan_dahdi.c: q931.c:3092 q931_setup: call 32780 on channel 1 enters state 1 (Call Initiated) [Mar 18 14:42:47] VERBOSE[9044] app_dial.c: -- Called g2/069911160036 [Mar 18 14:42:47] DEBUG[9044] channel.c: Set channel DAHDI/1-1 to read format ulaw [Mar 18 14:42:47] DEBUG[9044] channel.c: Set channel SIP/fooba-09e2ce40 to read format alaw [Mar 18 14:42:47] DEBUG[8835] devicestate.c: No provider found, checking channel drivers for DAHDI - 1 [Mar 18 14:42:47] DEBUG[8835] devicestate.c: Changing state for DAHDI/1 - state 2 (In use) [Mar 18 14:42:47] DEBUG[8835] devicestate.c: device 'DAHDI/1' state '2' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Processing device state change for 'DAHDI/1-1' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'DAHDI/1-1' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate state for device 'DAHDI/1-1' has not changed from 'In use' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Processing device state change for 'DAHDI/1' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Adding per-server state of 'In use' for 'DAHDI/1' [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate devstate result is 2 [Mar 18 14:42:47] DEBUG[8834] devicestate.c: Aggregate state for device 'DAHDI/1' has changed to 'In use' [Mar 18 14:42:47] DEBUG[8863] app_queue.c: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=10 [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 12/0xC) (Terminator) [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Message type: SETUP ACKNOWLEDGE (13) [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < [18 03 a9 83 81] [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < ChanSel: As indicated in following octets [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Channel: 1 ] [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: -- Processing IE 24 (cs0, Channel Identification) [Mar 18 14:42:47] VERBOSE[8840] chan_dahdi.c: q931.c:3849 q931_receive: call 32780 on channel 1 enters state 2 (Overlap sending) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=17 [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 12/0xC) (Terminator) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Message type: PROGRESS (3) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < [08 02 8a 9f] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Network beyond the interworking point (10) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Cause: Normal, unspecified (31), class = Normal Event (1) ] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < [1e 02 82 88] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < [1e 02 82 82] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ] [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: -- Processing IE 8 (cs0, Cause) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: -- Processing IE 30 (cs0, Progress Indicator) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: -- Processing IE 30 (cs0, Progress Indicator) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: -- PROGRESS with cause code 31 received [Mar 18 14:42:52] DEBUG[8840] chan_dahdi.c: Queuing frame from PRI_EVENT_PROGRESS on channel 0/1 span 1 [Mar 18 14:42:52] VERBOSE[9044] app_dial.c: -- DAHDI/1-1 is making progress passing it to SIP/fooba-09e2ce40 [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: Setting framing from config on incoming call [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True Text flag: True [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: Audio is at 11.222.32.165 port 11776 [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: Adding codec 0x100 (g729) to SDP [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: -- Done with adding codecs to SDP [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729) [Mar 18 14:42:52] VERBOSE[9044] chan_sip.c: <--- Transmitting (NAT) to 11.222.33.3:39768 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.10.0.51:39768;branch=z9hG4bK-d8754z-2009612eaa1b1d37-1---d8754z-;received=11.222.33.3;rport=39768 From: "fooba samuel"<sip:fooba@11.222.32.165>;tag=b166b067 To: "fooba"<sip:069911160036@11.222.32.165>;tag=as0b666c05 Call-ID: YjI0MjhmNWU5NGRhNjYyYTgxMTJmMGMwMDFlZTk1OTE. CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r180641M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: <sip:069911160036@11.222.32.165> Content-Type: application/sdp Content-Length: 345 v=0 o=root 641903893 641903893 IN IP4 11.222.32.165 s=Asterisk PBX SVN-trunk-r180641M c=IN IP4 11.222.32.165 t=0 0 m=audio 11776 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 18 14:42:52] DEBUG[9044] chan_sip.c: Trying to put 'SIP/2.0 18' onto UDP socket destined for 11.222.33.3:39768 [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=5 [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Call Ref: len= 2 (reference 12/0xC) (Terminator) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: < Message type: CALL PROCEEDING (2) [Mar 18 14:42:52] VERBOSE[8840] chan_dahdi.c: q931.c:3641 q931_receive: call 32780 on channel 1 enters state 3 (Outgoing call Proceeding) [Mar 18 14:42:52] DEBUG[8840] chan_dahdi.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 [Mar 18 14:42:52] VERBOSE[9044] app_dial.c: -- DAHDI/1-1 is proceeding passing it to SIP/fooba-09e2ce40 [Mar 18 14:42:52] DEBUG[9044] rtp.c: Got RTCP report of 132 bytes [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... [Mar 18 14:42:52] DEBUG[9044] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1... By: Olle Johansson (oej) 2009-03-18 08:54:33 Please, please add long debug messages as attachments. It's really hard to get an overview otherwise. This issue is shown using woomera channels as well, so I'm wondering if it's something general that needs to be fixed in the core, or if it's really up to each channel to handle. By: klaus3000 (klaus3000) 2009-03-18 10:03:18 Hi! I modified the patch and now it seems to work (in both cases which did not worked above). New patch attached: patch_trunk_183progress_klaus3000.txt By: Leif Madsen (lmadsen) 2009-03-18 10:32:19 Marking this as ready for review as the patch updated by klaus3000 solves the issue for him. By: Digium Subversion (svnbot) 2009-03-19 14:15:34 Repository: asterisk Revision: 183319 U branches/1.4/channels/chan_dahdi.c ------------------------------------------------------------------------ r183319 | tilghman | 2009-03-19 14:15:34 -0500 (Thu, 19 Mar 2009) | 8 lines Delay signalling progress until a PRI channel really signals progress. (closes issue ASTERISK-12346) Reported by: klaus3000 Patches: 20090316__bug13034.diff.txt uploaded by tilghman (license 14) patch_trunk_183progress_klaus3000.txt uploaded by klaus3000 (license 65) Tested by: klaus3000 ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=183319 By: Digium Subversion (svnbot) 2009-03-19 14:17:32 Repository: asterisk Revision: 183321 _U trunk/ U trunk/channels/chan_dahdi.c ------------------------------------------------------------------------ r183321 | tilghman | 2009-03-19 14:17:31 -0500 (Thu, 19 Mar 2009) | 15 lines Merged revisions 183319 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r183319 | tilghman | 2009-03-19 14:15:33 -0500 (Thu, 19 Mar 2009) | 8 lines Delay signalling progress until a PRI channel really signals progress. (closes issue ASTERISK-12346) Reported by: klaus3000 Patches: 20090316__bug13034.diff.txt uploaded by tilghman (license 14) patch_trunk_183progress_klaus3000.txt uploaded by klaus3000 (license 65) Tested by: klaus3000 ........ ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=183321 By: Digium Subversion (svnbot) 2009-03-19 14:18:36 Repository: asterisk Revision: 183327 _U branches/1.6.0/ U branches/1.6.0/channels/chan_dahdi.c ------------------------------------------------------------------------ r183327 | tilghman | 2009-03-19 14:18:36 -0500 (Thu, 19 Mar 2009) | 22 lines Merged revisions 183321 via svnmerge from https://origsvn.digium.com/svn/asterisk/trunk ................ r183321 | tilghman | 2009-03-19 14:17:31 -0500 (Thu, 19 Mar 2009) | 15 lines Merged revisions 183319 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r183319 | tilghman | 2009-03-19 14:15:33 -0500 (Thu, 19 Mar 2009) | 8 lines Delay signalling progress until a PRI channel really signals progress. (closes issue ASTERISK-12346) Reported by: klaus3000 Patches: 20090316__bug13034.diff.txt uploaded by tilghman (license 14) patch_trunk_183progress_klaus3000.txt uploaded by klaus3000 (license 65) Tested by: klaus3000 ........ ................ ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=183327 By: Digium Subversion (svnbot) 2009-03-19 14:19:29 Repository: asterisk Revision: 183333 _U branches/1.6.1/ U branches/1.6.1/channels/chan_dahdi.c ------------------------------------------------------------------------ r183333 | tilghman | 2009-03-19 14:19:29 -0500 (Thu, 19 Mar 2009) | 22 lines Merged revisions 183321 via svnmerge from https://origsvn.digium.com/svn/asterisk/trunk ................ r183321 | tilghman | 2009-03-19 14:17:31 -0500 (Thu, 19 Mar 2009) | 15 lines Merged revisions 183319 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r183319 | tilghman | 2009-03-19 14:15:33 -0500 (Thu, 19 Mar 2009) | 8 lines Delay signalling progress until a PRI channel really signals progress. (closes issue ASTERISK-12346) Reported by: klaus3000 Patches: 20090316__bug13034.diff.txt uploaded by tilghman (license 14) patch_trunk_183progress_klaus3000.txt uploaded by klaus3000 (license 65) Tested by: klaus3000 ........ ................ ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=183333 By: Digium Subversion (svnbot) 2009-03-19 14:20:22 Repository: asterisk Revision: 183337 _U branches/1.6.2/ U branches/1.6.2/channels/chan_dahdi.c ------------------------------------------------------------------------ r183337 | tilghman | 2009-03-19 14:20:22 -0500 (Thu, 19 Mar 2009) | 22 lines Merged revisions 183321 via svnmerge from https://origsvn.digium.com/svn/asterisk/trunk ................ r183321 | tilghman | 2009-03-19 14:17:31 -0500 (Thu, 19 Mar 2009) | 15 lines Merged revisions 183319 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r183319 | tilghman | 2009-03-19 14:15:33 -0500 (Thu, 19 Mar 2009) | 8 lines Delay signalling progress until a PRI channel really signals progress. (closes issue ASTERISK-12346) Reported by: klaus3000 Patches: 20090316__bug13034.diff.txt uploaded by tilghman (license 14) patch_trunk_183progress_klaus3000.txt uploaded by klaus3000 (license 65) Tested by: klaus3000 ........ ................ ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=183337 By: klaus3000 (klaus3000) 2009-03-20 04:41:23 Hi! I just reviewed the patch an wondered if p->dialing=0 should be added for PRI_EVENT_RINGING too (I think yes), and then I found this code: case PRI_EVENT_RINGING: ... if (ast_strlen_zero(pri->pvts[chanpos]->dop.dialstr)) { dahdi_enable_ec(pri->pvts[chanpos]); pri->pvts[chanpos]->subs[SUB_REAL].needringing = 1; pri->pvts[chanpos]->alerting = 1; } else ast_debug(1, "Deferring ringing notification because of extra digits to dial...\n"); Why do we go on sending dialstring digits if we already received ALERTING? Isn't this worthless or is there a use case I do not see. By: Tilghman Lesher (tilghman) 2009-03-20 10:27:13 The point isn't that we're actually dialling anything. The point is that we're not sending PROGRESS until dial is turned off. It's simply a flag that prevents frames from getting forwarded on to the SIP channel driver. You're certainly welcome to test this proposed change, but please open it as a new issue, as the fix we came up with solved the issue as stated. By: Tzafrir Cohen (tzafrir) 2009-03-29 10:47:28 Reopened, as requested on #asterisk-dev. By: Martin Vit (festr) 2009-03-29 11:05:31 hi, I've the same problem as reporter (the latest SVN version) i've configured sip.conf progressinband=never I'm receiving to asterisk - SIP/SDP Request: INVITE sip:xx@yy, with session description asterisk responds with 183 with SDP although there is progressinabnd=never This call (INVITE) is routed to Zap/g1 PRI euroISDN on pri debug: Message type: CALL PROCEEDING (2) (after 2 seconds) Message type: ALERTING (1) after received ALERTING, asterisk sends 180 RING but asterisk is not generating alert inside RTP SDP although it sends RTP (but silence) so the far end is not generating alert (although 180 RING is sended by us) because of early 183 I'm not sure that i've explain it clear. If any question, logs or so, tell me. (I've made small hacks inside channel_sip.c to not send 183 with SDP in any situation) and it works for me in this installation. But it should be fixed somehow. and the question - asterisk does not can generate its own alert when ALERT is received on the PRI? By: klaus3000 (klaus3000) 2009-03-29 16:14:07 Take a look at the "CALL PROCEEDING" - if it contains PROGRESS IE with "inband information available" then it is necessary to start early media (183) and the ringback should be generated by the remote end (callee switch) By: Martin Vit (festr) 2009-03-29 16:47:23 It does not contain PROGRESS IE CLI> pri debug span 1 -- Called g1/xxxx < Protocol Discriminator: Q.931 (8) len=5 < Call Ref: len= 2 (reference 2/0x2) (Terminator) < Message type: CALL PROCEEDING (2) q931.c:3683 q931_receive: call 32770 on channel 1 enters state 3 (Outgoing call Proceeding) [Mar 29 17:58:28] DEBUG[16573]: chan_dahdi.c:9576 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 -- Zap/1-1 is proceeding passing it to SIP/xxx-yyy < Protocol Discriminator: Q.931 (8) len=5 < Call Ref: len= 2 (reference 2/0x2) (Terminator) < Message type: ALERTING (1) q931.c:3596 q931_receive: call 32770 on channel 1 enters state 4 (Call Delivered) [Mar 29 17:58:34] DEBUG[16573]: chan_dahdi.c:1780 dahdi_enable_ec: Enabled echo cancellation on channel 1 -- Zap/1-1 is ringing By: klaus3000 (klaus3000) 2009-03-29 16:58:51 IMO that's clearly a bug. You should not fix chan_sip, but chan_dahdi/libpri where the bug is present. chan_dahdi should not report "progress" if the inband-information is not available. Please take a look at libpri/chan_dahdi to fix it. By: Martin Vit (festr) 2009-03-29 18:05:22 Off course, but I'm not capable to dig into chan_dahdi and libpri :) so this hack is temporary solution until somone came with a fix. By: Tilghman Lesher (tilghman) 2009-03-31 22:50:09 festr: while it may be a bug, please open a new issue, instead of reopening this old one, which has already been solved. By: Olle Johansson (oej) 2009-09-18 09:10:09 Please test with the latest 1.4/1.6.x versions and the new option for no premature media turned on in sip.conf. Thanks. | ||||