I observe a very strange delay on my asterisk server. When I try dial out asetrisk write Dial… and wait 20sec before it sends Invite to other peer:
kab-vs3*CLI>
<-- SIP read from 192.168.162.2:5060:
INVITE sip:0808031@192.168.119.250;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.162.2;branch=z9hG4bKac654810089
Max-Forwards: 70
From: sip:809973@192.168.162.2;tag=1c654806330
To: sip:0808031@192.168.119.250;user=phone
Call-ID: 65480583441200022430@192.168.162.2
CSeq: 1 INVITE
Contact: sip:809973@192.168.162.2
Supported: em,100rel,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
User-Agent: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.60A.016.003
Content-Type: application/sdp
Content-Length: 273
v=0
o=AudiocodesGW 654796344 654796224 IN IP4 192.168.162.2
s=Phone-Call
c=IN IP4 192.168.162.2
t=0 0
m=audio 6000 RTP/AVP 18 8 96
a=rtpmap:18 g729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 pcma/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=ptime:20
a=sendrecv
— (13 headers 13 lines)—
Using INVITE request as basis request - 65480583441200022430@192.168.162.2
Sending to 192.168.162.2 : 5060 (non-NAT)
May 28 13:53:07 DEBUG[17248]: chan_sip.c:7586 check_user_full: Setting NAT on RTP to 524288
May 28 13:53:07 DEBUG[17248]: chan_sip.c:7595 check_user_full: Setting NAT on UDPTL to 524288
Found user '809973’
Found RTP audio format 18
Found RTP audio format 8
Found RTP audio format 96
Peer audio RTP is at port 192.168.162.2:6000
May 28 13:53:07 DEBUG[17248]: chan_sip.c:3751 process_sdp: Peer audio RTP is at port 192.168.162.2:6000
Peer T.38 UDPTL is at port 192.168.162.2:65535
May 28 13:53:07 DEBUG[17248]: chan_sip.c:3785 process_sdp: Peer T.38 UDPTL is at port 192.168.162.2:65535
Found description format g729
Found description format pcma
Found description format telephone-event
May 28 13:53:07 DEBUG[17248]: chan_sip.c:3918 process_sdp: T38 state changed to 0 on channel
Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
May 28 13:53:07 DEBUG[17248]: chan_sip.c:10967 handle_request_invite: Checking SIP call limits for device 809973
Looking for 0808031 in test_1 (domain 192.168.119.250)
May 28 13:53:07 DEBUG[17248]: chan_sip.c:6596 build_route: build_route: Contact hop: sip:809973@192.168.162.2
list_route: hop: sip:809973@192.168.162.2
Transmitting (NAT) to 192.168.162.2:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.162.2;branch=z9hG4bKac654810089;received=192.168.162.2
From: sip:809973@192.168.162.2;tag=1c654806330
To: sip:0808031@192.168.119.250;user=phone
Call-ID: 65480583441200022430@192.168.162.2
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:0808031@192.168.119.250
Content-Length: 0
May 28 13:53:07 DEBUG[17399]: pbx.c:1510 pbx_substitute_variables_helper_full: Function result is ‘0’
– Executing NoOp(“SIP/809973-6d8e”, “Group Count: 0”) in new stack
– Executing Set(“SIP/809973-6d8e”, “GROUP()=Test”) in new stack
May 28 13:53:07 DEBUG[17399]: pbx.c:1510 pbx_substitute_variables_helper_full: Function result is ‘Test’
– Executing NoOp(“SIP/809973-6d8e”, “Group List: Test”) in new stack
May 28 13:53:07 DEBUG[17399]: pbx.c:1510 pbx_substitute_variables_helper_full: Function result is ‘1’
– Executing NoOp(“SIP/809973-6d8e”, “Group Count: 1”) in new stack
May 28 13:53:07 DEBUG[17399]: pbx.c:1510 pbx_substitute_variables_helper_full: Function result is ‘1’
– Executing NoOp(“SIP/809973-6d8e”, “Group Count2: 1”) in new stack
May 28 13:53:07 DEBUG[17399]: pbx.c:1510 pbx_substitute_variables_helper_full: Function result is '1’
May 28 13:53:07 DEBUG[17399]: pbx.c:1577 pbx_substitute_variables_helper_full: Expression result is ‘0’
– Executing GotoIf(“SIP/809973-6d8e”, “0?103”) in new stack
May 28 13:53:07 DEBUG[17399]: pbx.c:6122 pbx_builtin_gotoif: Not taking any branch
– Executing Dial(“SIP/809973-6d8e”, “SIP/192.168.119.225/0808031|60|tT”) in new stack
kaba-vs3*CLI>
May 28 13:53:27 DEBUG[17399]: chan_sip.c:2149 sip_call: Outgoing Call for 0808031
May 28 13:53:27 DEBUG[17399]: chan_sip.c:2156 sip_call: Our T38 capability (3856), joint T38 capability (3856)
We’re at 192.168.119.250 port 15926
Adding codec 0x8 (alaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
13 headers, 12 lines
Reliably Transmitting (no NAT) to 192.168.119.225:5060:
INVITE sip:0808031@192.168.119.225 SIP/2.0
Via: SIP/2.0/UDP 192.168.119.250:5060;branch=z9hG4bK0d996b36;rport
From: “809973” sip:809973@192.168.119.250;tag=as5cc0978a
To: sip:0808031@192.168.119.225
Contact: sip:809973@192.168.119.250
Call-ID: 568f201d123826ff5b8c8e5c07507e83@192.168.119.250
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Mon, 28 May 2007 11:53:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 269
v=0
o=root 17240 17240 IN IP4 192.168.119.250
s=session
c=IN IP4 192.168.119.250
t=0 0
m=audio 15926 RTP/AVP 8 3 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
-- Called 192.168.119.225/0808031
kaba-vs3*CLI> exit
<-- SIP read from 192.168.119.225:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.119.250:5060;branch=z9hG4bK0d996b36;rport
From: “809973” sip:809973@192.168.119.250;tag=as5cc0978a
To: sip:0808031@192.168.119.225;tag=64E7A008-17E5
Date: Mon, 28 May 2007 11:53:28 GMT
Call-ID: 568f201d123826ff5b8c8e5c07507e83@192.168.119.250
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0
— (10 headers 0 lines)—
May 28 13:53:27 DEBUG[17248]: chan_sip.c:1512 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘568f201d123826ff5b8c8e5c07507e83@192.168.119.250’ Request 102: Found
<-- SIP read from 192.168.119.225:5060:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.119.250:5060;branch=z9hG4bK0d996b36;rport
From: “809973” sip:809973@192.168.119.250;tag=as5cc0978a
To: sip:0808031@192.168.119.225;tag=64E7A008-17E5
Date: Mon, 28 May 2007 11:53:28 GMT
Call-ID: 568f201d123826ff5b8c8e5c07507e83@192.168.119.250
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
llow-Events: telephone-event
Contact: sip:0808031@192.168.119.225:5060
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 188
v=0
o=CiscoSystemsSIP-GW-UserAgent 8761 4344 IN IP4 192.168.119.225
s=SIP Call
c=IN IP4 192.168.119.225
t=0 0
m=audio 19388 RTP/AVP 8
c=IN IP4 192.168.119.225
a=rtpmap:8 PCMA/8000
— (14 headers 8 lines)—
May 28 13:53:28 DEBUG[17248]: chan_sip.c:1512 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘568f201d123826ff5b8c8e5c07507e83@192.168.119.250’ Request 102: Found
Found RTP audio format 8
Peer audio RTP is at port 192.168.119.225:19388
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3751 process_sdp: Peer audio RTP is at port 192.168.119.225:19388
Peer T.38 UDPTL is at port 192.168.119.225:65535
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3785 process_sdp: Peer T.38 UDPTL is at port 192.168.119.225:65535
Found description format PCMA
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3918 process_sdp: T38 state changed to 0 on channel SIP/192.168.119.225-2fb7
Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3969 process_sdp: Oooh, we need to change our formats since our peer supports only 0x8 (alaw) and not 0x4 (ulaw)
– SIP/192.168.119.225-2fb7 is making progress passing it to SIP/809973-6d8e
We’re at 192.168.119.250 port 16928
Adding codec 0x8 (alaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Transmitting (NAT) to 192.168.162.2:5060:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.162.2;branch=z9hG4bKac654810089;received=192.168.162.2
From: sip:809973@192.168.162.2;tag=1c654806330
To: sip:0808031@192.168.119.250;user=phone;tag=as51405165
Call-ID: 65480583441200022430@192.168.162.2
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:0808031@192.168.119.250
Content-Type: application/sdp
Content-Length: 266
v=0
o=root 17240 17240 IN IP4 192.168.119.250
s=session
c=IN IP4 192.168.119.250
t=0 0
m=audio 16928 RTP/AVP 8 3 0 96
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=silenceSupp:off - - - -
kaba-vs3*CLI> exit
<-- SIP read from 192.168.119.225:5060:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.119.250:5060;branch=z9hG4bK0d996b36;rport
From: “809973” sip:809973@192.168.119.250;tag=as5cc0978a
To: sip:0808031@192.168.119.225;tag=64E7A008-17E5
Date: Mon, 28 May 2007 11:53:28 GMT
Call-ID: 568f201d123826ff5b8c8e5c07507e83@192.168.119.250
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
llow-Events: telephone-event
Contact: sip:0808031@192.168.119.225:5060
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 188
v=0
o=CiscoSystemsSIP-GW-UserAgent 8761 4344 IN IP4 192.168.119.225
s=SIP Call
c=IN IP4 192.168.119.225
t=0 0
m=audio 19388 RTP/AVP 8
c=IN IP4 192.168.119.225
a=rtpmap:8 PCMA/8000
— (14 headers 8 lines)—
May 28 13:53:28 DEBUG[17248]: chan_sip.c:1512 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘568f201d123826ff5b8c8e5c07507e83@192.168.119.250’ Request 102: Found
Found RTP audio format 8
Peer audio RTP is at port 192.168.119.225:19388
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3751 process_sdp: Peer audio RTP is at port 192.168.119.225:19388
Peer T.38 UDPTL is at port 192.168.119.225:65535
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3785 process_sdp: Peer T.38 UDPTL is at port 192.168.119.225:65535
Found description format PCMA
May 28 13:53:28 DEBUG[17248]: chan_sip.c:3918 process_sdp: T38 state changed to 0 on channel SIP/192.168.119.225-2fb7
Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
– SIP/192.168.119.225-2fb7 is making progress passing it to SIP/809973-6d8e
Regards