We have some problem for long distance call

Hello,

We have some problem for long distance call.

The bellow is the sample php and asterisk extension.

When we make a call from local to local/long distance, the call is ok. First phone is ringing, we answer and then the second number is dialed.
When we make a call from long distance to local/long, both phones ring at the same time.
This is not the expected behavior. The second number should be dialed only after the first phone is answered.

Checking the asterisk log, we found something strange.
When we make a call from local, we have delay bewteen the “Originate” and "Answer"
When we make a call from long distance, there is no delay between “Originate” and “Answer” and this is impossible.
The second number is dialed even if we didn’t answer the phone.

Anyone experienced this problem?
How can we fix it?

Thank you!


fputs($socket, “Action: Originate\r\n”);
fputs($socket, “Timeout: 300000\r\n”);
fputs($socket, “CallerID: 1111\r\n”);
fputs($socket, “Channel: SIP/1514xxxxxxx@openface\r\n”);
fputs($socket, “Account: XCC\r\n”);
fputs($socket, “Context: sample\r\n”);
fputs($socket, “Exten: 1514xxxxxxx\r\n”);
fputs($socket, “Priority: 1\r\n”);
fputs($socket, “Async: yes\r\n”);
fputs($socket, “\r\n”);


[dialstatus]
; extensions for DIALSTATUS
exten => _s-.,1,NoOp(##DIALSTATUS: ${DIALSTATUS} ##########)
exten => _s-.,2,NoOp(##DIALSTATUS: ${DIALSTATUS} UNHANDLED)
exten => s-CONGESTION,2,Congestion(30)
exten => s-CHANUNAVAIL,2,Congestion(30)
exten => s-ANSWER,2,NoOp(call was answered: ${DIALSTATUS})
exten => s-BUSY,2,Set(PRI_CAUSE=17)
exten => s-BUSY,3,Busy(9)
exten => s-BUSY,4,Hangup

[sample]
include => dialstatus
exten => _X.,1,NoOp(${CONTEXT} dialing)
exten => _X.,2,Answer
exten => _X.,3,ResetCDR()

exten => _X.,4,SetAMAFlags(BILLING)
exten => _X.,5,Wait(1)
exten => _X.,6,Playback(helloworld)
exten => _X.,7,Dial(SIP/${EXTEN}@openface)

exten => s,1,NoOp(fellthrough to s,1 in ${CONTEXT})
exten => s,2,Playback(cannot-complete-as-dialed)
exten => s,3,Congestion(30)


Local

Dec 23 12:00:17 DEBUG[10295] manager.c: Manager received command ‘Originate’
Dec 23 12:00:17 DEBUG[10296] chan_sip.c: Setting NAT on RTP to 0
Dec 23 12:00:17 DEBUG[10296] acl.c: ##### Testing xxx.xxx.xxx.xxx with xxx.xxx.xxx.xxx
Dec 23 12:00:17 DEBUG[10296] chan_sip.c: Target address xxx.xxx.xxx.xxx is not local, substituting externip
Dec 23 12:00:17 DEBUG[10296] chan_sip.c: Outgoing Call for 1514xxxxxxx
Dec 23 12:00:17 DEBUG[30472] chan_sip.c: Acked pending invite 102
Dec 23 12:00:17 DEBUG[30472] chan_sip.c: Stopping retransmission on '52520a9b139153c42489623a4f0c7208@xxx.xxx.xxx.xxx’ of Request 102: Match Found
Dec 23 12:00:17 DEBUG[30472] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘525
20a9b139153c42489623a4f0c7208@xxx.xxx.xxx.xxx’ Request 103: Found
Dec 23 12:00:17 DEBUG[30472] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘525
20a9b139153c42489623a4f0c7208@xxx.xxx.xxx.xxx’ Request 103: Found
Dec 23 12:00:20 DEBUG[30472] chan_sip.c: Acked pending invite 103
Dec 23 12:00:20 DEBUG[30472] chan_sip.c: Stopping retransmission on '6139b6d811708d16636f7a315b525e21@xxx.xxx.xxx.xxx’ of Request 103: Match Found
Dec 23 12:00:20 DEBUG[30472] chan_sip.c: build_route: Contact hop: sip:1888xxxxxxx@xxx.xxx.xxx.xxx
Dec 23 12:00:20 VERBOSE[10290] logger.c: – SIP/openface-09c3c2f0 answered SIP/openface-09bfc440
Dec 23 12:00:27 DEBUG[30472] chan_sip.c: Acked pending invite 103
Dec 23 12:00:27 DEBUG[30472] chan_sip.c: Stopping retransmission on '52520a9b139153c42489623a4f0c7208@xxx.xxx.xxx.xxx’ of Request 103: Match Found
Dec 23 12:00:27 DEBUG[30472] chan_sip.c: build_route: Contact hop: sip:1514xxxxxxxx@xxx.xxx.xxx.xxx
Dec 23 12:00:27 DEBUG[30430] channel.c: Avoiding initial deadlock for 'SIP/openface-09c42e30’
Dec 23 12:00:27 VERBOSE[10298] logger.c: – Executing NoOp(“SIP/openface-09c42e30” in new stack
Dec 23 12:00:27 VERBOSE[10298] logger.c: – Executing Answer() in new stack
Dec 23 12:00:27 VERBOSE[10298] logger.c: – Executing ResetCDR(“SIP/openface-09c42e30”, “”) in new stack
Dec 23 12:00:27 VERBOSE[10298] logger.c: – Executing SetAMAFlags(“SIP/openface-09c42e30”, “BILLING”) in new stack
Dec 23 12:00:27 VERBOSE[10298] logger.c: – Executing Wait(“SIP/openface-09c42e30”, “2”) in new stack


Long Distance

Dec 23 12:11:30 DEBUG[10564] manager.c: Manager received command ‘Originate’
Dec 23 12:11:30 DEBUG[10565] chan_sip.c: Setting NAT on RTP to 0
Dec 23 12:11:30 DEBUG[10565] acl.c: ##### Testing xxx.xxx.xxx.xxx with xxx.xxx.xxx.xxx
Dec 23 12:11:30 DEBUG[10565] chan_sip.c: Target address xxx.xxx.xxx.xxx is not local, substituting externip
Dec 23 12:11:30 DEBUG[10565] chan_sip.c: Outgoing Call for 1416xxxxxxx
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: Acked pending invite 102
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: Stopping retransmission on '65e0b821064412e6039d6d2e193624c4@xxx.xxx.xxx.xxx’ of Request 102: Match Found
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘65e
0b821064412e6039d6d2e193624c4@xxx.xxx.xxx.xxx’ Request 103: Found
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: Acked pending invite 103
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: Stopping retransmission on '65e0b821064412e6039d6d2e193624c4@xxx.xxx.xxx.xxx’ of Request 103: Match Found
Dec 23 12:11:30 DEBUG[30472] chan_sip.c: build_route: Contact hop: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
Dec 23 12:11:30 DEBUG[30430] channel.c: Avoiding initial deadlock for 'SIP/openface-09c19070’
Dec 23 12:11:30 VERBOSE[10566] logger.c: – Executing NoOp(“SIP/openface-09c19070”) in new stack
Dec 23 12:11:30 VERBOSE[10566] logger.c: – Executing Answer() in new stack
Dec 23 12:11:30 VERBOSE[10566] logger.c: – Executing ResetCDR(“SIP/openface-09c19070”, “”) in new stack
Dec 23 12:11:30 VERBOSE[10566] logger.c: – Executing SetAMAFlags(“SIP/openface-09c19070”, “BILLING”) in new stack
Dec 23 12:11:30 VERBOSE[10566] logger.c: – Executing Wait(“SIP/openface-09c19070”, “2”) in new stack

post up your SIP debugging output so we can take a look. To me it appears everything is fine on your end. The flow of the two calls (regardless of timing) looks fine. In reality the concept of local and long distance is pretty blurry in the SIP paradigm.

I am guessing it’s a problem with your VoIP provider, but looking at some debug might help solidify that theory.

It is only the first leg and after answer we sent hangup without dialing the second number.

This is the SIP debug output:


IMSCLI> sip debug
SIP Debugging enabled
IMS
CLI>
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Manager ‘XXX-XXXX’ logged on from xxx.xxx.xxx.xxx
We’re at xxx.xxx.xxx.xxx port 18184
Adding codec 0x4 (ulaw) to SDP
== Manager ‘XXX-XXXX’ logged off from xxx.xxx.xxx.xxx
Adding codec 0x8 (alaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
13 headers, 12 lines
Reliably Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
INVITE sip:1416xxxxxxx@provider SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK2839feae;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider
Contact: sip:1647xxxxxxx@xxx.xxx.xxx.xxx
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Dec 2008 18:17:09 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: applicat다ion/sdp
Content-Length: 269

v=0
o=root 30386 30386 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 18184 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -


IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK2839feae;received=xxx.xxx.xxx.xxx;rport=5060
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as7e250832
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 102 INVITE
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Proxy-Authenticate: Digest algorithm=MD5, realm=“provider”, nonce="630d8a44"
Content-Length: 0

— (10 headers 0 lines) —
Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
ACK sip:1416xxxxxxx@provider SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK2839feae;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as7e250832
Contact: sip:1647xxxxxxx@xxx.xxx.xxx.xxx
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


We’re at xxx.xxx.xxx.xxx port 18184
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x8 (alaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
INVITE sip:1416xxxxxxx@provider SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5d0f1ddb;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider
Contact: sip:1647xxxxxxx@xxx.xxx.xxx.xxx
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Proxy-Authorization: Digest username=“username”, realm=“provider”, algorithm=MD5, uri=“sip:1416xxxxxxx@provider”, nonce=“630d8a44”, response=“32558e1d61a74c8ae427d2681baa2efd”, opaque=""
Date: Tue, 23 Dec 2008 18:17:09 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 269

v=0
o=root 30386 30387 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 18184 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -


IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5d0f1ddb;received=xxx.xxx.xxx.xxx;rport=5060
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 INVITE
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
Content-Length: 0

— (10 headers 0 lines) —
IMSCLI>
IMS
CLI>
IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5d0f1ddb;received=xxx.xxx.xxx.xxx;rport=5060
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 INVITE
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
Content-Type: application/sdp
Content-Length: 261

v=0
o=root 23104 23104 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 23226 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

— (11 headers 12 lines) —
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 101
Peer audio RTP is at port xxx.xxx.xxx.xxx:23226
Found description format PCMU
Found description format PCMA
Found description format GSM
Found description format telephone-event
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
list_route: hop: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
set_destination: Parsing sip:1416xxxxxxx@xxx.xxx.xxx.xxx for address/port to send to
set_destination: set destination to xxx.xxx.xxx.xxx, port 5060
Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
ACK sip:1416xxxxxxx@xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK55ad9758;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Contact: sip:1647xxxxxxx@xxx.xxx.xxx.xxx
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0



IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5d0f1ddb;received=xxx.xxx.xxx.xxx;rport=5060
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 INVITE
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
Content-Type: application/sdp
Content-Length: 261

v=0
o=root 23104 23104 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 23226 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

— (11 headers 12 lines) —
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 101
Peer audio RTP is at port xxx.xxx.xxx.xxx:23226
Found description format PCMU
Found description format PCMA
Found description format GSM
Found description format telephone-event
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
set_destination: Parsing sip:1416xxxxxxx@xxx.xxx.xxx.xxx for address/port to send to
set_destination: set destination to xxx.xxx.xxx.xxx, port 5060
Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
ACK sip:1416xxxxxxx@xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK0080137e;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Contact: sip:1647xxxxxxx@xxx.xxx.xxx.xxx
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 103 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


Scheduling destruction of call '52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx’ in 32000 ms
set_destination: Parsing sip:1416xxxxxxx@xxx.xxx.xxx.xxx for address/port to send to
set_destination: set destination to xxx.xxx.xxx.xxx, port 5060
Reliably Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
BYE sip:1416xxxxxxx@xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5816c969;rport
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 104 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Proxy-Authorization: Digest username=“username”, realm=“provider”, algorithm=MD5, uri="sip:1416xxxxxxx@xxx.xxx.xxx.xxx", nonce=“630d8a44”, response=“6f01b32f3d8673f84d462ffe90edc9fc”, opaque=""
Content-Length: 0


IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK5816c969;received=xxx.xxx.xxx.xxx;rport=5060
From: “1647xxxxxxx” sip:1647xxxxxxx@xxx.xxx.xxx.xxx;tag=as28860a60
To: sip:1416xxxxxxx@provider;tag=as73fd2fa7
Call-ID: 52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
CSeq: 104 BYE
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:1416xxxxxxx@xxx.xxx.xxx.xxx
Content-Length: 0
X-Asterisk-HangupCause: Unallocated (unassigned) number

— (11 headers 0 lines) —
Destroying call '52f6bcaa33c181a522f6d62e4f2742f1@xxx.xxx.xxx.xxx
Destroying call '43e6324c47c3816b230d73f653197208@127.0.0.1’
12 headers, 0 lines
Reliably Transmitting (no NAT) to xxx.xxx.xxx.xxx:5060:
OPTIONS sip:provider SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK487a36d5;rport
From: “asterisk” sip:asterisk@xxx.xxx.xxx.xxx;tag=as567fd04a
To: sip:provider
Contact: sip:asterisk@xxx.xxx.xxx.xxx
Call-ID: 31b00d9a46d6d62b432511f9264b3d7f@xxx.xxx.xxx.xxx
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Dec 2008 18:17:16 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


IMS*CLI>
<-- SIP read from xxx.xxx.xxx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK487a36d5;received=xxx.xxx.xxx.xxx;rport=5060
From: “asterisk” sip:asterisk@xxx.xxx.xxx.xxx;tag=as567fd04a
To: sip:provider;tag=as4260a0c0
Call-ID: 31b00d9a46d6d62b432511f9264b3d7f@xxx.xxx.xxx.xxx
CSeq: 102 OPTIONS
User-Agent: Provider PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:xxx.xxx.xxx.xxx
Accept: application/sdp
Content-Length: 0

— (11 headers 0 lines) —
Destroying call '31b00d9a46d6d62b432511f9264b3d7f@xxx.xxx.xxx.xxx
IMSCLI>
IMS
CLI>
IMSCLI>
IMS
CLI> sip no debug
SIP Debugging Disabled
IMS*CLI>

The only thing I see which is odd are some retransmissions during the SIP transaction.

Can you post you “full” log that coincides with this particular SIP trace?

INVITE
<<<< 407 Proxy Authentication Required

ACK
INVITE (with Proxy Auth)
<<<< 100 TRYING
<<<< 200 OK

ACK
<<<< 200 OK (re-transmission of previous OK)

ACK (retransmission of previous ACK)
BYE
<<<< 200 OK