Extensions Strange Behaviour

[parts]

Extensions Strange Behaviour

I have 5 extensions on my 3CX system V 12.

1 VoIP connection outbound only

I PSTN line connection via an OBi110 Gateway

The System runs on a freestanding Atom based Windows 7 Box

The Obi gateway and the VoIP are registered

All extensions are registered

All but one extension is in a ring group

I can make calls via the VoIP trunk OK

I can make calls between all extensions


NOW HERE IS THE PROBLEM


The system receives an incoming call and transfers it to an extension, but not an extension in the ring group, nor is it the operator extension

If I direct the call to a specific extension from the inbound route the specified extension does not ring but the same extension as with the call group does.



Help Please

 

[craigreilly]

Are you setting this up in the DID routes or in the VOIP Gateway settings?

Posting the log files may be helpful so we can trace the path. Otherwise, we are just throwing random ideas at you for a wild goose chase. Be sure to turn on verbose mode when showing the logs.

 

[parts]

Here are the log files
I
The ring group is made up of extension 201 (A2 x.x.x.161 ) and 213 (7B x.x.x.160) Extension 202 (C6 x.x.x.156) is not included

the last 2 digits of the MAC address for the extensions is in the brackets followed by the last 3 digits of the IP address

The IP the Obi is x.x.x.5



3-Sep-2013 10:36:31.540 Currently active calls [none]
23-Sep-2013 10:35:59.540 Currently active calls [none]
23-Sep-2013 10:35:32.700 L:144.2[Extn]: Terminating targets, reason: SIP ;cause=487 ;text="Request Cancelled"
23-Sep-2013 10:35:32.700 Leg L:144.2[Extn] is terminated: Cause: 487 Request Cancelled/INVITE from 10.0.0.156:50551
23-Sep-2013 10:35:32.700 L:144.2[Extn] got Terminated Recv 487/INVITE from 10.0.0.156:50551 tid=bf04a06e222bca01 Call-ID=ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.:
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP 10.0.0.10:5060;branch=z9hG4bK-d8754z-bf04a06e222bca01-1---d8754z-;rport
Contact: <sip:[email protected]:5061;transport=udp>
To: <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50
From: <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
Call-ID: ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.
CSeq: 1 INVITE
Allow: ACK, BYE, CANCEL, INVITE, NOTIFY, OPTIONS, REFER, REGISTER, UPDATE
Server: Cisco-CP7940G/8.0
Content-Length: 0
Remote-Party-ID: "202" <sip:[email protected]>;party=called;id-type=subscriber;privacy=off;screen=yes
23-Sep-2013 10:35:32.700 Terminated from <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50 to <sip:[email protected]:5060;nf=e>;tag=d51a0c1f; reason: Error
23-Sep-2013 10:35:32.699 L:144.2[Extn] got Failure: Failure Recv 487/INVITE from 10.0.0.156:50551 tid=bf04a06e222bca01 Call-ID=ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.:
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP 10.0.0.10:5060;branch=z9hG4bK-d8754z-bf04a06e222bca01-1---d8754z-;rport
Contact: <sip:[email protected]:5061;transport=udp>
To: <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50
From: <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
Call-ID: ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.
CSeq: 1 INVITE
Allow: ACK, BYE, CANCEL, INVITE, NOTIFY, OPTIONS, REFER, REGISTER, UPDATE
Server: Cisco-CP7940G/8.0
Content-Length: 0
Remote-Party-ID: "202" <sip:[email protected]>;party=called;id-type=subscriber;privacy=off;screen=yes
23-Sep-2013 10:35:32.699 [CM503003]: Call(C:144): Call to <sip:[email protected]:5060> has failed; Cause: 487 Request Cancelled/INVITE from 10.0.0.156:50551
23-Sep-2013 10:35:32.699 Session 258844 has failed in leg L:144.2[Extn] ; Cause: 487 Request Cancelled/INVITE from 10.0.0.156:50551
23-Sep-2013 10:35:32.699 Failure from <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50 to <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
23-Sep-2013 10:35:32.461 [CM503008]: Call(C:144): Call is terminated
23-Sep-2013 10:35:32.461 L:144.2[Extn]: Terminating targets, reason: SIP ;cause=200 ;text="Call terminated on user request"
23-Sep-2013 10:35:32.458 Blocking refers for the Call(C:144)
23-Sep-2013 10:35:32.458 Call(C:144) is terminated
23-Sep-2013 10:35:32.456 ~Target=Ext:Ext.202
23-Sep-2013 10:35:32.456 ~Route=Dev:sip:[email protected]:5061;transport=udp
23-Sep-2013 10:35:32.456 Reason: SIP ;cause=487 ;text="Request Terminated"
23-Sep-2013 10:35:32.456 L:144.1[Line:10001<<08003289393]: Terminating targets, reason: SIP ;cause=487 ;text="Request Terminated"
23-Sep-2013 10:35:32.456 Leg L:144.1[Line:10001<<08003289393] is terminated: Cause: CANCEL from 10.0.0.5:5080
23-Sep-2013 10:35:32.453 L:144.1[Line:10001<<08003289393] got Terminated Recv Req CANCEL from 10.0.0.5:5080 tid=-23ea0349 [email protected]:
CANCEL sip:10.0.0.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.5:5080;branch=z9hG4bK-23ea0349;rport=5080
Max-Forwards: 70
To: <sip:10.0.0.10>
From: <sip:[email protected]>;tag=SP13c20e1b63c20153d
Call-ID: [email protected]
CSeq: 8002 CANCEL
Proxy-Authorization: DIGEST algorithm=MD5,nonce="414d535c08509c4429:5d93ef3d735c8c36c038306867ea9f0c",realm="3CXPhoneSystem",response="63c2604c2532c49a17d85781af861a7b",uri="sip:10.0.0.10:5060",username="10001"
User-Agent: OBIHAI/OBi110-1.3.0.2776
Content-Length: 0
23-Sep-2013 10:35:32.453 Terminated from <sip:[email protected]>;tag=SP13c20e1b63c20153d to <sip:10.0.0.10>;tag=a34d1b07; reason: RemoteBye
23-Sep-2013 10:35:32.453 L:144.1[Line:10001<<08003289393] Sending: OnSendResp Send 487/INVITE from 0.0.0.0:0 tid=-23ea0349 [email protected]:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 10.0.0.5:5080;branch=z9hG4bK-23ea0349;rport=5080
To: <sip:10.0.0.10>;tag=a34d1b07
From: <sip:[email protected]>;tag=SP13c20e1b63c20153d
Call-ID: [email protected]
CSeq: 8002 INVITE
Content-Length: 0
23-Sep-2013 10:35:32.453 SendMsg from <sip:10.0.0.10>;tag=a34d1b07 to <sip:[email protected]>;tag=SP13c20e1b63c20153d
23-Sep-2013 10:35:32.452 L:144.1[Line:10001<<08003289393] Sending: OnSendResp Send 200/CANCEL from 0.0.0.0:0 tid=-23ea0349 [email protected]:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.0.5:5080;branch=z9hG4bK-23ea0349;rport=5080
Contact: <sip:10.0.0.10:5060>
To: <sip:10.0.0.10>;tag=a34d1b07
From: <sip:[email protected]>;tag=SP13c20e1b63c20153d
Call-ID: [email protected]
CSeq: 8002 CANCEL
Content-Length: 0
23-Sep-2013 10:35:32.452 SendMsg from <sip:10.0.0.10>;tag=a34d1b07 to <sip:[email protected]>;tag=SP13c20e1b63c20153d
23-Sep-2013 10:35:27.540 Currently active calls - 1: [144]
23-Sep-2013 10:35:01.390 L:144.1[Line:10001<<08003289393] Sending: OnSendResp Send 180/INVITE from 0.0.0.0:0 tid=-23ea0349 [email protected]:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.0.0.5:5080;branch=z9hG4bK-23ea0349;rport=5080
Contact: <sip:10.0.0.10:5060>
To: <sip:10.0.0.10>;tag=a34d1b07
From: <sip:[email protected]>;tag=SP13c20e1b63c20153d
Call-ID: [email protected]
CSeq: 8002 INVITE
Content-Length: 0
23-Sep-2013 10:35:01.389 SendMsg from <sip:10.0.0.10>;tag=a34d1b07 to <sip:[email protected]>;tag=SP13c20e1b63c20153d
23-Sep-2013 10:35:01.389 Provisional response arrived for session 258844 of Leg L:144.2[Extn]
23-Sep-2013 10:35:01.389 L:144.2[Extn] got Provisional Recv 180/INVITE from 10.0.0.156:50551 tid=bf04a06e222bca01 Call-ID=ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.0.0.10:5060;branch=z9hG4bK-d8754z-bf04a06e222bca01-1---d8754z-;rport
Contact: <sip:[email protected]:5061;transport=udp>
To: <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50
From: <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
Call-ID: ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.
CSeq: 1 INVITE
Allow: ACK, BYE, CANCEL, INVITE, NOTIFY, OPTIONS, REFER, REGISTER, UPDATE
Server: Cisco-CP7940G/8.0
Content-Length: 0
Remote-Party-ID: "202" <sip:[email protected]>;party=called;id-type=subscriber;privacy=off;screen=yes
23-Sep-2013 10:35:01.389 Provisional(180) from <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50 to <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
23-Sep-2013 10:35:01.389 [CM505001]: Endpoint Extn:202: Device info: Device Identified: [Man: Cisco;Mod: 7940;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco-CP7940G/8.0] PBX contact: [sip:[email protected]:5060]
23-Sep-2013 10:35:01.389 [CM503002]: Call(C:144): Alerting Extn:202 by contact <sip:[email protected]:5061>
23-Sep-2013 10:35:01.387 UacSession 258844 has formed leg L:144.2[Extn]
23-Sep-2013 10:35:01.386 Answer from <sip:[email protected]>;tag=0014a851f7c601204d630807-25b87d50 to <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
23-Sep-2013 10:35:01.106 [CM503025]: Call(C:144): Calling T:Extn:202@[Dev:sip:[email protected]:5061;transport=udp] for L:144.1[Line:10001<<08003289393]
23-Sep-2013 10:35:01.106 Route to L:144.2[Extn] sends Invite-OUT Send Req INVITE from 0.0.0.0:0 tid=3f0744077179c76e Call-ID=ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.:
INVITE sip:[email protected]:5061;transport=udp SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d8754z-3f0744077179c76e-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]>
From: <sip:[email protected]:5060;nf=e>;tag=d51a0c1f
Call-ID: ZTE3MDBmOTczNjYxZTExODMxZjk4MjYxZTBiZTYyZDI.
CSeq: 1 INVITE
Alert-Info: <http://www.notused.invalidtld>;info=external
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
Content-Length: 351

v=0
o=3cxPS 445653188608 385238433793 IN IP4 10.0.0.10
s=3cxPS Audio call
c=IN IP4 10.0.0.10
t=0 0
m=audio 7018 RTP/AVP 0 8 3 13 9 110 99 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:13 CN/8000
a=rtpmap:9 G722/8000
a=rtpmap:110 iLBC/8000
a=rtpmap:99 SPEEX/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
23-Sep-2013 10:35:01.096 Outbound URI is used: sip:[email protected]:5061;transport=udp
23-Sep-2013 10:35:01.096 SLA is globally disabled
23-Sep-2013 10:35:01.095 Added leg L:144.2[Extn]
23-Sep-2013 10:35:01.066 [Flow] Call(C:144): making call from L:144.1[Line:10001<<08003289393] to T:Extn:202@[Dev:sip:[email protected]:5061;transport=udp]
23-Sep-2013 10:35:01.066 [CM503027]: Call(C:144): From: Line:10001<<08003289393 (<sip:[email protected]:5060>) to T:Extn:202@[Dev:sip:[email protected]:5061;transport=udp]
23-Sep-2013 10:35:01.066 [CM503004]: Call(C:144): Route 1: from L:144.1[Line:10001<<08003289393] to T:Extn:202@[Dev:sip:[email protected]:5061;transport=udp]
23-Sep-2013 10:35:01.065 [Flow] Endpoint Extn:202 has no forwarding rule on reason 'All calls'
23-Sep-2013 10:35:01.065 [Flow] Call(C:144): has built target endpoint: Extn:202 for call from L:144.1[Line:10001<<08003289393]
23-Sep-2013 10:35:01.065 [Flow] Target endpoint for 202 is Extn:202
23-Sep-2013 10:35:01.065 [Flow] Building target endpoint to 202 from <sip:[email protected]:5060>
23-Sep-2013 10:35:01.065 [CM503010]: Call(C:144): Making route(s) from Line:10001<<08003289393 to <sip:[email protected]:5060>
23-Sep-2013 10:35:01.065 Remote SDP is set for leg L:144.1[Line:10001<<08003289393]
23-Sep-2013 10:35:01.065 OnOffer from <sip:[email protected]:5060;nf=e>
23-Sep-2013 10:35:01.065 [CM505002]: Gateway:[OBi] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [OBIHAI/OBi110-1.3.0.2776] PBX contact: [sip:[email protected]:5060]
23-Sep-2013 10:35:01.063 Inbound DID: ''; Phonebook Name: ''
23-Sep-2013 10:35:01.063 [CM500002]: Call(C:144): Info on incoming INVITE from Line:10001<<08003289393:
Invite-IN Recv Req INVITE from 10.0.0.5:5080 tid=-23ea0349 [email protected]:
INVITE sip:10.0.0.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.5:5080;branch=z9hG4bK-23ea0349;rport=5080
Max-Forwards: 70
Contact: <sip:[email protected]:5080>
To: <sip:10.0.0.10>
From: <sip:[email protected]>;tag=SP13c20e1b63c20153d
Call-ID: [email protected]
CSeq: 8002 INVITE
Expires: 60
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Content-Type: application/sdp
Proxy-Authorization: DIGEST algorithm=MD5,nonce="414d535c08509c4429:5d93ef3d735c8c36c038306867ea9f0c",realm="3CXPhoneSystem",response="8342d1f0243defbd3d11b86f30b1e722",uri="sip:10.0.0.10:5060",username="10001"
Supported: replaces
User-Agent: OBIHAI/OBi110-1.3.0.2776
Content-Length: 304
Remote-Party-ID: <sip:[email protected]>;party=calling;privacy=off

v=0
o=- 26415681 1 IN IP4 10.0.0.5
s=-
c=IN IP4 10.0.0.5
t=0 0
m=audio 16634 RTP/AVP 0 8 18 104 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:104 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20
a=xg726bitorder:big-endian
23-Sep-2013 10:35:01.063 [CM503001]: Call(C:144): Incoming call from Line:10001<<08003289393 to <sip:[email protected]:5060>
23-Sep-2013 10:35:01.058 Line limit check: Current # of calls for line Lc:10001(@OBi[<sip:[email protected]:5080>]) is 1; limit is 1
23-Sep-2013 10:35:01.058 Blacklist check: number '08003289393', list: ''; result = false
23-Sep-2013 10:35:01.052 Outbound URI is used: sip:[email protected]:5080
23-Sep-2013 10:35:01.045 [CM503012]: Inbound office hours rule (unnamed) for 10001 forwards to DN:202
23-Sep-2013 10:35:01.044 [Flow] Looking for inbound target: called=; caller=<sip:08003289393@:5060>
23-Sep-2013 10:35:01.044 CallerNameAddr: <sip:08003289393;nf=e>
23-Sep-2013 10:35:01.044 Tenant's phonebook has failed to load!
23-Sep-2013 10:35:01.044 Looking for phone number 08003289393 in tenant's 'default' phonebook
23-Sep-2013 10:35:01.044 No inbound caller ID reformat rule is defined, or it is disabled ()
23-Sep-2013 10:35:01.044 Line 10001 has been updated from DB
23-Sep-2013 10:35:01.044 IncomingCall: C:144 from <sip:[email protected]:5060> to <sip10.0.0.10:5060>
23-Sep-2013 10:35:01.044 Added leg L:C:144.1[No endpoint yet]
23-Sep-2013 10:35:01.043 UasSession 258841 started
23-Sep-2013 10:35:01.043 Call from <sip:[email protected]>;tag=SP13c20e1b63c20153d to <sip:10.0.0.10>;tag=a34d1b07
23-Sep-2013 10:34:55.540 Currently active calls [none]
23-Sep-2013 10:34:23.540 Currently active calls [none]
23-Sep-2013 10:34:07.833 Line 10001 got Device: Dev(51):[sip:[email protected]:5080 / 10001]
23-Sep-2013 10:33:51.540 Currently active calls [none]


Thanks for looking at this

Chris

 

[parts]

My inbound route was not set up in Voip provider section. Incoming route is UK PSTN


parts

 

[leejor]

My inbound route was not set up in Voip provider section. Incoming route is UK PSTN

So...what you're saying ,is...you solved it?

 

[parts]

Sorry i have not responded earlier, I have had a virus , all clear now.

No such luck.
Ive tried rejigging the handsets/Extensions combinations there is always one extension that rings even when it is not in the ring group and is not the operator extension. I'm not sure what to next any ideas ?

 

[lneblett]

This is the portion of the log of interest:

23-Sep-2013 10:35:01.045 [CM503012]: Inbound office hours rule (unnamed) for 10001 forwards to DN:20223-Sep-2013 10:35:01.065 [Flow] Endpoint Extn:202 has no forwarding rule on reason 'All calls'

The call is coming in from the Obi and is checked against certain parameters and not finding any of significance, is then routed to extension 202 by an inbound rule. The system is clearly building the route to that extension and delivers to same whereupon the extension rang for approx. 30 seconds. It does not appear to be a phone issue, but rather that you need to look at the rules for the Obi gateway and see how defined to deliver calls that the system does not recognize via DID.

The system is doing exactly as you indicate, but the logs only confirm it. They do not show that there is an error as they only show the actions, not how the system was/is set-up and what you want it to do. You should look at port/line 10001 and see how this is directed. I am assuming that the time of day and date that the log shows is in keeping with the system being in office hours.