Suddenly can't dial out

abcym15 · March 25, 2018, 10:00am

Hello,
I have had a FreePBX install (14.0.1.19) running for 2 months connected to a Grandstream GXW4104. Inbound and outbound calling have been working fine until today, when all of a sudden I can’t dial out. Inbound calling is still fine.

When dialling out I get the message ‘The number you have dialled is not in service’.

[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] app_dial.c: Called SIP/GXWT1/01234567890
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s@macro-dialout-trunk:29] NoOp(“SIP/205-00000021”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 1”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s@macro-dialout-trunk:30] GotoIf(“SIP/205-00000021”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“SIP/205-00000021”, “RC=1”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“SIP/205-00000021”, “1,1”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx_builtins.c: Goto (macro-dialout-trunk,1,1)
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [1@macro-dialout-trunk:1] Goto(“SIP/205-00000021”, “s-INVALIDNMBR,1”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx_builtins.c: Goto (macro-dialout-trunk,s-INVALIDNMBR,1)
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:1] NoOp(“SIP/205-00000021”, “Dial failed due to trunk reporting Address Incomplete - giving up”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:2] Progress(“SIP/205-00000021”, “”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:3] Playback(“SIP/205-00000021”, “ss-noservice,noanswer”) in new stack
[2018-03-25 10:53:59] VERBOSE[12793][C-0000001a] file.c: <SIP/205-00000021> Playing ‘ss-noservice.ulaw’ (language ‘en_GB’)

The only thing I can think of is that we changed to British Summer Time today (GMT+1) but the time on the server is correct, and I can’t find the time on the gateway but the NTP servers and time zone are correct.

I have another trunk set up with an Obi110 and this also has the same issue. But, if i add a trunk to another SIP provider, it works fine.

Can anyone shed any light on why this would happen?

PitzKey · March 25, 2018, 10:39am

Can you double check your Trunk outbound settings and dial strings if they are correct? (you can get instructions from your provider)
I know in the US most providers requires to send 11 digits, not sure about the UK.

abcym15 · March 25, 2018, 10:52am

Yep, all seem correct - nothing has been changed at all since this time yesterday when they were working fine. It’s strange!

Stewart1 · March 25, 2018, 1:05pm

Strange problem. The actual error may differ from what is being reported. Try:
sip set debug on
at the Asterisk command line to see whether the correct number format is presented to the gateway and what error status is returned. I would assume that you should see e.g.
INVITE sip:[email protected]:5060 SIP/2.0
(The SIP conversation will appear both in the Asterisk log and on the command line if you remain connected to it.)

IMO the OBi has better debug tools than the Grandstream. For starters, what (if anything) appears in Status -> Call History for a failed call? If needed, in System Management -> Device Admin you can set up a syslog server and see whether you have a problem with digit maps, outbound call route, etc.

System Management -> Network Settings will show its idea of current local time and the settings used to determine that.

abcym15 · March 28, 2018, 7:16pm

Hello,
Thanks so much for the advice. I have looked at a debug and the correct number format is being presented to the gateway, but the error status returned seems to be 401 Unauthorized.

<— Reliably Transmitting (NAT) to XX.XX.XXX.XX:2951 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XXX.XX:2951;branch=z9hG4bK7Ftm3wNFZxTZ7qmc;received=XX.XX.XXX.XX;rport=2951
From: “AC” sip:205@PBXADDRESS;tag=7EF0594B866AE99C1BAD87781E75D0E3
To: sip:01234567890@PBXADDRESS;tag=as30713a26
Call-ID: 76F912B2EBB8E8224499D7D25718FDFBB07E7021
CSeq: 1 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“4327d3a8”
Content-Length: 0

Call History on the Obi shows nothing at all when trying to make an outbound call. The time zone setting on the Obi is fine, as DST was set up correctly.

Stewart1 · March 28, 2018, 7:38pm

The 401 you posted appears to be a response sent from the PBX to extension 205. It’s not necessarily an error; normally the extension would send an ACK then resend the INVITE with an Authorization header, which should then be accepted.

Are there any INVITE packets sent from the PBX to the OBi? If so, what happens after that? If not, can you see why (OBi isn’t registered, Outbound Route doesn’t go to that trunk, etc.)?

abcym15 · April 2, 2018, 3:25pm

Thanks again for your help - I am not 100% sure what I’m looking for here so have some more detailed log info:

<— SIP read from UDP:XXX.XXX.XXX.XXX:48892 —>
REGISTER sip:SIPSERVER:5060 SIP/2.0
Call-ID: [email protected]
Content-Length: 0
CSeq: 36166 REGISTER
From: sip:PSTNLINE@SIPSERVER;tag=SP22cc12aea5b6b12a3
Max-Forwards: 70
To: sip:PSTNLINE@SIPSERVER
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:48892;branch=z9hG4bK-5ae61fd8;rport
Authorization: DIGEST algorithm=MD5,nonce=“7ff3c6c4”,realm=“asterisk”,response=“bb4ffe07e598d966371a185cd5c746d6”,uri=“sip:SIPSERVER:5060”,username=“PSTNLINE”
User-Agent: OBIHAI/OBi110-1.3.0.2860
Contact: sip:[email protected]:48892;expires=60;+sip.instance=“urn:uuid:00000000-0000-0000-0000-9cadef01531a”
Allow: ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,REFER,UPDATE
Supported: replaces

<------------->
— (13 headers 0 lines) —
Sending to XXX.XXX.XXX.XXX:48892 (NAT)
[2018-04-02 16:19:01] NOTICE[1686]: chan_sip.c:17278 check_auth: Correct auth, but based on stale nonce received from ‘sip:PSTNLINE@SIPSERVER;tag=SP22cc12aea5b6b12a3’

<— Transmitting (NAT) to XXX.XXX.XXX.XXX:48892 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:48892;branch=z9hG4bK-5ae61fd8;received=XXX.XXX.XXX.XXX;rport=48892
From: sip:PSTNLINE@SIPSERVER;tag=SP22cc12aea5b6b12a3
To: sip:PSTNLINE@SIPSERVER;tag=as2c7f3bab
Call-ID: [email protected]
CSeq: 36166 REGISTER
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“661e9dc4”, stale=true
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘[email protected]’ in 32000 ms (Method: REGISTER)

<— SIP read from UDP:XXX.XXX.XXX.XXX:48892 —>
REGISTER sip:SIPSERVER:5060 SIP/2.0
Call-ID: [email protected]
Content-Length: 0
CSeq: 36167 REGISTER
From: sip:PSTNLINE@SIPSERVER;tag=SP22cc12aea5b6b12a3
Max-Forwards: 70
To: sip:PSTNLINE@SIPSERVER
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:48892;branch=z9hG4bK-88969d8;rport
Authorization: DIGEST algorithm=MD5,nonce=“661e9dc4”,realm=“asterisk”,response=“a2848b869056b41d2bba406d96217916”,uri=“sip:SIPSERVER:5060”,username=“PSTNLINE”
User-Agent: OBIHAI/OBi110-1.3.0.2860
Contact: sip:[email protected]:48892;expires=60;+sip.instance=“urn:uuid:00000000-0000-0000-0000-9cadef01531a”
Allow: ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,REFER,UPDATE
Supported: replaces

<------------->
— (13 headers 0 lines) —
Sending to XXX.XXX.XXX.XXX:48892 (NAT)
Reliably Transmitting (NAT) to XXX.XXX.XXX.XXX:48892:
OPTIONS sip:[email protected]:48892 SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK02d24a2f;rport
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as534d40de
To: sip:[email protected]:48892
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-14.0.1.19(13.17.2)
Date: Mon, 02 Apr 2018 15:19:01 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<— Transmitting (NAT) to XXX.XXX.XXX.XXX:48892 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:48892;branch=z9hG4bK-88969d8;received=XXX.XXX.XXX.XXX;rport=48892
From: sip:PSTNLINE@SIPSERVER;tag=SP22cc12aea5b6b12a3
To: sip:PSTNLINE@SIPSERVER;tag=as2c7f3bab
Call-ID: [email protected]
CSeq: 36167 REGISTER
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 60
Contact: sip:[email protected]:48892;expires=60
Date: Mon, 02 Apr 2018 15:19:01 GMT
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘[email protected]’ in 32000 ms (Method: REGISTER)

<— SIP read from UDP:XXX.XXX.XXX.XXX:48892 —>
SIP/2.0 200 OK
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
Content-Length: 0
From: “Unknown” sip:[email protected];tag=as534d40de
To: sip:[email protected]:48892
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK02d24a2f;received=YYY.YYY.YYY.YYY;rport=5060

<------------->
— (7 headers 0 lines) —
Really destroying SIP dialog ‘[email protected]:5060’ Method: OPTIONS
– Remote UNIX connection
– Remote UNIX connection disconnected
– Remote UNIX connection
– Remote UNIX connection disconnected
– Remote UNIX connection
– Remote UNIX connection disconnected

<— SIP read from UDP:ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
INVITE sip:01234567890@SIPSERVER SIP/2.0
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;rport
Contact: sip:[email protected]:2925
Max-Forwards: 70
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY
Supported: replaces, path
To: sip:01234567890@SIPSERVER
Content-Type: application/sdp
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 1 INVITE
User-Agent: Acrobits Softphone/5.9
Content-Length: 362

v=0
o=- 6064877934 42815 IN IP4 172.26.170.170
s=hmnnshv
c=IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
t=0 0
m=audio 43930 RTP/AVP 0 8 9 103 102 3 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:102 iLBC/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:102 mode=20
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
<------------->
— (13 headers 14 lines) —
Sending to ZZZ.ZZZ.ZZZ.ZZZ:2925 (NAT)
Sending to ZZZ.ZZZ.ZZZ.ZZZ:2925 (NAT)
Using INVITE request as basis request - F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
Found peer ‘205’ for ‘205’ from ZZZ.ZZZ.ZZZ.ZZZ:2925

<— Reliably Transmitting (NAT) to ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;received=ZZZ.ZZZ.ZZZ.ZZZ;rport=2925
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 1 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“14435003”
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B’ in 13760 ms (Method: INVITE)
Retransmitting #1 (NAT) to ZZZ.ZZZ.ZZZ.ZZZ:2925:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;received=ZZZ.ZZZ.ZZZ.ZZZ;rport=2925
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 1 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“14435003”
Content-Length: 0

Retransmitting #2 (NAT) to ZZZ.ZZZ.ZZZ.ZZZ:2925:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;received=ZZZ.ZZZ.ZZZ.ZZZ;rport=2925
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 1 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“14435003”
Content-Length: 0

<— SIP read from UDP:ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
ACK sip:01234567890@SIPSERVER SIP/2.0
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;rport
Max-Forwards: 70
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
CSeq: 1 ACK
User-Agent: Acrobits Softphone/5.9
Content-Length: 0

<------------->
— (9 headers 0 lines) —

<— SIP read from UDP:ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
ACK sip:01234567890@SIPSERVER SIP/2.0
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;rport
Max-Forwards: 70
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
CSeq: 1 ACK
User-Agent: Acrobits Softphone/5.9
Content-Length: 0

<------------->
— (9 headers 0 lines) —

<— SIP read from UDP:ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
INVITE sip:01234567890@SIPSERVER SIP/2.0
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bK3R14bbSuUFTneRrP;rport
Contact: sip:[email protected]:2925
Max-Forwards: 70
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY
Supported: replaces, path
To: sip:01234567890@SIPSERVER
Content-Type: application/sdp
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 2 INVITE
Authorization: Digest username=“205”,realm=“asterisk”,algorithm=MD5,uri=“sip:01234567890@SIPSERVER”,nonce=“14435003”,response=“59db2506905aa8d91c574920f8e32326”
User-Agent: Acrobits Softphone/5.9
Content-Length: 362

v=0
o=- 6064877934 42815 IN IP4 172.26.170.170
s=hmnnshv
c=IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
t=0 0
m=audio 43930 RTP/AVP 0 8 9 103 102 3 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:102 iLBC/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:102 mode=20
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
<------------->
— (14 headers 14 lines) —
Sending to ZZZ.ZZZ.ZZZ.ZZZ:2925 (NAT)
Using INVITE request as basis request - F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
Found peer ‘205’ for ‘205’ from ZZZ.ZZZ.ZZZ.ZZZ:2925
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 9
Found RTP audio format 103
Found RTP audio format 102
Found RTP audio format 3
Found RTP audio format 101
Found audio description format telephone-event for ID 101
Found audio description format iLBC for ID 102
Found audio description format opus for ID 103
Capabilities: us - (ulaw|alaw|gsm|g726|g722), peer - audio=(ulaw|gsm|alaw|g722|ilbc|opus)/video=(nothing)/text=(nothing), combined - (ulaw|alaw|gsm|g722)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port ZZZ.ZZZ.ZZZ.ZZZ:43930
Looking for 01234567890 in from-internal (domain SIPSERVER)
sip_route_dump: route/path hop: sip:[email protected]:2925

<— Transmitting (NAT) to ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bK3R14bbSuUFTneRrP;received=ZZZ.ZZZ.ZZZ.ZZZ;rport=2925
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 2 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:[email protected]:5060
Content-Length: 0

<------------>
– Executing [01234567890@from-internal:1] Macro(“SIP/205-00000189”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/205-00000189”, “TOUCH_MONITOR=1522682344.800”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/205-00000189”, “AMPUSER=205”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“SIP/205-00000189”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“SIP/205-00000189”, “1?Set(__REALCALLERIDNUM=205)”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/205-00000189”, “AMPUSER=205”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/205-00000189”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/205-00000189”, “AMPUSERCIDNAME=Anthony C”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“SIP/205-00000189”, “0?report”) in new stack
– Executing [s@macro-user-callerid:9] Set(“SIP/205-00000189”, “AMPUSERCID=205”) in new stack
– Executing [s@macro-user-callerid:10] Set(“SIP/205-00000189”, “__DIAL_OPTIONS=HhTtr”) in new stack
– Executing [s@macro-user-callerid:11] Set(“SIP/205-00000189”, “CALLERID(all)=“Anthony C” <205>”) in new stack
– Executing [s@macro-user-callerid:12] GotoIf(“SIP/205-00000189”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:13] ExecIf(“SIP/205-00000189”, “1?Set(GROUP(concurrency_limit)=205)”) in new stack
– Executing [s@macro-user-callerid:14] ExecIf(“SIP/205-00000189”, “0?Set(CHANNEL(language)=)”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/205-00000189”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,29)
– Executing [s@macro-user-callerid:29] Set(“SIP/205-00000189”, “CALLERID(number)=205”) in new stack
– Executing [s@macro-user-callerid:30] Set(“SIP/205-00000189”, “CALLERID(name)=Anthony C”) in new stack
– Executing [s@macro-user-callerid:31] GotoIf(“SIP/205-00000189”, “0?cnum”) in new stack
– Executing [s@macro-user-callerid:32] Set(“SIP/205-00000189”, “CDR(cnam)=Anthony C”) in new stack
– Executing [s@macro-user-callerid:33] Set(“SIP/205-00000189”, “CDR(cnum)=205”) in new stack
– Executing [s@macro-user-callerid:34] Set(“SIP/205-00000189”, “CHANNEL(language)=en_GB”) in new stack
– Executing [01234567890@from-internal:2] Gosub(“SIP/205-00000189”, “sub-record-check,s,1(out,01234567890,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/205-00000189”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“SIP/205-00000189”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“SIP/205-00000189”, “NOW=1522682344”) in new stack
– Executing [s@sub-record-check:4] Set(“SIP/205-00000189”, “__DAY=02”) in new stack
– Executing [s@sub-record-check:5] Set(“SIP/205-00000189”, “__MONTH=04”) in new stack
– Executing [s@sub-record-check:6] Set(“SIP/205-00000189”, “__YEAR=2018”) in new stack
– Executing [s@sub-record-check:7] Set(“SIP/205-00000189”, “__TIMESTR=20180402-161904”) in new stack
– Executing [s@sub-record-check:8] Set(“SIP/205-00000189”, “__FROMEXTEN=205”) in new stack
– Executing [s@sub-record-check:9] Set(“SIP/205-00000189”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“SIP/205-00000189”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/205-00000189”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/205-00000189”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/205-00000189”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/205-00000189”, “3?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/205-00000189”, “1?sub-record-check,out,1”) in new stack
– Goto (sub-record-check,out,1)
– Executing [out@sub-record-check:1] NoOp(“SIP/205-00000189”, “Outbound Recording Check from 205 to 01234567890”) in new stack
– Executing [out@sub-record-check:2] Set(“SIP/205-00000189”, “RECMODE=force”) in new stack
– Executing [out@sub-record-check:3] ExecIf(“SIP/205-00000189”, “0?Goto(routewins)”) in new stack
– Executing [out@sub-record-check:4] ExecIf(“SIP/205-00000189”, “0?Goto(routewins)”) in new stack
– Executing [out@sub-record-check:5] Gosub(“SIP/205-00000189”, “recordcheck,1(force,out,01234567890)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/205-00000189”, “Starting recording check against force”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/205-00000189”, “force”) in new stack
– Goto (sub-record-check,recordcheck,5)
– Executing [recordcheck@sub-record-check:5] Set(“SIP/205-00000189”, “__REC_POLICY_MODE=FORCE”) in new stack
– Executing [recordcheck@sub-record-check:6] GotoIf(“SIP/205-00000189”, “1?startrec”) in new stack
– Goto (sub-record-check,recordcheck,16)
– Executing [recordcheck@sub-record-check:16] NoOp(“SIP/205-00000189”, “Starting recording: out, 01234567890”) in new stack
– Executing [recordcheck@sub-record-check:17] Set(“SIP/205-00000189”, “AUDIOHOOK_INHERIT(MixMonitor)=yes”) in new stack
– Executing [recordcheck@sub-record-check:18] Set(“SIP/205-00000189”, “__CALLFILENAME=out-01234567890-205-20180402-161904-1522682344.800”) in new stack
– Executing [recordcheck@sub-record-check:19] MixMonitor(“SIP/205-00000189”, “2018/04/02/out-01234567890-205-20180402-161904-1522682344.800.wav,abi(LOCAL_MIXMON_ID),”) in new stack
– Executing [recordcheck@sub-record-check:20] Set(“SIP/205-00000189”, “__MIXMON_ID=0x7f9f08074ab0”) in new stack
– Executing [recordcheck@sub-record-check:21] Set(“SIP/205-00000189”, “__RECORD_ID=SIP/205-00000189”) in new stack
– Executing [recordcheck@sub-record-check:22] Set(“SIP/205-00000189”, “__REC_STATUS=RECORDING”) in new stack
– Executing [recordcheck@sub-record-check:23] Set(“SIP/205-00000189”, “CDR(recordingfile)=out-01234567890-205-20180402-161904-1522682344.800.wav”) in new stack
– Executing [recordcheck@sub-record-check:24] Return(“SIP/205-00000189”, “”) in new stack
– Executing [out@sub-record-check:6] Return(“SIP/205-00000189”, “”) in new stack
– Executing [01234567890@from-internal:3] ExecIf(“SIP/205-00000189”, “0 ?Set(CDR(accountcode)=)”) in new stack
– Executing [01234567890@from-internal:4] Set(“SIP/205-00000189”, “MOHCLASS=default”) in new stack
– Executing [01234567890@from-internal:5] Set(“SIP/205-00000189”, “_NODEST=”) in new stack
– Executing [01234567890@from-internal:6] Macro(“SIP/205-00000189”, “dialout-trunk,2,01234567890,off”) in new stack
– Executing [s@macro-dialout-trunk:1] Set(“SIP/205-00000189”, “DIAL_TRUNK=2”) in new stack
– Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/205-00000189”, “0?sub-pincheck,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/205-00000189”, “0?disabletrunk,1”) in new stack
– Executing [s@macro-dialout-trunk:4] Set(“SIP/205-00000189”, “DIAL_NUMBER=01234567890”) in new stack
– Executing [s@macro-dialout-trunk:5] Set(“SIP/205-00000189”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
– Executing [s@macro-dialout-trunk:6] Set(“SIP/205-00000189”, “OUTBOUND_GROUP=OUT_2”) in new stack
– Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/205-00000189”, “1?nomax”) in new stack
– Goto (macro-dialout-trunk,s,9)
– Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/205-00000189”, “0?skipoutcid”) in new stack
– Executing [s@macro-dialout-trunk:10] Set(“SIP/205-00000189”, “DIAL_TRUNK_OPTIONS=T”) in new stack
– Executing [s@macro-dialout-trunk:11] Macro(“SIP/205-00000189”, “outbound-callerid,2”) in new stack
– Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/205-00000189”, “0?Set(CALLERPRES(name-pres)=)”) in new stack
– Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/205-00000189”, “0?Set(CALLERPRES(num-pres)=)”) in new stack
– Executing [s@macro-outbound-callerid:3] ExecIf(“SIP/205-00000189”, “0?Set(REALCALLERIDNUM=205)”) in new stack
– Executing [s@macro-outbound-callerid:4] GotoIf(“SIP/205-00000189”, “1?normcid”) in new stack
– Goto (macro-outbound-callerid,s,7)
– Executing [s@macro-outbound-callerid:7] Set(“SIP/205-00000189”, “USEROUTCID=”) in new stack
– Executing [s@macro-outbound-callerid:8] Set(“SIP/205-00000189”, “EMERGENCYCID=”) in new stack
– Executing [s@macro-outbound-callerid:9] Set(“SIP/205-00000189”, “TRUNKOUTCID=”) in new stack
– Executing [s@macro-outbound-callerid:10] GotoIf(“SIP/205-00000189”, “1?trunkcid”) in new stack
– Goto (macro-outbound-callerid,s,15)
– Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/205-00000189”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/205-00000189”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/205-00000189”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:18] ExecIf(“SIP/205-00000189”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
– Executing [s@macro-outbound-callerid:19] ExecIf(“SIP/205-00000189”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
– Executing [s@macro-outbound-callerid:20] Set(“SIP/205-00000189”, “CDR(outbound_cnum)=205”) in new stack

<— SIP read from UDP:ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
ACK sip:01234567890@SIPSERVER SIP/2.0
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bKfGu5BBiXwSRdyaMI;rport
Max-Forwards: 70
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as5f384dde
CSeq: 1 ACK
User-Agent: Acrobits Softphone/5.9
Content-Length: 0

<------------->
— (9 headers 0 lines) —
– Executing [s@macro-outbound-callerid:21] Set(“SIP/205-00000189”, “CDR(outbound_cnam)=Anthony C”) in new stack
– Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/205-00000189”, “0?sub-flp-2,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:13] Set(“SIP/205-00000189”, “OUTNUM=01234567890”) in new stack
– Executing [s@macro-dialout-trunk:14] Set(“SIP/205-00000189”, “custom=SIP/PSTNLINE”) in new stack
– Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/205-00000189”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
– Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/205-00000189”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
– Executing [s@macro-dialout-trunk:17] Macro(“SIP/205-00000189”, “dialout-trunk-predial-hook,”) in new stack
– Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/205-00000189”, “”) in new stack
– Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/205-00000189”, “0?skipcrm”) in new stack
– Executing [s@macro-dialout-trunk:19] Set(“SIP/205-00000189”, “__CRM_DIRECTION=OUTBOUND”) in new stack
– Executing [s@macro-dialout-trunk:20] Set(“SIP/205-00000189”, “__CRM_DESTINATION=01234567890”) in new stack
– Executing [s@macro-dialout-trunk:21] Set(“SIP/205-00000189”, “__CRM_SOURCE=205”) in new stack
– Executing [s@macro-dialout-trunk:22] AGI(“SIP/205-00000189”, “sangomacrm.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
== Begin MixMonitor Recording SIP/205-00000189
– <SIP/205-00000189>AGI Script sangomacrm.agi completed, returning 0
– Executing [s@macro-dialout-trunk:23] Set(“SIP/205-00000189”, “CHANNEL(hangup_handler_push)=crm-hangup,s,1”) in new stack
– Executing [s@macro-dialout-trunk:24] NoOp(“SIP/205-00000189”, “CRM Finished”) in new stack
– Executing [s@macro-dialout-trunk:25] GotoIf(“SIP/205-00000189”, “0?bypass,1”) in new stack
– Executing [s@macro-dialout-trunk:26] ExecIf(“SIP/205-00000189”, “1?Set(CONNECTEDLINE(num,i)=01234567890)”) in new stack
– Executing [s@macro-dialout-trunk:27] GotoIf(“SIP/205-00000189”, “0?customtrunk”) in new stack
– Executing [s@macro-dialout-trunk:28] Dial(“SIP/205-00000189”, “SIP/PSTNLINE/01234567890,300,T”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Audio is at 16614
Adding codec ulaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to XXX.XXX.XXX.XXX:48892:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK0ce2ac51;rport
Max-Forwards: 70
From: “Anthony C” sip:[email protected];tag=as70ec5382
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-14.0.1.19(13.17.2)
Date: Mon, 02 Apr 2018 15:19:05 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 254

v=0
o=root 192411319 192411319 IN IP4 YYY.YYY.YYY.YYY
s=Asterisk PBX 13.17.2
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 16614 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
-- Called SIP/PSTNLINE/01234567890
<— SIP read from UDP:XXX.XXX.XXX.XXX:48892 —>
SIP/2.0 100 Trying
Call-ID: [email protected]:5060
CSeq: 102 INVITE
Content-Length: 0
From: “Anthony C” sip:[email protected];tag=as70ec5382
To: sip:[email protected];tag=SP22cc12aea5b6b12a3
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK0ce2ac51;received=YYY.YYY.YYY.YYY;rport=5060
Server: OBIHAI/OBi110-1.3.0.2860

<------------->
— (8 headers 0 lines) —

<— SIP read from UDP:XXX.XXX.XXX.XXX:48892 —>
SIP/2.0 486 Busy Here
Call-ID: [email protected]:5060
CSeq: 102 INVITE
Content-Length: 0
From: “Anthony C” sip:[email protected];tag=as70ec5382
To: sip:[email protected];tag=SP22cc12aea5b6b12a3
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK0ce2ac51;received=YYY.YYY.YYY.YYY;rport=5060
Server: OBIHAI/OBi110-1.3.0.2860

<------------->
— (8 headers 0 lines) —
– Got SIP response 486 “Busy Here” back from XXX.XXX.XXX.XXX:48892
Transmitting (NAT) to XXX.XXX.XXX.XXX:48892:
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK0ce2ac51;rport
Max-Forwards: 70
From: “Anthony C” sip:[email protected];tag=as70ec5382
To: sip:[email protected];tag=SP22cc12aea5b6b12a3
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: FPBX-14.0.1.19(13.17.2)
Content-Length: 0
-- SIP/PSTNLINE-0000018a is busy
== Everyone is busy/congested at this time (1:1/0/0)
– Executing [s@macro-dialout-trunk:29] NoOp(“SIP/205-00000189”, “Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17”) in new stack
– Executing [s@macro-dialout-trunk:30] GotoIf(“SIP/205-00000189”, “0?continue,1:s-BUSY,1”) in new stack
– Goto (macro-dialout-trunk,s-BUSY,1)
– Executing [s-BUSY@macro-dialout-trunk:1] NoOp(“SIP/205-00000189”, “Dial failed due to trunk reporting BUSY - giving up”) in new stack
– Executing [s-BUSY@macro-dialout-trunk:2] PlayTones(“SIP/205-00000189”, “busy”) in new stack
[2018-04-02 16:19:05] WARNING[26088][C-00000633]: translate.c:407 framein: no samples for ulawtolin
– Executing [s-BUSY@macro-dialout-trunk:3] Busy(“SIP/205-00000189”, “20”) in new stack

<— Reliably Transmitting (NAT) to ZZZ.ZZZ.ZZZ.ZZZ:2925 —>
SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP ZZZ.ZZZ.ZZZ.ZZZ:2925;branch=z9hG4bK3R14bbSuUFTneRrP;received=ZZZ.ZZZ.ZZZ.ZZZ;rport=2925
From: “Anthony C” sip:205@SIPSERVER;tag=20ACEB9E71BCCD97699AAE4FD9398D7B
To: sip:01234567890@SIPSERVER;tag=as6514128f
Call-ID: F434F1AFF89E090B8CBF3FD1D9212ADF5949EA3B
CSeq: 2 INVITE
Server: FPBX-14.0.1.19(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-Asterisk-HangupCause: User busy
X-Asterisk-HangupCauseCode: 17
Content-Length: 0

<------------>
== Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on ‘SIP/205-00000189’ in macro ‘dialout-trunk’
== Spawn extension (from-internal, 01234567890, 6) exited non-zero on ‘SIP/205-00000189’
– Executing [h@from-internal:1] Macro(“SIP/205-00000189”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/205-00000189”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
Really destroying SIP dialog ‘[email protected]:5060’ Method: INVITE
– Executing [s@macro-hangupcall:3] ExecIf(“SIP/205-00000189”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:4] NoOp(“SIP/205-00000189”, " monior file= /var/spool/asterisk/monitor/2018/04/02/out-01234567890-205-20180402-161904-1522682344.800.wav") in new stack
– Executing [s@macro-hangupcall:5] AGI(“SIP/205-00000189”, “attendedtransfer-rec-restart.php,/var/spool/asterisk/monitor/2018/04/02/out-01234567890-205-20180402-161904-1522682344.800.wav”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php

cynjut · April 2, 2018, 3:43pm

Your OBI says the line is busy.

abcym15 · April 2, 2018, 4:14pm

Really strange. The line definitely isn’t busy, and when I dial in it picks up the call and works as normal, even hanging up properly so the Obi does know that it’s free. The Grandstream gateway - which is in a different physical location and connected to a totally different line - also still appears as being engaged.

I can’t work out why this would happen. I might have to factory reset one of the units and see what happens!

Stewart1 · April 4, 2018, 5:20am

Check the OBi Line Status before attempting an outbound call. You should see:
State: On Hook
LoopCurrent: 0 mA
TipRingVoltage; (magnitude between 40 and 60 V, polarity doesn’t matter).

Assuming that’s ok, set up syslog on the OBi; it’s under System Management -> Device Admin. Attempt a call and with luck it will tell you why it is returning a 486 Busy Here status.

system · April 4, 2019, 5:20am

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.