Outbound called answers while ringing

Asterisk Asterisk Support
1

I’m placing an outbound SIP call from asterisk (v 10.9) with music on hold set. It seems the call is answered straight away, but it’s still ringing? So the MOH plays for a second, then it goes to ringing.

Log segments below. The call starts, then we get an ACK back which asterisk interprets as answered? I’m no SIP expert, and I dont’ get what’s going on here? Anyone got any ideas?

Call starts here:

[code] [2013-05-20 16:22:38] – Executing [s@macro-trunkdial:64] Dial(“SIP/200-00000035”, “SIP/trunk-ISPhone-61289606206/0398351925,10,m(default)”) in new stack
[2013-05-20 16:22:38] == Using SIP RTP CoS mark 5
[2013-05-20 16:22:38] Audio is at 16842
[2013-05-20 16:22:38] Adding codec 100004 (alaw) to SDP
[2013-05-20 16:22:38] Adding codec 100003 (ulaw) to SDP
[2013-05-20 16:22:38] Adding codec 100008 (g729) to SDP
[2013-05-20 16:22:38] Adding codec 100012 (g722) to SDP
[2013-05-20 16:22:38] Adding codec 100011 (g726) to SDP
[2013-05-20 16:22:38] Adding codec 100001 (g723) to SDP
[2013-05-20 16:22:38] Adding codec 100002 (gsm) to SDP
[2013-05-20 16:22:38] Adding non-codec 0x1 (telephone-event) to SDP
[2013-05-20 16:22:38] Reliably Transmitting (NAT) to 27.111.13.65:5060:
INVITE sip:0398351925@phone.sipcity.com.au SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK1aa7770e;rport
Max-Forwards: 70
From: “Chris Warr” sip:asterisk@192.168.30.78;tag=as01446822
To: sip:0398351925@phone.sipcity.com.au
Contact: sip:asterisk@192.168.30.78:5060
Call-ID: 5eb024ff5b6a6b0e2cc0c585482f1a9a@192.168.30.78
CSeq: 102 INVITE
User-Agent: jingl.com.au
Date: Mon, 20 May 2013 06:22:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 430

v=0
o=root 2076308761 2076308761 IN IP4 192.168.30.78
s=Asterisk PBX 10.9.0
c=IN IP4 192.168.30.78
t=0 0
m=audio 16842 RTP/AVP 8 0 18 9 111 4 3 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

[/code]
MOH kicks off:

[2013-05-20 16:22:38] -- Called SIP/trunk-ISPhone-61289606206/0398351925 [2013-05-20 16:22:38] -- Started music on hold, class 'default', on SIP/200- 00000035 [2013-05-20 16:22:38] <--- SIP read from UDP:27.111.13.65:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 150.101.214.40:16505;branch=z9hG4bK1aa7770e;received=150.101.214.40;rport=16505 From: "Chris Warr" <sip:asterisk@150.101.214.40:16505>;tag=as01446822 To: <sip:0398351925@phone.sipcity.com.au>;tag=as00743571 Call-ID: 5eb024ff5b6a6b0e2cc0c585482f1a9a@192.168.30.78 CSeq: 102 INVITE User-Agent: ATP PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="2talk.co.nz", nonce="68cdcd2a" Content-Length: 0

Then we get an ACK back:

[2013-05-20 16:22:40] Transmitting (NAT) to 27.111.13.65:5060: ACK sip:0398351925@27.111.13.65 SIP/2.0 Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK0f59b839;rport Max-Forwards: 70 From: "Chris Warr" <sip:asterisk@192.168.30.78>;tag=as01446822 To: <sip:0398351925@phone.sipcity.com.au>;tag=as7cebfe00 Contact: <sip:asterisk@192.168.30.78:5060> Call-ID: 5eb024ff5b6a6b0e2cc0c585482f1a9a@192.168.30.78 CSeq: 103 ACK User-Agent: jingl.com.au Content-Length: 0

And now asterisk thinks the call is answered?

[code][2013-05-20 16:22:40]     -- SIP/trunk-ISPhone-61289606206-00000036 answered SIP/200-    00000035
[2013-05-20 16:22:40]     -- Stopped music on hold on SIP/200-00000035[/code]
2

Asterisk sends the ACK to stop the remote party repeating its response; it is not a response.

The response here is 407, which is a request for authentication. It is not an ANSWER.

Provided that Asterisk has relevant proxy authentication parameters, it should repeat the INVITE with those parameters.

An answer would be a response code of 200.

I’m going to guess that the remote system answers prematurely and then sends ringing in band, but that happens after the end of your trace.

3

After looking closer at the logs, there is a response code of 200, just before the ACK. Here’s more log:

[code][2013-05-20 17:00:55] VERBOSE[29012] pbx.c: [2013-05-20 17:00:55] – Executing [s@macro-trunkdial:64] Dial(“SIP/200-0000003b”, “SIP/trunk-ISPhone-61289606206/0398351925,10,m(default)”) in new stack
[2013-05-20 17:00:55] VERBOSE[29012] netsock2.c: [2013-05-20 17:00:55] == Using SIP RTP CoS mark 5
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Audio is at 16254
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100004 (alaw) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100003 (ulaw) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100008 (g729) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100012 (g722) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100011 (g726) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100001 (g723) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100002 (gsm) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Adding non-codec 0x1 (telephone-event) to SDP
[2013-05-20 17:00:55] VERBOSE[29012] chan_sip.c: [2013-05-20 17:00:55] Reliably Transmitting (NAT) to 27.111.13.65:5060:
INVITE sip:0398351925@phone.sipcity.com.au SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK34a5de6f;rport
Max-Forwards: 70
From: “Chris Warr” sip:asterisk@192.168.30.78;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au
Contact: sip:asterisk@192.168.30.78:5060
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 102 INVITE
User-Agent: jingl.com.au
Date: Mon, 20 May 2013 07:00:55 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 430

v=0
o=root 1947078553 1947078553 IN IP4 192.168.30.78
s=Asterisk PBX 10.9.0
c=IN IP4 192.168.30.78
t=0 0
m=audio 16254 RTP/AVP 8 0 18 9 111 4 3 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

[2013-05-20 17:00:55] VERBOSE[29012] app_dial.c: [2013-05-20 17:00:55] – Called SIP/trunk-ISPhone-61289606206/0398351925
[2013-05-20 17:00:55] VERBOSE[29012] res_musiconhold.c: [2013-05-20 17:00:55] – Started music on hold, class ‘default’, on SIP/200-0000003b
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55]
<— SIP read from UDP:27.111.13.65:5060 —>
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 150.101.214.40:16505;branch=z9hG4bK34a5de6f;received=150.101.214.40;rport=16505
From: “Chris Warr” sip:asterisk@150.101.214.40:16505;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au;tag=as1ccdfab0
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 102 INVITE
User-Agent: ATP PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm=“2talk.co.nz”, nonce="30bc19f4"
Content-Length: 0

<------------->
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] — (11 headers 0 lines) —
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Transmitting (NAT) to 27.111.13.65:5060:
ACK sip:0398351925@phone.sipcity.com.au SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK34a5de6f;rport
Max-Forwards: 70
From: “Chris Warr” sip:asterisk@192.168.30.78;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au;tag=as1ccdfab0
Contact: sip:asterisk@192.168.30.78:5060
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 102 ACK
User-Agent: jingl.com.au
Content-Length: 0

[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Audio is at 16254
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100004 (alaw) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100003 (ulaw) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100008 (g729) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100012 (g722) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100011 (g726) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100001 (g723) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding codec 100002 (gsm) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Adding non-codec 0x1 (telephone-event) to SDP
[2013-05-20 17:00:55] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:55] Reliably Transmitting (NAT) to 27.111.13.65:5060:
INVITE sip:0398351925@phone.sipcity.com.au SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK12c8dd94;rport
Max-Forwards: 70
From: “Chris Warr” sip:asterisk@192.168.30.78;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au
Contact: sip:asterisk@192.168.30.78:5060
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 103 INVITE
User-Agent: jingl.com.au
Proxy-Authorization: Digest username=“61289606206”, realm=“2talk.co.nz”, algorithm=MD5, uri="sip:0398351925@phone.sipcity.com.au", nonce=“30bc19f4”, response="9bc6bb6b6d07feda84aa9cd03b94f7c6"
Date: Mon, 20 May 2013 07:00:55 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 430

v=0
o=root 1947078553 1947078554 IN IP4 192.168.30.78
s=Asterisk PBX 10.9.0
c=IN IP4 192.168.30.78
t=0 0
m=audio 16254 RTP/AVP 8 0 18 9 111 4 3 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

[2013-05-20 17:00:56] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:56]
<— SIP read from UDP:27.111.13.65:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 150.101.214.40:16505;branch=z9hG4bK12c8dd94;received=150.101.214.40;rport=16505
From: “Chris Warr” sip:asterisk@150.101.214.40:16505;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 103 INVITE
User-Agent: ATP PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:0398351925@27.111.13.65
Content-Length: 0

<------------->
[2013-05-20 17:00:56] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:56] — (11 headers 0 lines) —
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57]

***Here’s the OK. Call is ringing here.

<— SIP read from UDP:27.111.13.65:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 150.101.214.40:16505;branch=z9hG4bK12c8dd94;received=150.101.214.40;rport=16505
From: “Chris Warr” sip:asterisk@150.101.214.40:16505;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au;tag=as286f417c
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 103 INVITE
User-Agent: ATP PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:0398351925@27.111.13.65
Content-Type: application/sdp
Content-Length: 307

v=0
o=root 16829 16829 IN IP4 27.111.13.65
s=session
c=IN IP4 27.111.13.65
t=0 0
m=audio 45170 RTP/AVP 18 3 8 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------->
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] — (12 headers 15 lines) —
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found RTP audio format 18
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found RTP audio format 3
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found RTP audio format 8
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found RTP audio format 0
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found RTP audio format 101
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found audio description format G729 for ID 18
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found audio description format GSM for ID 3
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found audio description format PCMA for ID 8
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found audio description format PCMU for ID 0
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Found audio description format telephone-event for ID 101
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Capabilities: us - (g723|gsm|ulaw|alaw|g726|g729|g722), peer - audio=(gsm|ulaw|alaw|g729)/video=(nothing)/text=(nothing), combined - (gsm|ulaw|alaw|g729)
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Peer audio RTP is at port 27.111.13.65:45170
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] list_route: hop: sip:0398351925@27.111.13.65
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] set_destination: Parsing sip:0398351925@27.111.13.65 for address/port to send to
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] set_destination: set destination to 27.111.13.65:5060
[2013-05-20 17:00:57] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:57] Transmitting (NAT) to 27.111.13.65:5060:

****We get this ACK then asterisk thinks it’s answered. Still ringing.

ACK sip:0398351925@27.111.13.65 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK02b576b0;rport
Max-Forwards: 70
From: “Chris Warr” sip:asterisk@192.168.30.78;tag=as70cf55b6
To: sip:0398351925@phone.sipcity.com.au;tag=as286f417c
Contact: sip:asterisk@192.168.30.78:5060
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 103 ACK
User-Agent: jingl.com.au
Content-Length: 0

[2013-05-20 17:00:57] VERBOSE[29012] app_dial.c: [2013-05-20 17:00:57] – SIP/trunk-ISPhone-61289606206-0000003c answered SIP/200-0000003b
[2013-05-20 17:00:57] VERBOSE[29012] res_musiconhold.c: [2013-05-20 17:00:57] – Stopped music on hold on SIP/200-0000003b
[2013-05-20 17:00:58] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:58] Really destroying SIP dialog ‘168ca7d62432c58914b0b27c75848315@192.168.30.78’ Method: REGISTER
[2013-05-20 17:00:58] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:58] Really destroying SIP dialog ‘339298e22a27682555972b9f4174ff5f@192.168.30.78’ Method: REGISTER
[2013-05-20 17:00:58] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:58] Really destroying SIP dialog ‘1d6e134f3de31e16276c55c0523ab46f@192.168.30.78’ Method: REGISTER
[2013-05-20 17:00:59] VERBOSE[25363] chan_sip.c: [2013-05-20 17:00:59] Really destroying SIP dialog ‘2c0f29e96fd2c3de5e109404608c89fd@192.168.30.78’ Method: REGISTER
[2013-05-20 17:01:13] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:13]
<— SIP read from UDP:27.111.13.65:5060 —>
OPTIONS sip:61289606206@150.101.214.40:16505 SIP/2.0
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK5cdb6413;rport
From: “2talkpbx” sip:2talkpbx@27.111.13.65;tag=as66b24a50
To: sip:61289606206@150.101.214.40:16505
Contact: sip:2talkpbx@27.111.13.65
Call-ID: 6ff9e88563c84dd776a03ebc6b098d4e@27.111.13.65
CSeq: 102 OPTIONS
User-Agent: ATP PBX
Max-Forwards: 70
Date: Mon, 20 May 2013 07:01:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0

<------------->
[2013-05-20 17:01:13] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:13] — (13 headers 0 lines) —
[2013-05-20 17:01:13] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:13] Looking for 61289606206 in default (domain 150.101.214.40)
[2013-05-20 17:01:13] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:13]
<— Transmitting (NAT) to 27.111.13.65:5060 —>
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK5cdb6413;received=27.111.13.65;rport=5060
From: “2talkpbx” sip:2talkpbx@27.111.13.65;tag=as66b24a50
To: sip:61289606206@150.101.214.40:16505;tag=as674378d8
Call-ID: 6ff9e88563c84dd776a03ebc6b098d4e@27.111.13.65
CSeq: 102 OPTIONS
Server: jingl.com.au
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Accept: application/sdp
Content-Length: 0

<------------>
[2013-05-20 17:01:13] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:13] Scheduling destruction of SIP dialog ‘6ff9e88563c84dd776a03ebc6b098d4e@27.111.13.65’ in 32000 ms (Method: OPTIONS)
[2013-05-20 17:01:15] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:15]
<— SIP read from UDP:27.111.13.65:5060 —>
NOTIFY sip:61289606206@150.101.214.40:16505 SIP/2.0
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK7e7d51f9;rport
From: “2talkpbx” sip:2talkpbx@27.111.13.65;tag=as4b3d6918
To: sip:61289606206@150.101.214.40:16505
Contact: sip:2talkpbx@27.111.13.65
Call-ID: 768911695210fd7a5f65276f32f85d28@27.111.13.65
CSeq: 102 NOTIFY
User-Agent: ATP PBX
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 92

Messages-Waiting: no
Message-Account: sip:2talkpbx@27.111.13.65
Voice-Message: 0/0 (0/0)

<------------->
[2013-05-20 17:01:15] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:15] — (12 headers 3 lines) —
[2013-05-20 17:01:15] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:15]
<— Transmitting (NAT) to 27.111.13.65:5060 —>
SIP/2.0 489 Bad event
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK7e7d51f9;received=27.111.13.65;rport=5060
From: “2talkpbx” sip:2talkpbx@27.111.13.65;tag=as4b3d6918
To: sip:61289606206@150.101.214.40:16505;tag=as32370d9c
Call-ID: 768911695210fd7a5f65276f32f85d28@27.111.13.65
CSeq: 102 NOTIFY
Server: jingl.com.au
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
[2013-05-20 17:01:15] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:15] Scheduling destruction of SIP dialog ‘768911695210fd7a5f65276f32f85d28@27.111.13.65’ in 32000 ms (Method: NOTIFY)
[2013-05-20 17:01:18] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:18]
<— SIP read from UDP:27.111.13.65:5060 —>
BYE sip:asterisk@150.101.214.40:16505 SIP/2.0
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK4efddb80;rport
From: sip:0398351925@phone.sipcity.com.au;tag=as286f417c
To: “Chris Warr” sip:asterisk@150.101.214.40:16505;tag=as70cf55b6
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 102 BYE
User-Agent: ATP PBX
Max-Forwards: 70
Content-Length: 0

<------------->
[2013-05-20 17:01:18] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:18] — (9 headers 0 lines) —
[2013-05-20 17:01:18] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:18] Sending to 27.111.13.65:5060 (NAT)
[2013-05-20 17:01:18] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:18] Scheduling destruction of SIP dialog ‘4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78’ in 32000 ms (Method: BYE)
[2013-05-20 17:01:18] VERBOSE[25363] chan_sip.c: [2013-05-20 17:01:18]
<— Transmitting (NAT) to 27.111.13.65:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 27.111.13.65:5060;branch=z9hG4bK4efddb80;received=27.111.13.65;rport=5060
From: sip:0398351925@phone.sipcity.com.au;tag=as286f417c
To: “Chris Warr” sip:asterisk@150.101.214.40:16505;tag=as70cf55b6
Call-ID: 4650d0fb5eb2cb2902ed0ff12576548f@192.168.30.78
CSeq: 102 BYE
Server: jingl.com.au
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
[2013-05-20 17:01:18] VERBOSE[29012] pbx.c: [2013-05-20 17:01:18] – Executing [h@default:1] JinglLogQOS(“SIP/200-0000003b”, “”) in new stack
[2013-05-20 17:01:18] VERBOSE[29012] app_macro.c: [2013-05-20 17:01:18] == Spawn extension (macro-trunkdial, s, 64) exited non-zero on ‘SIP/200-0000003b’ in macro ‘trunkdial’
[2013-05-20 17:01:18] VERBOSE[29012] pbx.c: [2013-05-20 17:01:18] == Spawn extension (default, 123, 6) exited non-zero on ‘SIP/200-0000003b’
[2013-05-20 17:01:18] VERBOSE[29012] chan_sip.c: [2013-05-20 17:01:18] Scheduling destruction of SIP dialog ‘130fdd41-73dd3a38-2cfcf7a3@192.168.30.150’ in 32000 ms (Method: ACK)
[2013-05-20 17:01:18] VERBOSE[29012] chan_sip.c: [2013-05-20 17:01:18] set_destination: Parsing sip:200@192.168.30.150 for address/port to send to
[2013-05-20 17:01:18] VERBOSE[29012] chan_sip.c: [2013-05-20 17:01:18] set_destination: set destination to 192.168.30.150:5060
[2013-05-20 17:01:18] VERBOSE[29012] chan_sip.c: [2013-05-20 17:01:18] Reliably Transmitting (NAT) to 192.168.30.150:5060:
BYE sip:200@192.168.30.150 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.78:5060;branch=z9hG4bK6993b1bc;rport
Max-Forwards: 70
From: sip:123@192.168.30.78;user=phone;tag=as609bc34d[/code]

4

There is no 180 Ringing and no early media, so if you get a transition from music to ringing it is because the remote side has answered the call and is passing ringback tone in the media stream.

5

thanks, so is there anything I can do about that? Any options I can pass? Or can I ask the sip provider to do something different?

6

Ask the SIP provider to do something different. There is no way for a SIP client to sell a SIP server not to answer until the their outgoing side answers. On the other hand, that is not good behaviour.

Of course, the issue could be on the PSTN side of the SIP provider.

I think that some of the Asterisk GUIs answer prematurely. That may be because it is the only way they can be certain of sending early media.

7

Thanks for your help. I was able to find the solution with my sip providers help. Turns out the number I was dialling was auto-answering and providing the ringing tone. I’ve tried different number and got the results I was expecting. Thanks again.