QUESTION A weird behavior of DISA - can anyone help?

[dbdataplus]

Background info
FreePBX 2.11.0.37
Asterisk 11.7.0
I have two phones in my home office:
an AT&T POTS line and an internet phone.

The problem
I set up a DISA "123" on the main IVR.
I call the PBX from my internet phone and dial "123" I get the DISA prompt, put in the PIN and get a dial tone. I then dial 9+1+{phone number of my POTS} the pots phone on my desk rings. I answer and have a talk with myself and hang up both phones.

Now I call back. I use the Internet phone to dial the PBX, but I get a recording saying that the {phone number of my Internet Phone} is not in service!! Logs show this recording is coming from the SIP provider to the PBX. (not the phone number I CALLED from my Internet phone - but my OWN number - the one I'm calling on at that moment.)

So, for giggles, I use my POTS phone to call the PBX/DISA and dial 9+1+{phone number of my internet phone}. It rings, I answer, I talk to myself and hang up both phones.
When I try AGAIN (calling from my internet phone to my POTS phone) I get a recording saying that {internet phone number} is not in service.

BOTH my phones (pots and internet) can call each other directly, either can call any OTHER number ... but when either is used to call the PBX, the log file shows that Integra Telecom is playing the "not in service" message and then playing the phone number I'm ON.

This condition lasts for about a half an hour during which time
-- neither of my phones can dial the main PBX
-- the main PBX is taking calls just fine for everyone else
-- my phones can dial other numbers just fine

It's as if the call chain never fully collapsed and Asterisk is waiting for a reconnect?

Here is a snippet of the log file (310328xxxx) is my POTS line number

[2014-07-30 17:10:20] VERBOSE[31483][C-000038b9] app_dial.c: -- SIP/109-000022d9 answered SIP/IntegraIn-000022d8
[2014-07-30 17:10:20] VERBOSE[32087] chan_sip.c: == Extension Changed 109[ext-local] new state InUse for Notify User 100
[2014-07-30 17:10:20] VERBOSE[32087] chan_sip.c: == Extension Changed 109[ext-local] new state InUse for Notify User 101
[2014-07-30 17:10:36] VERBOSE[32111][C-000038bb] netsock2.c: == Using SIP RTP TOS bits 184
[2014-07-30 17:10:36] VERBOSE[32111][C-000038bb] netsock2.c: == Using SIP RTP CoS mark 5
[2014-07-30 17:10:36] VERBOSE[605][C-000038bb] pbx.c: -- Executing [310328xxxx@from-trunk:1] Set("SIP/IntegraIn-000022da", "__FROM_DID=310328xxxx") in new stack
[2014-07-30 17:10:36] VERBOSE[605][C-000038bb] pbx.c: -- Executing [310328xxxx@from-trunk:2] NoOp("SIP/IntegraIn-000022da", "Received an unknown call with DID set to 310328xxxx") in new stack
[2014-07-30 17:10:36] VERBOSE[605][C-000038bb] pbx.c: -- Executing [310328xxxx@from-trunk:3] Goto("SIP/IntegraIn-000022da", "s,a2") in new stack
[2014-07-30 17:10:36] VERBOSE[605][C-000038bb] pbx.c: -- Goto (from-trunk,s,2)
[2014-07-30 17:10:36] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@from-trunk:2] Answer("SIP/IntegraIn-000022da", "") in new stack
[2014-07-30 17:10:37] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@from-trunk:3] Wait("SIP/IntegraIn-000022da", "2") in new stack
[2014-07-30 17:10:39] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@from-trunk:4] Playback("SIP/IntegraIn-000022da", "ss-noservice") in new stack
[2014-07-30 17:10:39] VERBOSE[605][C-000038bb] file.c: -- Playing 'ss-noservice.gsm' (language 'en')
[2014-07-30 17:10:44] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@from-trunk:5] SayAlpha("SIP/IntegraIn-000022da", "310328xxxx") in new stack
[2014-07-30 17:10:44] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/3.gsm' (language 'en')
[2014-07-30 17:10:45] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/1.gsm' (language 'en')
[2014-07-30 17:10:45] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/0.gsm' (language 'en')
[2014-07-30 17:10:46] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/3.gsm' (language 'en')
[2014-07-30 17:10:47] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/2.gsm' (language 'en')
[2014-07-30 17:10:47] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/8.gsm' (language 'en')
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/x.gsm' (language 'en')
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/x.gsm' (language 'en')
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/x.gsm' (language 'en')
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] file.c: -- Playing 'digits/x.gsm' (language 'en')
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: == Spawn extension (from-trunk, s, 5) exited non-zero on 'SIP/IntegraIn-000022da'
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: -- Executing [h@from-trunk:1] Macro("SIP/IntegraIn-000022da", "hangupcall,") in new stack
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/IntegraIn-000022da", "1?theend") in new stack
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: -- Goto (macro-hangupcall,s,3)
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/IntegraIn-000022da", "0?Set(CDR(recordingfile)=)") in new stack
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/IntegraIn-000022da", "") in new stack
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/IntegraIn-000022da' in macro 'hangupcall'
[2014-07-30 17:10:48] VERBOSE[605][C-000038bb] pbx.c: == Spawn extension (from-trunk, h, 1) exited non-zero on 'SIP/IntegraIn-000022da'

 

[rossiv]

Interesting....never seen it read the number back, but stranger has happened.
Usually when you see a "Received an unknown call with DID....." you don't see a trunk name associated with it. It'll have the IP address. My first thought after scanning the logs was that the provider was sending calls from an IP address not in the Asterisk config, but that's not the case.

And now I'm confused. It'd be really helpful if you could draw us a diagram of what does and doesn't go through the PBX. Something like

AT&T POTS ----------------\              /Internet Phone
                        -------PBX--------
Integra SIP----------------/

 

[dbdataplus]

Happy to try. If I understand your request for a chart - it goes like this:

Internet phone -->Dsl-extreme/AT&T ---->Integra Telecom ---->Asterisk ---> Disa ----> integra telecom ---> AT&T pots line.
In other words, I use my Internet phone to call my pots phone via the asterisk system - and it works flawlessly


Then I try exactly the same thing again
Internet phone -->Dsl-extreme/AT&T ---->Integra Telecom ---->Asterisk ---> Disa ----> integra telecom --->"Number Not In Service" message. {phone # of my Internet Phone}

****SO****
Thinking that the Internet phone is flakey, I try a reverse-- calling FROM my pots to Asterisk and then back to my Internet phone. That works the first time as well - then fails subsequent times.

Now I'm not proposing what is actually happening but the following scenario would explain it.

I call into Disa and make a call out, then hang up
Asterisk does not collapse the process/session in its entirety
I call back in 5 minutes
Asterisk reconnects me to the DISA process that already has my CID as a session.
DISA mistakenly attempts to connect me to my caller ID as an outgoing number, but without the "1" in from of it, generates an Integra error.

A curious thing that I forgot to mention is that after approximately 20 minutes, both phones can again call into that number.

 

[dbdataplus]

Additional chart

ATT POTS line ----------------------------<--->-----------Integra Telecom SIP <-----------> Asterisk PBX
Internet Phone --> Dsl Extreme -----/

|------------My House ------------------|-- The mystery--| Integra Telecom, Inc ---------|--- My client ---|