Phone Not Registering

I am having problems registering phones to my New PBX from one of my offices.

I installed the newest version of FreePBX Yesterday and I am facing issues with just this one office. I can actually register a phone to my old PBX which was Elastic Distro.

I could not get a log from my Deskphone so I downloaded X-Lite which also fails to register and I get the following Debug Log. I have changed my PBX IP to 999.999.999.999 in the log for security.

Blockquote

[18-07-30]13:15:44.357 | Info | AbstractPhone | “[[email protected]]::EnableAccount” | AbPhone::CAccount::EnableAccount
[18-07-30]13:15:44.357 | Debug | CCM | “Adding to pending… [id:105][worker-sz:0][pending:0]” | sua::CResipProcessThread::Add
[18-07-30]13:15:44.357 | Info | DNS | “DNS [query:999.999.999.999]” | sua::CDNS::StartTopologyLookup
[18-07-30]13:15:44.357 | Info | DNS | “DNS-Lookup performed: ‘_sip._udp.’ ‘999.999.999.999’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[18-07-30]13:15:44.357 | Info | DNS | " 0 - [ip:999.999.999.999:5060][ttl:4294967295][P:0][W:0][query-name:999.999.999.999]" | sua::CDNS::InternalShutdown
[18-07-30]13:15:44.357 | Info | DNS | “DNS [query:999.999.999.999]” | sua::CDNS::StartTopologyLookup
[18-07-30]13:15:44.357 | Info | DNS | “DNS-Lookup performed: ‘_sip._tcp.’ ‘999.999.999.999’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[18-07-30]13:15:44.357 | Info | DNS | " 0 - [ip:999.999.999.999:5060][ttl:4294967295][P:0][W:0][query-name:999.999.999.999]" | sua::CDNS::InternalShutdown
[18-07-30]13:15:44.357 | Debug | AbstractPhone | “[[email protected]]::OnDNSLookupPlusDiscoveryProcessResult” | AbPhone::CAccount::CCCMSink::OnDNSLookupPlusDiscoveryProcessResult
[18-07-30]13:15:44.358 | Info | AbstractPhone | “Receiving notification about firewall IP address: 0.0.0.0, voip always possible: 0” | AbPhone::CAbstractPhone::OnFirewallInformation
[18-07-30]13:15:44.358 | Debug | CCM | “CSIPAccess created, [handle:03FA9B80] [ENetworkUp]” | sua::CCallControlManager::CreateSIPAccess
[18-07-30]13:15:44.358 | Debug | CCM | “[state:EState_CreatingTransport][T|F] [URI:[email protected]]” | sua::CSIPAccess::CreateDUM
[18-07-30]13:15:44.358 | Debug | RESIP | “BaseSecurity::BaseSecurity” |
[18-07-30]13:15:44.365 | Debug | RESIP:DNS | “number of name servers found 1” |
[18-07-30]13:15:44.365 | Debug | RESIP:DNS | “name server 192.168.1.254” |
[18-07-30]13:15:44.365 | Debug | RESIP:DUM | “Adding credential: realm=999.999.999.999 user=401” |
[18-07-30]13:15:44.365 | Debug | CCM | “[state:EInitial]” | sua::CSIPDUMWrapper::SetContainedObjects
[18-07-30]13:15:44.365 | Debug | CCM | “Adding to pending… [id:152][worker-sz:0][pending:1]” | sua::CResipProcessThread::Add
[18-07-30]13:15:44.365 | Debug | CCM | “[state:EState_CreatingTransport][T|F] [URI:[email protected]]” | sua::CSIPAccess::CreateTransport
[18-07-30]13:15:44.365 | Info | CCM | “Creating transport… [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::Start
[18-07-30]13:15:44.365 | Debug | CCM | “Local IPs: <192.168.1.104>” | sua::CSIPAccess::CTransportCreator::Start
[18-07-30]13:15:44.365 | Debug | CCM | “[port:5998 (0->0)] [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::CreateNonTunnelingTransports
[18-07-30]13:15:44.365 | Info | CCM | “Not using firewall SIP proxy. Reasons: [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::UseFirewallSIPProxy
[18-07-30]13:15:44.365 | Debug | CCM | “Not using SBC/Firewall proxy. [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::CreateNonTunnelingTransports
[18-07-30]13:15:44.365 | Debug | CCM | “Trying to add a NatNavigator on port: 5998” | sua::CResipTransportCreator::AddNATNavTransportTryNextOpenPort
[18-07-30]13:15:44.365 | Info | RESIP:TRANSPORT | “Creating UDP transport host= port=5998 ipv4=1” |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Creating fd=2200 V4/UDP” |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Binding to 0.0.0.0” |
[18-07-30]13:15:44.365 | Info | CCM | “DSCP marking is already set correct for SIP or DNS signaling socket, where socket=2200, where transport type=3, where resip file is W:\Headsvn\SUA\Library\sipfoundry\main\resip\stack\InternalTransport.cxx, where resip line # is 120, where DSCP value=0” | sua::CCMAfterSocketCreationFuncPtr
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Adding transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:15:44.365 | Debug | CCM | “Trying to add a native transport on port: 5998” | sua::CResipTransportCreator::AddNativeTransportTryNextOpenPort
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “ConnectionBase::ConnectionBase, no params: 09F67E98” |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “ConnectionManager::ConnectionManager() called " |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Creating fd=2216 V4/TCP” |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Binding to 0.0.0.0” |
[18-07-30]13:15:44.365 | Info | RESIP:TRANSPORT | “Creating TCP transport host= port=5998 ipv4=1” |
[18-07-30]13:15:44.365 | Debug | RESIP:TRANSPORT | “Adding transport: [ V4 0.0.0.0:5998 TCP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:15:44.365 | Debug | CCM | “[state:EState_CreatingTransport][T|F] [URI:[email protected]]” | sua::CSIPAccess::HandleTransportCreationSuccess
[18-07-30]13:15:44.365 | Debug | CCM | “[state:EStarting]” | sua::CSIPDUMWrapper::NotifyDUMIsReady
[18-07-30]13:15:44.366 | Debug | AbstractPhone | “[[email protected]]::OnSIPAccessCreationProgress” | AbPhone::CAccount::CCCMSink::OnSIPAccessCreationProgress
[18-07-30]13:15:44.366 | Debug | AbstractPhone | “[[email protected]]::OnSIPAccessCreationProgress” | AbPhone::CAccount::CCCMSink::OnSIPAccessCreationProgress
[18-07-30]13:15:44.366 | Debug | AbstractPhone | “[[email protected]]::OnSIPAccessReady” | AbPhone::CAccount::CCCMSink::OnSIPAccessReady
[18-07-30]13:15:44.366 | Debug | CCM | " [URI:[email protected]]” | sua::CSIPAccess::InstallIncomingCallSink
[18-07-30]13:15:44.366 | Debug | CCM | " [URI:[email protected]]" | sua::CSIPAccess::InstallServerIMPagerMessageSink
[18-07-30]13:15:44.366 | Debug | CCM | “[event:message-summary] [URI:[email protected]]” | sua::CSIPAccess::InstallOutOfDialogNotifySink
[18-07-30]13:15:44.366 | Debug | CCM | “[event:message-summary]” | sua::CMyDUMOutOfDialogNotifyHandler::InstallSIPEventSink
[18-07-30]13:15:44.366 | Debug | CCM | " [URI:[email protected]]" | sua::CSIPAccess::SIPRegister
[18-07-30]13:15:44.366 | Debug | CCM | " [URI:[email protected]]" | sua::CTransportMonitorUsingRegistration::NotifyNewSIPClientRegistration
[18-07-30]13:15:44.366 | Debug | CCM | “[URI:[email protected]]” | sua::CSIPRegistration::Start
[18-07-30]13:15:44.367 | Debug | RESIP:DUM | “BaseCreator::makeInitialRequest: 09F3A1B0” |
[18-07-30]13:15:44.367 | Debug | RESIP:DUM | “RegistrationCreator::RegistrationCreator: 09F3A1B0” |
[18-07-30]13:15:44.367 | Debug | RESIP:DUM | " ************* Created DialogSet(UAC) – NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.-9322ad3c*************" |
[18-07-30]13:15:44.367 | Debug | RESIP:DUM | "SEND: REGISTER sip:999.999.999.999 SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-21485510ac7f0502-1–d87543-;rport
Max-Forwards: 70
Contact: <sip,401;rinstance=f7ee1873afc6b1ca>
To: "“401"”<sip;[email protected]>
From: "“401"”<sip;[email protected]>;tag=9322ad3c
Call-ID: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.
CSeq: 1 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0
[18-07-30]13:15:44.367 | Debug | RESIP:TRANSACTION | "Adding application timer: " |
[18-07-30]13:15:44.367 | Debug | Utilities | “Adding timer213, m_cTimers.size() 3” | sua::CTimerManager::CreateTimer
[18-07-30]13:15:44.383 | Debug | Utilities | “Adding timer243, m_cTimers.size() 4” | sua::CTimerManager::CreateTimer
[18-07-30]13:15:44.393 | Debug | GUI | “AUTO_UPDATE: started” | eyeBeam::CAutoUpdateClient::OnAutoUpdateNotify
[18-07-30]13:15:44.412 | Info | GUI | “Receiving notification about firewall IP address: 0.0.0.0, voip always possible: 0” | eyeBeam::CPhoneFrame::OnNetworkFirewallInformation
[18-07-30]13:15:44.544 | Info | RESIP:DUM | “Got a DumFeatureMessage09F681D8” |
[18-07-30]13:15:44.544 | Debug | RESIP:DUM | “has obp” |
[18-07-30]13:15:44.544 | Debug | RESIP:DUM | “Next hop is 999.999.999.999” |
[18-07-30]13:15:44.544 | Debug | RESIP:DUM | “DialogId::DialogId: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.-9322ad3c-” |
[18-07-30]13:15:44.544 | Debug | RESIP:DUM | “Using outbound proxy: sip:[email protected];lr -> SipReq: REGISTER 999.999.999.999 tid=21485510ac7f0502 cseq=REGISTER contact=401 / 1 from(tu)” |
[18-07-30]13:15:44.644 | Debug | RESIP:TRANSACTION | “Adding timer: Timer F tid=21485510ac7f0502 ms=32000” |
[18-07-30]13:15:44.644 | Debug | RESIP:DNS | “DnsResult::lookup sip:[email protected];lr” |
[18-07-30]13:15:44.644 | Debug | RESIP:DNS | “Numeric result so return immediately: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 connectionId=0 ]” |
[18-07-30]13:15:44.644 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=500” |
[18-07-30]13:15:44.646 | Debug | RESIP:TRANSPORT | “Looked up source for destination: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 connectionId=0 ] -> [ V4 192.168.1.104:0 UDP target domain=999.999.999.999 connectionId=0 ] sent-by= sent-port=0” |
[18-07-30]13:15:44.646 | Debug | RESIP:TRANSPORT | “findTransportBySource([ V4 192.168.1.104:0 UDP target domain=999.999.999.999 connectionId=0 ])” |
[18-07-30]13:15:44.647 | Debug | RESIP:TRANSPORT | “findTransport (any port, any interface) => Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:15:44.647 | Debug | RESIP:TRANSPORT | "Transmitting to [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.104:5998 UDP target domain=999.999.999.999 connectionId=0 ]REGISTER sip:999.999.999.999 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.104:5998;branch=z9hG4bK-d87543-21485510ac7f0502-1–d87543-;rport
Max-Forwards: 70
Contact: <sip;[email protected]:5998;rinstance=f7ee1873afc6b1ca>
To: "“401"”<sip;[email protected]>
From: "“401"”<sip;[email protected]>;tag=9322ad3c
Call-ID: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.
CSeq: 1 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0
[18-07-30]13:15:44.647 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:15:45.146 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=1000” |
[18-07-30]13:15:45.146 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:15:45.223 | Debug | Utilities | “Removing timer 59, m_cTimers.size() 3” | sua::CTimerManager::CancelTimer
[18-07-30]13:15:45.225 | Debug | Utilities | “Adding timer245, m_cTimers.size() 4” | sua::CTimerManager::CreateTimer
[18-07-30]13:15:46.146 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=2000” |
[18-07-30]13:15:46.146 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:15:48.147 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:15:48.147 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:15:49.228 | Debug | Utilities | “Removing timer 245, m_cTimers.size() 3” | sua::CTimerManager::CancelTimer
[18-07-30]13:15:49.234 | Debug | Utilities | “Adding timer246, m_cTimers.size() 4” | sua::CTimerManager::CreateTimer
[18-07-30]13:15:52.147 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:15:52.147 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:15:56.148 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:15:56.148 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:00.150 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:16:00.150 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:04.150 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:16:04.150 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:04.353 | Debug | Utilities | “Removing timer 120, m_cTimers.size() 3” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:04.353 | Debug | Utilities | "AUTO_UPDATE: T1 timer expired, Call OnAutoUpdteNotify(UpdateDue) " | sua::CAutoUpdate::OnTimer
[18-07-30]13:16:04.353 | Debug | Utilities | “Adding timer247, m_cTimers.size() 4” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:04.353 | Debug | GUI | “AUTO_UPDATE: checking for new configuration” | eyeBeam::CAutoUpdateClient::OnAutoUpdateNotify
[18-07-30]13:16:04.353 | Debug | Utilities | “Adding timer248, m_cTimers.size() 5” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:04.353 | Debug | Utilities | “Adding timer249, m_cTimers.size() 6” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:04.353 | Debug | Utilities | “AUTO_UPDATE: CheckForUpdates: Checking for new config and setting m_bCfgBlock variable TRUE” | sua::CAutoUpdate::CheckForUpdates
[18-07-30]13:16:04.353 | Debug | Utilities | “AUTO_UPDATE: CheckForUpdates: No server configured.” | sua::CAutoUpdate::CheckForUpdates
[18-07-30]13:16:04.353 | Debug | GUI | “AUTO_UPDATE: no new configuration available, checking for new installer anyway” | eyeBeam::CAutoUpdateClient::OnAutoUpdateNotify
[18-07-30]13:16:04.353 | Debug | Utilities | “Adding timer250, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:04.353 | Debug | Utilities | “AUTO_UPDATE: Checking for new update and setting block variable TRUE” | sua::CAutoUpdate::CheckForUpdates
[18-07-30]13:16:04.354 | Debug | Utilities | “Removing timer 247, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:04.354 | Debug | Utilities | “Removing timer 249, m_cTimers.size() 5” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:04.355 | Debug | Utilities | “AUTO_UPDATE: Hitting server for update check: https//upgrades.counterpath.com/xlite_3_0/upgrade.php?build=34025&mac=000ffef5f482&lang=en&platform=windows” | sua::CAutoUpdate::CheckForUpdates
[18-07-30]13:16:04.670 | Debug | Utilities | “AUTO_UPDATE: OnHTTPResponse: ulInErrorCode = 4294967295, ulInResponseStatus = 0” | sua::CAutoUpdate::OnHTTPResponse
[18-07-30]13:16:04.670 | Debug | Utilities | “AUTO_UPDATE: tInRequestID = 251” | sua::CAutoUpdate::OnHTTPResponse
[18-07-30]13:16:08.150 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:16:08.150 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:12.151 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:16:12.151 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:14.354 | Debug | Utilities | “Removing timer 248, m_cTimers.size() 4” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:14.354 | Debug | Utilities | "AUTO_UPDATE: T3 timer expired, Clearing T3 timer (un-block) " | sua::CAutoUpdate::OnTimer
[18-07-30]13:16:16.152 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=21485510ac7f0502 ms=4000” |
[18-07-30]13:16:16.152 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[18-07-30]13:16:16.652 | Debug | RESIP | “Helper::makeResponse(SipReq: REGISTER 999.999.999.999 tid=21485510ac7f0502 cseq=REGISTER [email protected]:5998 / 1 from(tu) code=408 reason=” |
[18-07-30]13:16:16.652 | Debug | RESIP:TRANSACTION | "Send to TU: TU: DialogUsageManager size=0 SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 192.168.1.104:5998;branch=z9hG4bK-d87543-21485510ac7f0502-1–d87543-;rport
To: "“401"”<sip;[email protected]>;tag=3265db4d
From: "“401"”<sip;[email protected]>;tag=9322ad3c
Call-ID: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.
CSeq: 1 REGISTER
Content-Length: 0
" |
[18-07-30]13:16:16.652 | Info | RESIP:DUM | “Got: SipResp: 408 tid=21485510ac7f0502 cseq=REGISTER / 1 from(wire)” |
[18-07-30]13:16:16.652 | Debug | RESIP:DUM | “DialogUsageManager::processResponse: SipResp: 408 tid=21485510ac7f0502 cseq=REGISTER / 1 from(wire)” |
[18-07-30]13:16:16.652 | Debug | RESIP:DUM | “DialogId::DialogId: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.-9322ad3c-3265db4d” |
[18-07-30]13:16:16.652 | Debug | RESIP:DUM | “Registration retry requestd for 999.999.999.999” |
[18-07-30]13:16:16.652 | Debug | CCM | “SipResp: 408 tid=21485510ac7f0502 cseq=REGISTER / 1 from(wire)[URI:[email protected]]” | sua::CSIPRegistration::onRequestRetry
[18-07-30]13:16:16.652 | Debug | CCM | “SipResp: 408 tid=21485510ac7f0502 cseq=REGISTER / 1 from(wire) [URI:[email protected]]” | sua::CTransportMonitorUsingRegistration::OnSIPRegistrationFailure
[18-07-30]13:16:16.652 | Debug | RESIP:DUM | “Application requested delayed retry on 408: 32” |
[18-07-30]13:16:16.652 | Debug | RESIP:TRANSACTION | “Adding application timer: DumTimeout::RegistrationRetry ClientRegistration sip:[email protected]: duration=32 seq=1” |
[18-07-30]13:16:16.653 | Debug | AbstractPhone | “[[email protected]]::OnSIPRegistrationAttemptFailed” | AbPhone::CAccount::CCCMSink::OnSIPRegistrationAttemptFailed
[18-07-30]13:16:16.653 | Debug | CCM | “[state:EState_Ready][T|T] [URI:[email protected]]” | sua::CSIPAccess::OnRegistrationTimedoutRecommendingDUMRestart
[18-07-30]13:16:16.653 | Debug | CCM | “[state:EState_Ready][T|T] [URI:[email protected]]” | sua::CSIPAccess::DoWorkForRestartDUMEvent
[18-07-30]13:16:16.653 | Debug | CCM | “[state:ERunning]” | sua::CSIPDUMWrapper::ShutdownDUM
[18-07-30]13:16:16.653 | Debug | Utilities | “Adding timer256, m_cTimers.size() 5” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:16.653 | Info | RESIP:DUM | “shutdown giveup=4 dialogSets=1” |
[18-07-30]13:16:16.653 | Debug | RESIP:DUM | “Shutdown waiting for all usages to be deleted (2)” |
[18-07-30]13:16:16.653 | Debug | RESIP:DUM | “1 -> AppDialogSet 1” |
[18-07-30]13:16:16.653 | Debug | RESIP:DUM | “2 -> ClientRegistration sip:[email protected]” |
[18-07-30]13:16:16.752 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RequestShutdown TU: DialogUsageManager size=0” |
[18-07-30]13:16:20.653 | Debug | Utilities | “Removing timer 256, m_cTimers.size() 4” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:20.653 | Debug | CCM | “Forced shutdown timer” | sua::CSIPDUMWrapper::OnTimer
[18-07-30]13:16:20.653 | Debug | CCM | “[event:EEventDUMMustDieTimer] -> [state:EWaitingOnDUMGracefully]” | sua::CSIPDUMWrapper::ProcessShutdownEvent
[18-07-30]13:16:20.653 | Debug | CCM | “” | sua::CSIPDUMWrapper::DoPostWaitingOnDUMGracefully
[18-07-30]13:16:20.653 | Debug | CCM | “” | sua::CSIPDUMWrapper::TransitionToWaitingOnDUMForced
[18-07-30]13:16:20.653 | Debug | Utilities | “Adding timer259, m_cTimers.size() 5” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:20.653 | Warning | RESIP:DUM | "force shutdown " |
[18-07-30]13:16:20.653 | Debug | RESIP:DUM | “Waiting for usages to be deleted (2)” |
[18-07-30]13:16:20.653 | Debug | RESIP:DUM | “1 -> AppDialogSet 1” |
[18-07-30]13:16:20.653 | Debug | RESIP:DUM | “2 -> ClientRegistration sip:[email protected]” |
[18-07-30]13:16:20.653 | Info | RESIP:DUM | “DialogUsageManager::onAllHandlesDestroyed: removing TU” |
[18-07-30]13:16:20.752 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RemoveTransactionUser TU: DialogUsageManager size=0” |
[18-07-30]13:16:20.752 | Info | RESIP:DUM | "TU unregistered " |
[18-07-30]13:16:20.752 | Debug | CCM | “[state:EWaitingOnDUMForced]” | sua::CSIPDUMWrapper::onDumCanBeDeleted
[18-07-30]13:16:20.752 | Debug | CCM | “[event:EEventDUMCanBeDeleted] -> [state:EWaitingOnDUMForced]” | sua::CSIPDUMWrapper::ProcessShutdownEvent
[18-07-30]13:16:20.752 | Debug | CCM | “” | sua::CSIPDUMWrapper::DoPostWaitingOnDUMForced
[18-07-30]13:16:20.752 | Debug | CCM | “Creating CDUMDestroyerActiveObject proxy. " | sua::CSIPDUMWrapper::TransitionToWaitingOnDestroyerActiveObject
[18-07-30]13:16:20.752 | Debug | Utilities | “Removing timer 259, m_cTimers.size() 4” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:20.752 | Debug | CCM | “[event:EEventDestroyerActiveObject] -> [state:EWaitingOnDestroyerActiveObject]” | sua::CSIPDUMWrapper::ProcessShutdownEvent
[18-07-30]13:16:20.752 | Debug | CCM | “” | sua::CSIPDUMWrapper::DoPostWaitingOnDestroyerActiveObject
[18-07-30]13:16:20.752 | Debug | RESIP:DUM | “DialogUsageManager::mDialogSetMap has 1 DialogSets” |
[18-07-30]13:16:20.752 | Debug | RESIP:DUM | “DialgSetId:NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.-9322ad3c” |
[18-07-30]13:16:20.752 | Debug | RESIP:DUM | “ClientRegistration::~ClientRegistration” |
[18-07-30]13:16:20.752 | Info | RESIP:DUM | “DialogUsageManager::destroy() not posting to stack” |
[18-07-30]13:16:20.752 | Debug | RESIP:DUM | “Waiting for usages to be deleted (1)” |
[18-07-30]13:16:20.752 | Debug | RESIP:DUM | " ********** DialogSet::~DialogSet: NzMwMTQ3NGJkMjFiNDBlZDJjMzZlYzU3ZTI3OTU4YjM.-9322ad3c*************” |
[18-07-30]13:16:20.752 | Debug | CCM | “[URI:[email protected]]” | sua::CSIPRegistration::OnAppDialogSetDestroy
[18-07-30]13:16:20.752 | Debug | CCM | “[URI:[email protected]]” | sua::CSIPRegistration::InternalShutdown
[18-07-30]13:16:20.752 | Debug | CCM | “Will attempt to re-REGISTER in 20 sec.[URI:[email protected]]” | sua::CSIPRegistrationWatcher::OnSIPRegistrationDestroyed
[18-07-30]13:16:20.752 | Debug | Utilities | “Adding timer263, m_cTimers.size() 5” | sua::CTimerManager::CreateTimer
[18-07-30]13:16:20.753 | Debug | RESIP | “SipStack::~SipStack()” |
[18-07-30]13:16:20.753 | Debug | RESIP | “BaseSecurity::~BaseSecurity” |
[18-07-30]13:16:20.753 | Debug | RESIP:TRANSPORT | “Shutting down [ V4 0.0.0.0:5998 TCP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.753 | Debug | RESIP:TRANSPORT | “ConnectionBase::~ConnectionBase 09F67E98” |
[18-07-30]13:16:20.753 | Debug | RESIP:TRANSPORT | “Shutting down [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.753 | Debug | RESIP:TRANSPORT | “Shutting down [ V4 0.0.0.0:5998 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.753 | Debug | RESIP:DUM | “~NatNavigator” |
[18-07-30]13:16:20.753 | Debug | RESIP:DUM | “~NatNavigator done” |
[18-07-30]13:16:20.753 | Debug | CCM | “[state:EState_RestartingDUM][T|T] [URI:[email protected]]” | sua::CSIPAccess::CreateDUM
[18-07-30]13:16:20.753 | Debug | RESIP | “BaseSecurity::BaseSecurity” |
[18-07-30]13:16:20.758 | Debug | RESIP:DNS | “number of name servers found 1” |
[18-07-30]13:16:20.758 | Debug | RESIP:DNS | “name server 192.168.1.254” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “Adding credential: realm=999.999.999.999 user=401” |
[18-07-30]13:16:20.759 | Debug | CCM | “[state:EInitial]” | sua::CSIPDUMWrapper::SetContainedObjects
[18-07-30]13:16:20.759 | Debug | CCM | “Overwriting pending… [id:152][worker-sz:2][pending:1]” | sua::CResipProcessThread::Add
[18-07-30]13:16:20.759 | Debug | CCM | “[state:EState_ReCreatingTransport][T|T] [URI:[email protected]]” | sua::CSIPAccess::CreateTransport
[18-07-30]13:16:20.759 | Info | CCM | “Creating transport… [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::Start
[18-07-30]13:16:20.759 | Debug | CCM | “Local IPs: <192.168.1.104>” | sua::CSIPAccess::CTransportCreator::Start
[18-07-30]13:16:20.759 | Debug | CCM | “[port:5999 (0->0)] [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::CreateNonTunnelingTransports
[18-07-30]13:16:20.759 | Info | CCM | “Not using firewall SIP proxy. Reasons: [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::UseFirewallSIPProxy
[18-07-30]13:16:20.759 | Debug | CCM | “Not using SBC/Firewall proxy. [URI:[email protected]]” | sua::CSIPAccess::CTransportCreator::CreateNonTunnelingTransports
[18-07-30]13:16:20.759 | Debug | CCM | “Trying to add a NatNavigator on port: 5999” | sua::CResipTransportCreator::AddNATNavTransportTryNextOpenPort
[18-07-30]13:16:20.759 | Info | RESIP:TRANSPORT | “Creating UDP transport host= port=5999 ipv4=1” |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Creating fd=2120 V4/UDP” |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Binding to 0.0.0.0” |
[18-07-30]13:16:20.759 | Info | CCM | “DSCP marking is already set correct for SIP or DNS signaling socket, where socket=2120, where transport type=3, where resip file is W:\Headsvn\SUA\Library\sipfoundry\main\resip\stack\InternalTransport.cxx, where resip line # is 120, where DSCP value=0” | sua::CCMAfterSocketCreationFuncPtr
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Adding transport: [ V4 0.0.0.0:5999 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.759 | Debug | CCM | “Trying to add a native transport on port: 5999” | sua::CResipTransportCreator::AddNativeTransportTryNextOpenPort
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “ConnectionBase::ConnectionBase, no params: 09ED3D80” |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “ConnectionManager::ConnectionManager() called " |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Creating fd=2240 V4/TCP” |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Binding to 0.0.0.0” |
[18-07-30]13:16:20.759 | Info | RESIP:TRANSPORT | “Creating TCP transport host= port=5999 ipv4=1” |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSPORT | “Adding transport: [ V4 0.0.0.0:5999 TCP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.759 | Debug | CCM | “[state:EState_ReCreatingTransport][T|T] [URI:[email protected]]” | sua::CSIPAccess::HandleTransportCreationSuccess
[18-07-30]13:16:20.759 | Debug | CCM | “[state:EStarting]” | sua::CSIPDUMWrapper::NotifyDUMIsReady
[18-07-30]13:16:20.759 | Debug | CCM | “Has current Registration: F[URI:[email protected]]” | sua::CSIPRegistrationWatcher::StartIfIdling
[18-07-30]13:16:20.759 | Debug | CCM | “[URI:[email protected]]” | sua::CSIPRegistration::Start
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “BaseCreator::makeInitialRequest: 040D7A00” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “RegistrationCreator::RegistrationCreator: 040D7A00” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | " ************* Created DialogSet(UAC) – NGE2YTBkZGRkNWZiNzFiNGIxODFlZjY2NTVjNWEwYTM.-e3273157*************” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | "SEND: REGISTER sip:999.999.999.999 SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-f87db363d32b0d45-1–d87543-;rport
Max-Forwards: 70
Contact: <sip;401;rinstance=09fbf0049662322d>
To: "“401"”<sip;[email protected]>
From: "“401"”<sip;[email protected]>;tag=e3273157
Call-ID: NGE2YTBkZGRkNWZiNzFiNGIxODFlZjY2NTVjNWEwYTM.
CSeq: 1 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0
" |
[18-07-30]13:16:20.759 | Debug | RESIP:TRANSACTION | "Adding application timer: " |
[18-07-30]13:16:20.759 | Info | RESIP:DUM | “Got a DumFeatureMessage09F3AA30” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “has obp” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “Next hop is 999.999.999.999” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “DialogId::DialogId: NGE2YTBkZGRkNWZiNzFiNGIxODFlZjY2NTVjNWEwYTM.-e3273157-” |
[18-07-30]13:16:20.759 | Debug | RESIP:DUM | “Using outbound proxy: sip:[email protected];lr -> SipReq: REGISTER 999.999.999.999 tid=f87db363d32b0d45 cseq=REGISTER contact=401 / 1 from(tu)” |
[18-07-30]13:16:20.760 | Debug | Utilities | “Removing timer 263, m_cTimers.size() 4” | sua::CTimerManager::CancelTimer
[18-07-30]13:16:20.859 | Debug | RESIP:TRANSACTION | “Adding timer: Timer F tid=f87db363d32b0d45 ms=32000” |
[18-07-30]13:16:20.859 | Debug | RESIP:DNS | “DnsResult::lookup sip:[email protected];lr” |
[18-07-30]13:16:20.859 | Debug | RESIP:DNS | “Numeric result so return immediately: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 connectionId=0 ]” |
[18-07-30]13:16:20.859 | Debug | RESIP:TRANSACTION | “Adding timer: Timer E1 tid=f87db363d32b0d45 ms=500” |
[18-07-30]13:16:20.861 | Debug | RESIP:TRANSPORT | “Looked up source for destination: [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 connectionId=0 ] -> [ V4 192.168.1.104:0 UDP target domain=999.999.999.999 connectionId=0 ] sent-by= sent-port=0” |
[18-07-30]13:16:20.861 | Debug | RESIP:TRANSPORT | “findTransportBySource([ V4 192.168.1.104:0 UDP target domain=999.999.999.999 connectionId=0 ])” |
[18-07-30]13:16:20.862 | Debug | RESIP:TRANSPORT | “findTransport (any port, any interface) => Transport: [ V4 0.0.0.0:5999 UDP target domain=unspecified connectionId=0 ]” |
[18-07-30]13:16:20.862 | Debug | RESIP:TRANSPORT | "Transmitting to [ V4 999.999.999.999:5060 UDP target domain=999.999.999.999 received on: Transport: [ V4 0.0.0.0:5999 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.104:5999 UDP target domain=999.999.999.999 connectionId=0 ]REGISTER sip:999.999.999.999 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.104:5999;branch=z9hG4bK-d87543-f87db363d32b0d45-1–d87543-;rport
Max-Forwards: 70

Just a suggestion…why not debug from the server side? If you have wireshark, which would be ideal, set the filter to the client IP address. If you do not have wireshark, try asterisk -rvvvvv on the console and see whether the SIP registrations are hitting your voip server or not and if they are reaching then you should see the response from the server going out. Not familiar with Xlite logs but it appears the SIP Register request from your xlite is not getting any response from the server. Can you ping the server from the device you are running xlite on?

Please get us some more information.
Is there a firewall between the phone and the PBX? Is the extension ChanSIP or PJSIP? What ports are you using?

And as @gdesilva said, a server side log will have more information.

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