Remote phone issue - Trixbox CE

system · February 25, 2014, 7:07pm

Trixbox CE v2.6.2.3
CentOS 5.5

First, I know Trixbox is outdated, we’re working on replacing it

Have a remote office with 8 phones. They have mostly been working fine for over 2 years. They point to an external IP of the PBX and everything works.

The remote office moved a month ago.

Yesterday, 4 of the phones stopped working. They hit the PBX but show up as unreachable. The other 4 phones in the office, work normally.

I’m gone into the UI and confirmed that the config is the same on working/non-working ones.

I am remote and have a phone here, which works without issue.

Any ideas on how to work out what is causing the issue with these isolated phones?

system · February 25, 2014, 10:24pm

Here’s a dump of the sip debug:

pastebin.com/qMRLvT8t

[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: SIP TIMER: Rescheduling retransmission #96228 (4) SIP/2.0 - 1
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #96228))
[Feb 25 13:58:02] VERBOSE[6698] logger.c:
<— SIP read from RemoteOfficeIP:41988 —>
REGISTER sip:PBXExtIP:5060 SIP/2.0
Via: SIP/2.0/UDP PhoneIP:5060;branch=z9hG4bK293376a6E48E72B5
From: “UserName” sip:extension@PBXExtIP;tag=3B1518E2-2EF5AF1
To: sip:extension@PBXExtIP
CSeq: 470 REGISTER
Call-ID: d2b68a1e-6201922d-51112bbc@PhoneIP
Contact: sip:extension@PhoneIP:5060;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER"
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.2.3.1734
Accept-Language: en
Authorization: Digest username=“extension”, realm=“asterisk”, nonce=“6b607c0b”, uri=“sip:PBXExtIP:5060”, response=“64ec7229df9c8f4bfa112132f715d6f2”, algorithm=MD5
Max-Forwards: 70
Expires: 60
Content-Length: 0

<------------->
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 0: REGISTER sip:PBXExtIP:5060 SIP/2.0 (42)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 1: Via: SIP/2.0/UDP PhoneIP:5060;branch=z9hG4bK293376a6E48E72B5 (64)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 2: From: “UserName” sip:extension@PBXExtIP;tag=3B1518E2-2EF5AF1 (67)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 3: To: sip:extension@PBXExtIP (31)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 4: CSeq: 470 REGISTER (18)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 5: Call-ID: d2b68a1e-6201922d-51112bbc@PhoneIP (47)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 6: Contact: sip:extension@PhoneIP:5060;methods=“INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER” (136)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.2.3.1734 (54)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 8: Accept-Language: en (19)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 9: Authorization: Digest username=“extension”, realm=“asterisk”, nonce=“6b607c0b”, uri=“sip:PBXExtIP:5060”, response=“64ec7229df9c8f4bfa112132f715d6f2”, algorithm=MD5 (166)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 10: Max-Forwards: 70 (16)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 11: Expires: 60 (11)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 12: Content-Length: 0 (17)
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: Header 13: (0)
[Feb 25 13:58:02] VERBOSE[6698] logger.c: — (13 headers 0 lines) —
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 25 13:58:02] VERBOSE[6698] logger.c: Using latest REGISTER request as basis request
[Feb 25 13:58:02] VERBOSE[6698] logger.c: Sending to RemoteOfficeIP : 41988 (NAT)
[Feb 25 13:58:02] DEBUG[6698] acl.c: ##### Testing RemoteOfficeIP with 0.0.0.0
[Feb 25 13:58:02] DEBUG[6698] acl.c: ##### Testing RemoteOfficeIP with 0.0.0.0
[Feb 25 13:58:02] VERBOSE[6698] logger.c:
<— Transmitting (NAT) to RemoteOfficeIP:41988 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP PhoneIP:5060;branch=z9hG4bK293376a6E48E72B5;received=RemoteOfficeIP
From: “UserName” sip:extension@PBXExtIP;tag=3B1518E2-2EF5AF1
To: sip:extension@PBXExtIP
Call-ID: d2b68a1e-6201922d-51112bbc@PhoneIP
CSeq: 470 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:extension@10.11.200.26
Content-Length: 0

<------------>
[Feb 25 13:58:02] VERBOSE[6698] logger.c:
<— Transmitting (NAT) to RemoteOfficeIP:41988 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP PhoneIP:5060;branch=z9hG4bK293376a6E48E72B5;received=RemoteOfficeIP
From: “UserName” sip:extension@PBXExtIP;tag=3B1518E2-2EF5AF1
To: sip:extension@PBXExtIP;tag=as4d53cc8b
Call-ID: d2b68a1e-6201922d-51112bbc@PhoneIP
CSeq: 470 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 60
Contact: sip:extension@PhoneIP:5060;expires=60
Date: Tue, 25 Feb 2014 21:58:02 GMT
Content-Length: 0

<------------>
[Feb 25 13:58:02] DEBUG[6698] devicestate.c: Notification of state change to be queued on device/channel SIP/extension
[Feb 25 13:58:02] VERBOSE[6698] logger.c: Scheduling destruction of SIP dialog ‘d2b68a1e-6201922d-51112bbc@PhoneIP’ in 32000 ms (Method: REGISTER)
[Feb 25 13:58:02] DEBUG[6677] devicestate.c: No provider found, checking channel drivers for SIP - extension
[Feb 25 13:58:02] DEBUG[6677] chan_sip.c: Checking device state for peer extension
[Feb 25 13:58:02] DEBUG[6677] devicestate.c: Changing state for SIP/extension - state 5 (Unavailable)
[Feb 25 13:58:02] DEBUG[6677] devicestate.c: No provider found, checking channel drivers for SIP - extension
[Feb 25 13:58:02] DEBUG[6677] chan_sip.c: Checking device state for peer extension
[Feb 25 13:58:02] DEBUG[6677] devicestate.c: Checking if I can find provider for “Custom” - number: DNDextension
[Feb 25 13:58:02] DEBUG[6677] db.c: Unable to find key ‘DNDextension’ in family ‘CustomDevstate’
[Feb 25 13:58:02] DEBUG[6697] app_queue.c: Device ‘SIP/extension’ changed to state ‘5’ (Unavailable) but we don’t care because they’re not a member of any queue.
[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: SIP TIMER: Not rescheduling id #96263:OPTIONS (Method 3) (No timer T1)
[Feb 25 13:58:02] VERBOSE[6698] logger.c: Retransmitting #1 (NAT) to RemoteOfficeIP:42052:

david55 · February 26, 2014, 8:03am

This:

should contain PBXIP.

This indicates that an OPTIONS request (qualify) from before the start of the trace failed to produce a response:

[Feb 25 13:58:02] DEBUG[6698] chan_sip.c: SIP TIMER: Not rescheduling id #96263:OPTIONS (Method 3) (No timer T1) [Feb 25 13:58:02] VERBOSE[6698] logger.c: Retransmitting #1 (NAT) to RemoteOfficeIP:42052: