Obi212 claims 'service unavailable'

[DrBourne]

whooo hoooo!
Got my Obi212, replacing Obi110 with defective line port(thanks drgeoff).
So far so good. With one major exception, Obi always reports 'service unavailable'.

Most configuration derived from;
https://www.wrbishop.com/telecom/end-robocaller-solicitation-and-hangup-calls-with-asterisk/

Other minor problems(?, didn't seem so at the time) overcome by browsing forums. But, I am lost ...

No problem(noted) with outgoing calls
Incoming calls ring in, but are reported as 'Call Failed (503 Service Unavailable; SP2(1234567890)) in FreePBX call history and logged
in asteriskcdrdb.cdr table

BTW, no VOIPs in use, yet.

Unsure as to what to include other than cli capture;
1234567890 is obsfucated home phone number.
0987654321 is obsfucated cell number.
192.168.254.16 is rasPBX IP
192.168.254.30 is asterisk IP

[Aug 25 13:27:13] Connected to Asterisk 13.20.0 currently running on raspbx (pid = 1092)
[Aug 25 13:33:33]   == Using SIP RTP TOS bits 184
[Aug 25 13:33:33]   == Using SIP RTP CoS mark 5
[Aug 25 13:33:33]        > 0x73d06818 -- Strict RTP learning after remote address set to: 192.168.254.30:16804
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk-sip-OBITRUNK1:1] Set("SIP/OBITRUNK1-00000000", "GROUP()=OUT_1") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk-sip-OBITRUNK1:2] Goto("SIP/OBITRUNK1-00000000", "from-trunk,1234567890,1") in new stack
[Aug 25 13:33:33]     -- Goto (from-trunk,1234567890,1)
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:1] Set("SIP/OBITRUNK1-00000000", "__DIRECTION=INBOUND") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:2] Gosub("SIP/OBITRUNK1-00000000", "sub-record-check,s,1(in,1234567890,dontcare)") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:1] GotoIf("SIP/OBITRUNK1-00000000", "0?initialized") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:2] Set("SIP/OBITRUNK1-00000000", "__REC_STATUS=INITIALIZED") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:3] Set("SIP/OBITRUNK1-00000000", "NOW=1566740013") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:4] Set("SIP/OBITRUNK1-00000000", "__DAY=25") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:5] Set("SIP/OBITRUNK1-00000000", "__MONTH=08") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:6] Set("SIP/OBITRUNK1-00000000", "__YEAR=2019") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:7] Set("SIP/OBITRUNK1-00000000", "__TIMESTR=20190825-133333") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:8] Set("SIP/OBITRUNK1-00000000", "__FROMEXTEN=unknown") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:9] Set("SIP/OBITRUNK1-00000000", "__MON_FMT=wav") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:10] NoOp("SIP/OBITRUNK1-00000000", "Recordings initialized") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:11] ExecIf("SIP/OBITRUNK1-00000000", "0?Set(ARG3=dontcare)") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:12] Set("SIP/OBITRUNK1-00000000", "REC_POLICY_MODE_SAVE=") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:13] ExecIf("SIP/OBITRUNK1-00000000", "0?Set(REC_STATUS=NO)") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:14] GotoIf("SIP/OBITRUNK1-00000000", "2?checkaction") in new stack
[Aug 25 13:33:33]     -- Goto (sub-record-check,s,17)
[Aug 25 13:33:33]     -- Executing [s@sub-record-check:17] GotoIf("SIP/OBITRUNK1-00000000", "1?sub-record-check,in,1") in new stack
[Aug 25 13:33:33]     -- Goto (sub-record-check,in,1)
[Aug 25 13:33:33]     -- Executing [in@sub-record-check:1] NoOp("SIP/OBITRUNK1-00000000", "Inbound Recording Check to 1234567890") in new stack
[Aug 25 13:33:33]     -- Executing [in@sub-record-check:2] Set("SIP/OBITRUNK1-00000000", "FROMEXTEN=unknown") in new stack
[Aug 25 13:33:33]     -- Executing [in@sub-record-check:3] ExecIf("SIP/OBITRUNK1-00000000", "10?Set(FROMEXTEN=0987654321)") in new stack
[Aug 25 13:33:33]     -- Executing [in@sub-record-check:4] Gosub("SIP/OBITRUNK1-00000000", "recordcheck,1(dontcare,in,1234567890)") in new stack
[Aug 25 13:33:33]     -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/OBITRUNK1-00000000", "Starting recording check against dontcare") in new stack
[Aug 25 13:33:33]     -- Executing [recordcheck@sub-record-check:2] Goto("SIP/OBITRUNK1-00000000", "dontcare") in new stack
[Aug 25 13:33:33]     -- Goto (sub-record-check,recordcheck,3)
[Aug 25 13:33:33]     -- Executing [recordcheck@sub-record-check:3] Return("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]     -- Executing [in@sub-record-check:5] Return("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:3] Set("SIP/OBITRUNK1-00000000", "CHANNEL(tonezone)=us") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:4] Set("SIP/OBITRUNK1-00000000", "__FROM_DID=1234567890") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:5] Set("SIP/OBITRUNK1-00000000", "returnhere=1") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:6] Gosub("SIP/OBITRUNK1-00000000", "app-blacklist-check,s,1()") in new stack
[Aug 25 13:33:33]     -- Executing [s@app-blacklist-check:1] GotoIf("SIP/OBITRUNK1-00000000", "0?blacklisted") in new stack
[Aug 25 13:33:33]     -- Executing [s@app-blacklist-check:2] Set("SIP/OBITRUNK1-00000000", "CALLED_BLACKLIST=1") in new stack
[Aug 25 13:33:33]     -- Executing [s@app-blacklist-check:3] Return("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:7] Set("SIP/OBITRUNK1-00000000", "CDR(did)=1234567890") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:8] GotoIf("SIP/OBITRUNK1-00000000", "0?") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:9] ExecIf("SIP/OBITRUNK1-00000000", "0 ?Set(CALLERID(name)=0987654321)") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:10] Set("SIP/OBITRUNK1-00000000", "CHANNEL(musicclass)=none") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:11] Set("SIP/OBITRUNK1-00000000", "__MOHCLASS=none") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:12] Set("SIP/OBITRUNK1-00000000", "__REVERSAL_REJECT=FALSE") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:13] GotoIf("SIP/OBITRUNK1-00000000", "1?post-reverse-charge") in new stack
[Aug 25 13:33:33]     -- Goto (from-trunk,1234567890,15)
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:15] NoOp("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:16] Set("SIP/OBITRUNK1-00000000", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:17] Set("SIP/OBITRUNK1-00000000", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:18] Set("SIP/OBITRUNK1-00000000", "CALLERID(name-pres)=allowed_not_screened") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:19] Set("SIP/OBITRUNK1-00000000", "CALLERID(num-pres)=allowed_not_screened") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:20] NoOp("SIP/OBITRUNK1-00000000", "CallerID Entry Point") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:21] Macro("SIP/OBITRUNK1-00000000", "prepend-cid,POTS-") in new stack
[Aug 25 13:33:33]     -- Executing [s@macro-prepend-cid:1] GotoIf("SIP/OBITRUNK1-00000000", "1?REPCID") in new stack
[Aug 25 13:33:33]     -- Goto (macro-prepend-cid,s,5)
[Aug 25 13:33:33]     -- Executing [s@macro-prepend-cid:5] Set("SIP/OBITRUNK1-00000000", "_RGPREFIX=POTS-") in new stack
[Aug 25 13:33:33]     -- Executing [s@macro-prepend-cid:6] Set("SIP/OBITRUNK1-00000000", "CALLERID(name)=POTS-Bourne Dale") in new stack
[Aug 25 13:33:33]     -- Executing [1234567890@from-trunk:22] Goto("SIP/OBITRUNK1-00000000", "ext-trunk,1,1") in new stack
[Aug 25 13:33:33]     -- Goto (ext-trunk,1,1)
[Aug 25 13:33:33]     -- Executing [1@ext-trunk:1] Set("SIP/OBITRUNK1-00000000", "TDIAL_STRING=SIP/OBITRUNK1") in new stack
[Aug 25 13:33:33]     -- Executing [1@ext-trunk:2] Set("SIP/OBITRUNK1-00000000", "DIAL_TRUNK=1") in new stack
[Aug 25 13:33:33]     -- Executing [1@ext-trunk:3] Goto("SIP/OBITRUNK1-00000000", "ext-trunk,tdial,1") in new stack
[Aug 25 13:33:33]     -- Goto (ext-trunk,tdial,1)
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:1] Set("SIP/OBITRUNK1-00000000", "OUTBOUND_GROUP=OUT_1") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:2] GotoIf("SIP/OBITRUNK1-00000000", "1?nomax") in new stack
[Aug 25 13:33:33]     -- Goto (ext-trunk,tdial,4)
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:4] ExecIf("SIP/OBITRUNK1-00000000", "1?Set(CALLERPRES(name-pres)=allowed_not_screened)") in new stack
[2019-08-25 13:33:33] WARNING[3715][C-00000000]: func_callerid.c:953 callerpres_write: CALLERPRES is deprecated.  Use CALLERID(name-pres) or CALLERID(num-pres) instead.
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:5] ExecIf("SIP/OBITRUNK1-00000000", "1?Set(CALLERPRES(num-pres)=allowed_not_screened)") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:6] Set("SIP/OBITRUNK1-00000000", "DIAL_NUMBER=1234567890") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:7] GosubIf("SIP/OBITRUNK1-00000000", "1?sub-flp-1,s,1()") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-flp-1:1] ExecIf("SIP/OBITRUNK1-00000000", "0?Return()") in new stack
[Aug 25 13:33:33]     -- Executing [s@sub-flp-1:2] Return("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:8] Set("SIP/OBITRUNK1-00000000", "OUTNUM=1234567890") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:9] Set("SIP/OBITRUNK1-00000000", "DIAL_TRUNK_OPTIONS=T") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:10] Dial("SIP/OBITRUNK1-00000000", "SIP/OBITRUNK1/1234567890,300,T") in new stack
[Aug 25 13:33:33]   == Using SIP RTP TOS bits 184
[Aug 25 13:33:33]   == Using SIP RTP CoS mark 5
[Aug 25 13:33:33]     -- Called SIP/OBITRUNK1/1234567890
[Aug 25 13:33:33]     -- Got SIP response 503 "Service Unavailable" back from 192.168.254.30:5160
[Aug 25 13:33:33]     -- SIP/OBITRUNK1-00000001 is circuit-busy
[Aug 25 13:33:33]   == Everyone is busy/congested at this time (1:0/1/0)
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:11] Set("SIP/OBITRUNK1-00000000", "CALLERID(number)=0987654321") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:12] Set("SIP/OBITRUNK1-00000000", "CALLERID(name)=POTS-Bourne Dale") in new stack
[Aug 25 13:33:33]     -- Executing [tdial@ext-trunk:13] Hangup("SIP/OBITRUNK1-00000000", "") in new stack
[Aug 25 13:33:33]   == Spawn extension (ext-trunk, tdial, 13) exited non-zero on 'SIP/OBITRUNK1-00000000'
raspbx*CLI>

My appologies for long post, but at this point I'm getting frustrated and desperate.

TIA,
Dale

[drgeoff]

The two links in and configuring an OBi110 as an FXO gateway (FreePBX guide).    Follow step 1 in "configuring an IBi110" don't work.  I don't know how you are configuring the 212 but the problem would appear to be there.

Does the OBi's Call History show the call attempt from the PBX back to the OBi?

[DrBourne]

Thanks drgeoff,

OBi appears to be responding to asterisk attempt with the 'Call Failed....', if I understand the following
call OBi record correctly;

12:55:21   From 'Bourne Dale' LI1(0987654321)   Fork to: PH1 SP2(1234567890)
12:55:21                              Ringing (PH1)
12:55:21                              Call Failed (503 Service Unavailable; SP2(1234567890))
12:55:30                              Call Connected (PH1)
12:55:43                              Call Ended

I suspect the 'ph,' in the line port InboundCallRoute is the OBi ringing the phone.
As a test, I deleted the ph, from the ITSP B InboundCallRoute.
Resulting log data remained the same. Only my phone did not ring this time.
So, I put it back. For wife's medical situation, I HAVE TO have a functioning phone.

I appologize for the dead link in Mr. Bishop's page, I was using a local copy.
Link should point to this;
https://wiki.freepbx.org/pages/viewpage.action?pageId=4161594


My current config;

Service Providers      ITSP A               ITSP B
ProxyServer         192.168.254.16         192.168.254.16
X_AccessList         192.168.254.16         192.168.254.16
ProxyServerPort      5160               5160
RegistrarServerPort   5160               5160
OutboundProxyPort    5160               5160
X_EchoServerPort      5160               5160
X_UseRefer         Checked
X_SpoofCallerID                        Checked

Voice Services         SP1 Service            SP2 Service
X_ServProvProfile       A                  B
X_InboundCallRoute   ph                   LI
X_KeepAliveServerPort    5160               5160
X_UserAgentPort       5160               5160
AuthUserName       PHONE               OBITRUNK1
AuthPassword          secret               secret
URI               PHONE@192.168.254.16   OBITRUNK1@192.168.254.16

Physical Interfaces      PHONE1 Port            LINE Port
PrimaryLine         PSTN Line
InboundCallRoute                         ph,SP2(1234567890)


I hope I included enough info to be useful.

Thanks again for helping me deduce the dead line port on my 110. Too bad there is no warranty. A $50 lesson, CHECK FOR WARRANTY!!

Dale

[drgeoff]

You have instructed the OBi212 to ring both the phone plugged into its PHONE port and the actual number that you represent by 1234567890.  The OBi212 is attempting to reach that number using the Service Provider you have configured on SP2, but not succeeding.

Have you configured the FreePBX details on SP2? And have you configured FreePBX to handle SP2 calls from the OBi?

By default a call dialled on the phone will use SP2 if you precede the number by **2.  If you dial **2 1234567890 what happens?

(I am not showing the actual 82... number as you may wish to edit your post to redact it and the other 82... number.)

[DrBourne]

Sorry for taking so long to respond. I needed to stop obsessing, step back and stop grabbing at straws.
I've been reading through(not completely though, yet) the 'Admin Guides', but haven't gleaned anything directly relating to my problem.

I totally do not understand how the OBi and Asterisk interact.
Supposing that the ph, in the InboundCallRoute was causing OBi to ring the phone before Asterisk could implement the 'Executing [tdial@ext-trunk:10] Dial("SIP/OBITRUNK1-00000000", "SIP/OBITRUNK1/home-nmbr,300,T") in new stack', I deleted it. While my phone did not ring, the result was still '-- Got SIP response 503 "Service Unavailable" back from 192.168.254.30:5160'.

BTW, going the other direction, deleting 'SP2(home-nmbr)'; phone rings, but Asterisk is 'out of the loop', it didn't respond at all. Which is what one would expect, I guess.

As far as 'Have you configured an operational ITSP on SP2?', my only 'configuration' is as listed previously. Did I miss something in this regard?

"Have you configured the FreePBX details on SP2? And have you configured FreePBX to handle SP2 calls from the OBi?"
I have select chan_sip as opposed to 'both'. The only other mod was allowing sip guests.
Just guessing here, but, since Asterisk tries to react to the incoming call, that it is at least aware that the OBi is 'talking' to it.

Using the **2 then home-nmbr results in 'the number you have dialed is not in service....'.

Maybe understanding the interaction between OBi and Asterisk would help me figure this out.
My suppositions;
1. OBi get an incoming call signal(whatever that may be) on it's LINE port;
2. Passes the CallerID, and likely much other info to asterisk to react too.
3. Asterisk appears to understand and attempts to react by attempting to 'call' the attached phone.

At this point, I am of the opinion that my OBi is probably configured wrongly.
From Asterisk's POV, is the OBi is a SIP(or VOIP) service or source?
Is there anything available that will define how the are supposed to work together?