First few seconds cut off in outgoing sip call

Asterisk Asterisk Support
1

Hi,

I’m having problems with the first few seconds of outgoing sip calls. This is my config:

FritzBox SIP client (192.168.178.1) directly connected to
Asterisk 1.6.2.11 (192.168.178.20:5050) which connects to sip servers (as a sip client) of my ISP.
So the server is behind a NAT device.

Outgoing calls and incoming calls work, incoming calls that stay inside my network work, too. I’d assume that my dialplan.conf is correct, but here’s the bit that dials out anyways:

[outgoing_calls_838XXX]
exten => _Z.,1,Dial(SIP/1und1-out-838XXX/02522${EXTEN})
exten => _Z.,n,Hangup()
exten => _0XXX.,1,Dial(SIP/1und1-out-838XXX/${EXTEN})
exten => _0XXX.,n,Hangup()

Maybe something in my sip.conf is not correct, so here it is:

[general]
context=default
allowoverlap=no
udpbindaddr=0.0.0.0:5050
tcpenable=no
tcpbindaddr=0.0.0.0
srvlookup=yes
disallow=all
register => 492522838XXX:<password>@1und1.de/492522838XXX
localnet=192.168.178.0/255.255.255.0
externhost=<My dynamic DNS address goes here>
externrefresh=600

[authentication]
[intern](!)
type=friend
secret=<password>
host=dynamic
disallow=all
allow=g722,g711,g726,ulaw,alaw
qualify=yes
canreinvite=no
nat=no

[fritz](intern)
context=fritz
callerid=838XXX

[1und1-out](!)
type=peer
secret=<password>
host=sip.1und1.de
fromdomain=sip.1und1.de
nat=yes
insecure=port,invite
disallow=all
allow=g722,g711,g726,ulaw,alaw
qualify=yes

[1und1-out-838XXX](1und1-out)
username=492522838XXX
fromuser=492522838XXX

[1und1-in](!)
type=peer
fromdomain=1und1.de
insecure=port,invite
nat=yes
context=incoming_calls
qualify=yes
allow=g722,g711,g726,ulaw,alaw

;36 entries like this:
[1und1_in_11](1und1-in)
host=sipbalance1-1.1und1.de

The problem is that on outgoing calls one or few seconds get cut off, so I often can’t hear the other persons first name. In my latest testcall I could hear the first letter of the first name, then the audio stopped and after the end of the first name the audio started again. I saved a debug log from that call:

[2011-03-23 16:08:46.744] DEBUG[15097] acl.c: Found IP address for this socket
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.178.20:5050
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: Setting NAT on RTP to Off
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: Allocating new SIP dialog for 69122BC88F16D9CD@192.168.178.1 - INVITE (With RTP)
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: Setting NAT on RTP to Off
[2011-03-23 16:08:46.744] DEBUG[15097] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.178.1:5060
[2011-03-23 16:08:46.747] DEBUG[15097] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2011-03-23 16:08:46.747] DEBUG[15097] chan_sip.c: Stopping retransmission on '69122BC88F16D9CD@192.168.178.1' of Response 6689: Match Found
[2011-03-23 16:08:46.753] DEBUG[15097] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-03-23 16:08:46.753] DEBUG[15097] chan_sip.c: Setting NAT on RTP to Off
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing session-level SDP o=user 9019161 9019161 IN IP4 192.168.178.1... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing session-level SDP s=call... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.178.1... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 G726-32/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 G726-40/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:99 G726-24/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=fmtp:97 mode=30... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:120 PCMA/16000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:121 PCMU/16000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtcp:7079... UNSUPPORTED.
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: We're settling with these formats: 0x180c (ulaw|alaw|g726|g722)
[2011-03-23 16:08:46.754] DEBUG[15097] chan_sip.c: Checking SIP call limits for device fritz
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: Updating call counter for incoming call
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: *** Our native formats are 0x1000 (g722) 
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: *** Joint capabilities are 0x180c (ulaw|alaw|g726|g722) 
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: *** Our capabilities are 0x180c (ulaw|alaw|g726|g722) 
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) 
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: This channel will not be able to handle video.
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: build_route: Contact hop: <sip:fritz@192.168.178.1;uniq=7957DCDA0C990829200DEFD93F646>
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: SIP/fritz-0000005d: New call is still down.... Trying... 
[2011-03-23 16:08:46.770] DEBUG[15097] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.178.1:5060
[2011-03-23 16:08:46.771] DEBUG[15088] devicestate.c: No provider found, checking channel drivers for SIP - fritz
[2011-03-23 16:08:46.771] DEBUG[15088] chan_sip.c: Checking device state for peer fritz
[2011-03-23 16:08:46.771] DEBUG[15088] devicestate.c: Changing state for SIP/fritz - state 1 (Not in use)
[2011-03-23 16:08:46.771] DEBUG[15088] devicestate.c: device 'SIP/fritz' state '1'

[2011-03-23 16:08:46.791] DEBUG[6117] pbx.c: Launching 'Dial'
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Asked to create a SIP channel with formats: 0x1000 (g722)
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Allocating new SIP dialog for 3b3ebdbe42dc97e61122a2610f0bc5b8@127.0.0.1 - INVITE (With RTP)
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Setting NAT on RTP to On
[2011-03-23 16:08:46.791] DEBUG[6117] acl.c: Found IP address for this socket
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Target address 212.227.18.205 is not local, substituting externip
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 88.77.73.227:5050
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: *** Our native formats are 0x1000 (g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: *** Joint capabilities are 0x1000 (g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: *** Our capabilities are 0x180c (ulaw|alaw|g726|g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: *** Our preferred formats from the incoming channel are 0x1000 (g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: This channel will not be able to handle video.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable DIALEDTIME.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable ANSWEREDTIME.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable DIALEDPEERNAME.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable DIALEDPEERNUMBER.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable DIALSTATUS.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable SIPCALLID.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable SIPDOMAIN.
[2011-03-23 16:08:46.791] DEBUG[6117] channel.c: Not copying variable SIPURI.
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Outgoing Call for 05241808218
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Updating call counter for outgoing call
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: ** Our capability: 0x180c (ulaw|alaw|g726|g722) Video flag: False Text flag: False
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: ** Our prefcodec: 0x1000 (g722) 
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: -- Done with adding codecs to SDP
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Done building SDP. Settling with this capability: 0x180c (ulaw|alaw|g726|g722)
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Initializing initreq for method INVITE - callid 6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de
[2011-03-23 16:08:46.791] DEBUG[6117] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 212.227.18.205:5060
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: Acked pending invite 102
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: Stopping retransmission on '6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de' of Request 102: Match Found
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: SIP response 407 to standard invite
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: Trying to put 'ACK sip:052' onto UDP socket destined for 212.227.18.205:5060
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: Auth attempt 1 on INVITE
[2011-03-23 16:08:46.833] DEBUG[15097] chan_sip.c: ** Our capability: 0x180c (ulaw|alaw|g726|g722) Video flag: False Text flag: False
[2011-03-23 16:08:46.834] DEBUG[15097] chan_sip.c: ** Our prefcodec: 0x1000 (g722) 
[2011-03-23 16:08:46.834] DEBUG[15097] chan_sip.c: -- Done with adding codecs to SDP
[2011-03-23 16:08:46.834] DEBUG[15097] chan_sip.c: Done building SDP. Settling with this capability: 0x180c (ulaw|alaw|g726|g722)
[2011-03-23 16:08:46.834] DEBUG[15097] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 212.227.18.205:5060
[2011-03-23 16:08:46.882] DEBUG[15097] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de' Request 103: Found
[2011-03-23 16:08:46.883] DEBUG[15097] chan_sip.c: SIP response 100 to standard invite
[2011-03-23 16:08:47.094] DEBUG[6117] rtp.c: RTP NAT: Got audio from other end. Now sending to address 88.79.152.245:15088
[2011-03-23 16:08:47.094] DEBUG[6117] chan_sip.c: Oooh, format changed to 8 alaw
[2011-03-23 16:08:47.094] DEBUG[6117] channel.c: Set channel SIP/1und1-out-838XXX-0000005e to read format g722
[2011-03-23 16:08:47.094] DEBUG[6117] channel.c: Set channel SIP/1und1-out-838XXX-0000005e to write format g722

[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de' Request 103: Found
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: SIP response 183 to standard invite
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing session-level SDP o=- 0 93672548 IN IP4 88.79.152.245... UNSUPPORTED.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing session-level SDP s=IMSS... UNSUPPORTED.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing session-level SDP c=IN IP4 88.79.152.245... OK.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: We're settling with these formats: 0x8 (alaw)
[2011-03-23 16:08:48.219] DEBUG[15097] chan_sip.c: We have an owner, now see if we need to change this call
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: Setting framing from config on incoming call
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: ** Our capability: 0x180c (ulaw|alaw|g726|g722) Video flag: True Text flag: True
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: -- Done with adding codecs to SDP
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: Done building SDP. Settling with this capability: 0x180c (ulaw|alaw|g726|g722)
[2011-03-23 16:08:48.219] DEBUG[6117] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 192.168.178.1:5060
[2011-03-23 16:08:48.231] DEBUG[6117] rtp.c: Ooh, format changed from unknown to g722
[2011-03-23 16:08:48.231] DEBUG[6117] rtp.c: Created smoother: format: 4096 ms: 20 len: 160
[2011-03-23 16:08:48.268] DEBUG[6117] rtp.c: Ooh, format changed from unknown to alaw
[2011-03-23 16:08:48.268] DEBUG[6117] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[2011-03-23 16:08:48.993] DEBUG[15097] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de' Request 103: Found
[2011-03-23 16:08:48.993] DEBUG[15097] chan_sip.c: SIP response 180 to standard invite
[2011-03-23 16:08:48.993] DEBUG[15097] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2011-03-23 16:08:48.993] DEBUG[15097] chan_sip.c: Call 6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de responded to our reinvite without changing SDP version; ignoring SDP.
[2011-03-23 16:08:48.993] DEBUG[15088] devicestate.c: No provider found, checking channel drivers for SIP - 1und1-out-838705
[2011-03-23 16:08:48.993] DEBUG[15088] chan_sip.c: Checking device state for peer 1und1-out-838XXX
[2011-03-23 16:08:48.993] DEBUG[15088] devicestate.c: Changing state for SIP/1und1-out-838XXX - state 1 (Not in use)
[2011-03-23 16:08:48.993] DEBUG[15088] devicestate.c: device 'SIP/1und1-out-838XXX' state '1'
[2011-03-23 16:08:48.993] DEBUG[6117] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.178.1:5060
[2011-03-23 16:08:50.722] DEBUG[6117] rtp.c: Got RTCP report of 120 bytes
[2011-03-23 16:08:50.722] DEBUG[6117] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.178.1:7079
[2011-03-23 16:08:52.019] DEBUG[6117] rtp.c: Got RTCP report of 76 bytes
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Acked pending invite 103
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Stopping retransmission on '6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de' of Request 103: Match Found
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: SIP response 200 to standard invite
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Call 6e8326fc736d0ce974b7340f1db31e27@sip.1und1.de responded to our reinvite without changing SDP version; ignoring SDP.
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Updating call counter for outgoing call
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: build_route: Record-Route hop: <sip:212.227.18.199;lr=on;ftag=as1c612ca6>
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: build_route: Record-Route hop: <sip:212.227.18.167;lr=on;ftag=as1c612ca6;did=288.4c578d56>
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: build_route: Record-Route hop: <sip:212.227.18.205;lr=on;ftag=as1c612ca6>
[2011-03-23 16:08:52.507] DEBUG[15097] chan_sip.c: Trying to put 'ACK sip:495' onto UDP socket destined for 212.227.18.205:5060
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: SIP answering channel: SIP/fritz-0000005d
[2011-03-23 16:08:52.507] DEBUG[6117] rtp.c: Setting the marker bit due to a source update
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: Setting framing from config on incoming call
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: ** Our capability: 0x180c (ulaw|alaw|g726|g722) Video flag: True Text flag: True
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: -- Done with adding codecs to SDP
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: Done building SDP. Settling with this capability: 0x180c (ulaw|alaw|g726|g722)
[2011-03-23 16:08:52.507] DEBUG[6117] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.178.1:5060
[2011-03-23 16:08:52.507] DEBUG[6117] features.c: bridge answer set, chan answer set
[2011-03-23 16:08:52.507] DEBUG[6117] rtp.c: Setting the marker bit due to a source update
[2011-03-23 16:08:52.507] DEBUG[6117] rtp.c: Setting the marker bit due to a source update
[2011-03-23 16:08:52.507] DEBUG[6117] rtp.c: Cannot packet2packet bridge - raw formats are incompatible
[2011-03-23 16:08:52.507] DEBUG[15088] devicestate.c: No provider found, checking channel drivers for SIP - 1und1-out-838705
[2011-03-23 16:08:52.508] DEBUG[15088] chan_sip.c: Checking device state for peer 1und1-out-838XXX
[2011-03-23 16:08:52.508] DEBUG[15088] devicestate.c: Changing state for SIP/1und1-out-838XXX - state 1 (Not in use)
[2011-03-23 16:08:52.508] DEBUG[15088] devicestate.c: device 'SIP/1und1-out-838XXX' state '1'
[2011-03-23 16:08:52.508] DEBUG[15088] devicestate.c: No provider found, checking channel drivers for SIP - fritz
[2011-03-23 16:08:52.508] DEBUG[15088] chan_sip.c: Checking device state for peer fritz
[2011-03-23 16:08:52.508] DEBUG[15088] devicestate.c: Changing state for SIP/fritz - state 1 (Not in use)
[2011-03-23 16:08:52.508] DEBUG[15088] devicestate.c: device 'SIP/fritz' state '1'

Any ideas? Or did I miss out on any vital information asterisk could have told me?

2

Bump

I’m not yet a specialist at reading these logs but here’s an idea: Is it possible that the codec changes right at the start of the conversation, just after the call has been accepted?

3

What’s more likely is that there is a re-invite to native bridging. Unfortunately, it takes quite a large amount of time to extract the important information from such logs, so if you can extract the key parts of the SDP, you are more likely to get a quick answer.