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