Asterisk Community

Unable to register SIP extensions

Asterisk Asterisk General

the_robust October 15, 2012, 5:27pm 1

Hello Geeks,

I have recently installed a freepbx server on cloud where there is strict firewall policy however ports 5000-6000 are all open.
I have created a couple of extensions for testing but the extensions fail to register with server. I have extracted a log file from Bria however unable to understand the issue. could you kindly help me here?:

[i]Bria Professional 2.4.3 build 50906 label 2050i
Processor:Intel® Core™ i5 CPU M 480 @ 2.67GHz
Speed: 2670.000000, Class: High (state of the art machine)
Operating System: Unknown
Supported features: MMX, High Resolution Counter, FPU, SSE, SSE2

Time | Type | Subsystem | Message | Function | Location
[12-10-15]20:33:19.513 | Info | n/a | “Log level for all subsystems currently set at: ‘Info’” |
[12-10-15]20:33:19.513 | Info | n/a | “Log level for all subsystems currently set at: ‘Info’” |
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 48000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 49600” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec dvi4 due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 81600” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec dvi4_wb due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 24000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 30000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec gsm due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 29500” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 272000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec l16_wb due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 14000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec speex due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 32000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Not using codec speex_fec due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 20800” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.514 | Info | Audio | “Upstream: 512000, min: 64000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 48000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 49600” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec dvi4 due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 81600” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec dvi4_wb due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 80000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 24000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 30000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec gsm due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 29500” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 272000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec l16_wb due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 14000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec speex due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 32000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Not using codec speex_fec due to insufficient upstream bandwidth” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 20800” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:19.515 | Info | Audio | “Upstream: 512000, min: 64000” | sua::CAudioCodecSelectionManager::LoadAudioCodecList
[12-10-15]20:33:23.995 | Info | USB Devices | “First attempt to connect device” | cpsi::CPolycomUSB::Connect
[12-10-15]20:33:23.996 | Info | USB Devices | “Failed to create ‘CLSID_PlcmGobiCtrl’ COM instance for USB device: ‘Polycom Communicator’. USB devices from this manufacturer may not function with this application.” | cpsi::CPolycomUSB::Connect
[12-10-15]20:33:25.641 | Info | USB Devices | “First attempt to connect device” | cpsi::CPolycomUSB::Connect
[12-10-15]20:33:25.642 | Info | USB Devices | “Failed to create ‘CLSID_PlcmGobiCtrl’ COM instance for USB device: ‘Polycom Communicator’. USB devices from this manufacturer may not function with this application.” | cpsi::CPolycomUSB::Connect
[12-10-15]20:33:30.269 | Info | AbstractPhone | “[7001@46.137.194.48]::DisableAccount” | AbPhone::CAccount::DisableAccount
[12-10-15]20:33:30.269 | Info | RESIP:DUM | “shutdown: dialogSets=1” |
[12-10-15]20:33:30.269 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RequestShutdown TU: DialogUsageManager size=0” |
[12-10-15]20:33:30.308 | Info | GUI | “Set Phone State to ALL GOOD -> have fun” | frontier::ClientApplication::setPhoneState
[12-10-15]20:33:30.317 | Info | GUI | “Set Phone State to ALL GOOD -> have fun” | frontier::ClientApplication::setPhoneState
[12-10-15]20:33:32.434 | Info | AbstractPhone | “[7001@46.137.194.48]::EnableAccount” | AbPhone::CAccount::EnableAccount
[12-10-15]20:33:32.439 | Info | GUI | “Set Phone State to registering” | frontier::ClientApplication::setPhoneState
[12-10-15]20:33:32.440 | Info | GUI | “Set Phone State to registering” | frontier::ClientApplication::setPhoneState
[12-10-15]20:33:34.285 | Info | RESIP:DUM | “force shutdown " |
[12-10-15]20:33:34.285 | Info | RESIP:DUM | “DialogUsageManager::onAllHandlesDestroyed: removing TU” |
[12-10-15]20:33:34.286 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RemoveTransactionUser TU: DialogUsageManager size=0” |
[12-10-15]20:33:34.286 | Info | RESIP:DUM | “TU unregistered " |
[12-10-15]20:33:34.288 | Info | RESIP:TRANSPORT | “Shutting down [ V4 0.0.0.0:52985 UDP target domain=unspecified mFlowKey=1892 ]” |
[12-10-15]20:33:34.289 | Info | AbstractPhone | “[7001@46.137.194.48]::EnableAccount” | AbPhone::CAccount::EnableAccount
[12-10-15]20:33:34.289 | Info | DNS | “DNS [query:46.137.194.48]” | sua::CDNS::StartTopologyLookup
[12-10-15]20:33:34.289 | Info | DNS | “DNS-Lookup performed: ‘_sip._udp.’ ‘46.137.194.48’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | " 0 - [ip:46.137.194.48:5060][ttl:4294967295][P:0][W:0][query-name:46.137.194.48]” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | “DNS [query:46.137.194.48]” | sua::CDNS::StartTopologyLookup
[12-10-15]20:33:34.289 | Info | DNS | “DNS-Lookup performed: ‘_sip._tcp.’ ‘46.137.194.48’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | " 0 - [ip:46.137.194.48:5060][ttl:4294967295][P:0][W:0][query-name:46.137.194.48]” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | AbstractPhone | “Receiving notification about firewall IP address: 0.0.0.0, voip always possible: 0” | AbPhone::CAbstractPhone::OnFirewallInformation
[12-10-15]20:33:34.289 | Info | DNS | “DNS [query:46.137.194.48]” | sua::CDNS::StartTopologyLookup
[12-10-15]20:33:34.289 | Info | DNS | “DNS-Lookup performed: ‘_sip._udp.’ ‘46.137.194.48’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | " 0 - [ip:46.137.194.48:5060][ttl:4294967295][P:0][W:0][query-name:46.137.194.48]" | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | “DNS [query:46.137.194.48]” | sua::CDNS::StartTopologyLookup
[12-10-15]20:33:34.289 | Info | DNS | “DNS-Lookup performed: ‘_sip._tcp.’ ‘46.137.194.48’ [default-port:5060][fallback to A/QA:T] - Results:” | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | DNS | " 0 - [ip:46.137.194.48:5060][ttl:4294967295][P:0][W:0][query-name:46.137.194.48]" | sua::CDNS::InternalShutdown
[12-10-15]20:33:34.289 | Info | GUI | “Set Phone State to registering” | frontier::ClientApplication::setPhoneState
[12-10-15]20:33:34.290 | Info | AbstractPhone | “Receiving notification about firewall IP address: 0.0.0.0, voip always possible: 0” | AbPhone::CAbstractPhone::OnFirewallInformation
[12-10-15]20:33:34.319 | Info | RESIP:DNS | “DNS initialization: found 2 name servers” |
[12-10-15]20:33:34.319 | Info | RESIP:DNS | " name server: 10.0.0.3" |
[12-10-15]20:33:34.319 | Info | RESIP:DNS | " name server: 8.8.8.8" |
[12-10-15]20:33:34.321 | Info | RESIP | “Root System Cert Store opened” |
[12-10-15]20:33:34.327 | Info | RESIP | “38 certs loaded of type 1” |
[12-10-15]20:33:34.328 | Info | RESIP | “My System Cert Store opened” |
[12-10-15]20:33:34.328 | Info | RESIP | “Certificate doesn’t contain vaild SIP subjectAltName; ignoring” |
[12-10-15]20:33:34.328 | Info | CCM | “Creating transport… [URI:7001@46.137.194.48]” | sua::CSIPAccess::CTransportCreator::Start
[12-10-15]20:33:34.328 | Info | CCM | “Not using firewall SIP proxy. Reasons: [URI:7001@46.137.194.48]” | sua::CSIPAccess::CTransportCreator::UseFirewallSIPProxy
[12-10-15]20:33:34.328 | Info | RESIP:TRANSPORT | “Creating UDP transport host= port=21262 ipv4=1” |
[12-10-15]20:33:34.328 | Info | CCM | “DSCP marking is set for SIP or DNS signaling socket, where socket=2224, where transport type=3, where resip file is C:\Workspace\dev\ua\sdk\contrib\sipfoundry\main\resip\stack\InternalTransport.cxx, where resip line # is 122, where DSCP value=40” | sua::CCMAfterSocketCreationFuncPtr
[12-10-15]20:33:34.329 | Info | RESIP:TRANSPORT | “Creating TCP transport host= port=21262 ipv4=1” |
[12-10-15]20:33:34.329 | Info | RESIP:TRANSPORT | “Creating TLS transport for domain interface= port=21263” |
[12-10-15]20:33:34.329 | Info | RESIP:DUM | “Got a DumFeatureMessage055E2070” |
[12-10-15]20:33:34.330 | Info | GUI | “Set Phone State to registering” | frontier::ClientApplication::setPhoneState
[12-10-15]20:34:06.330 | Info | RESIP:DUM | “Got: SipResp: 408 tid=6543a353a60df812 cseq=REGISTER / 1 from(wire)” |
[12-10-15]20:34:06.330 | Info | RESIP:DUM | “shutdown: dialogSets=1” |
[12-10-15]20:34:06.330 | Warning | AbstractPhone | “SIP registration failed; reason: ‘SipError’; SIP error-code: 408; error-phrase: ‘Request Timeout’” | cpsi::AccountImpl::OnRegistrationStatusChanged
[12-10-15]20:34:06.330 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RequestShutdown TU: DialogUsageManager size=0” |
[12-10-15]20:34:06.383 | Info | GUI | “Set Phone State to registration failed for at least one account” | frontier::ClientApplication::setPhoneState
[12-10-15]20:34:11.285 | Info | RESIP:DUM | “force shutdown " |
[12-10-15]20:34:11.285 | Info | RESIP:DUM | “DialogUsageManager::onAllHandlesDestroyed: removing TU” |
[12-10-15]20:34:11.285 | Info | RESIP:TRANSACTION | “TransactionUserMessage::RemoveTransactionUser TU: DialogUsageManager size=0” |
[12-10-15]20:34:11.285 | Info | RESIP:DUM | “TU unregistered " |
[12-10-15]20:34:11.285 | Info | RESIP:DUM | “DialogUsageManager::destroy() not posting to stack” |
[12-10-15]20:34:11.288 | Info | RESIP:TRANSPORT | “Shutting down [ V4 0.0.0.0:21262 UDP target domain=unspecified mFlowKey=2224 ]” |
[12-10-15]20:34:11.316 | Info | RESIP:DNS | “DNS initialization: found 2 name servers” |
[12-10-15]20:34:11.316 | Info | RESIP:DNS | " name server: 10.0.0.3” |
[12-10-15]20:34:11.316 | Info | RESIP:DNS | " name server: 8.8.8.8” |
[12-10-15]20:34:11.318 | Info | RESIP | “Root System Cert Store opened” |
[12-10-15]20:34:11.324 | Info | RESIP | “38 certs loaded of type 1” |
[12-10-15]20:34:11.325 | Info | RESIP | “My System Cert Store opened” |
[12-10-15]20:34:11.325 | Info | RESIP | “Certificate doesn’t contain vaild SIP subjectAltName; ignoring” |
[12-10-15]20:34:11.325 | Info | CCM | “Creating transport… [URI:7001@46.137.194.48]” | sua::CSIPAccess::CTransportCreator::Start
[12-10-15]20:34:11.325 | Info | CCM | “Not using firewall SIP proxy. Reasons: [URI:7001@46.137.194.48]” | sua::CSIPAccess::CTransportCreator::UseFirewallSIPProxy
[12-10-15]20:34:11.325 | Info | RESIP:TRANSPORT | “Creating UDP transport host= port=21263 ipv4=1” |
[12-10-15]20:34:11.325 | Info | CCM | “DSCP marking is set for SIP or DNS signaling socket, where socket=2224, where transport type=3, where resip file is C:\Workspace\dev\ua\sdk\contrib\sipfoundry\main\resip\stack\InternalTransport.cxx, where resip line # is 122, where DSCP value=40” | sua::CCMAfterSocketCreationFuncPtr
[12-10-15]20:34:11.326 | Info | RESIP:TRANSPORT | “Creating TCP transport host= port=21263 ipv4=1” |
[12-10-15]20:34:11.326 | Info | RESIP:TRANSPORT | “Creating TLS transport for domain interface= port=21264” |
[12-10-15]20:34:11.326 | Info | RESIP:DUM | “Got a DumFeatureMessage0D4999D8” |
[12-10-15]20:34:43.326 | Info | RESIP:DUM | “Got: SipResp: 408 tid=284f3e36c335146e cseq=REGISTER / 1 from(wire)” |
[12-10-15]20:35:15.327 | Info | RESIP:TRANSACTION | "Stats message " |
[12-10-15]20:35:15.327 | Info | RESIP:STATS | “RESIP:TRANSACTION
TU summary: 0 TRANSPORT 0 TRANSACTION 0 CLIENTTX 0 SERVERTX 0 TIMERS 0
Transaction summary: reqi 0 reqo 11 rspi 0 rspo 0
Details: INVi 0/S0/F0 INVo 0/S0/F0 ACKi 0 ACKo 0 BYEi 0/S0/F0 BYEo 0/S0/F0 CANi 0/S0/F0 CANo 0/S0/F0 MSGi 0/S0/F0 MSGo 0/S0/F0 OPTi 0/S0/F0 OPTo 0/S0/F0 REGi 0/S0/F0 REGo 1/S0/F0 PUBi 0/S0/F0 PUBo 0/S0/F0 SUBi 0/S0/F0 SUBo 0/S0/F0 NOTi 0/S0/F0 NOTo 0/S0/F0
Retransmissions: INVx 0 BYEx 0 CANx 0 MSGx 0 OPTx 0 REGx 10 finx 0 nonx 0 PUBx 0 SUBx 0 NOTx 0” |
[12-10-15]20:35:15.327 | Info | RESIP:DUM | “Got a DumFeatureMessage0D344AF0” |
[12-10-15]20:35:36.336 | Info | RESIP:TRANSPORT | “Exception writing to socket 2844 code: 10060; closing connection” |
[12-10-15]20:35:36.344 | Info | RESIP:TRANSACTION | “Sending ConnectionTerminated [ V4 46.137.194.48:5060 TCP target domain=46.137.194.48 mFlowKey=2844 ] to TUs” |
[12-10-15]20:35:36.344 | Info | RESIP:TRANSACTION | “Try sending request to a different dns result” |
[12-10-15]20:35:36.344 | Info | RESIP:TRANSACTION | “Ran out of dns entries for 46.137.194.48. Send 503” |
[12-10-15]20:35:36.345 | Info | RESIP:DNS | “local hostname does not contain a domain part Mustafa-PC” |
[12-10-15]20:35:36.349 | Info | RESIP:DUM | “Got: SipResp: 503 tid=18690e0daf446528 cseq=REGISTER / 2 from(wire)” |
[12-10-15]20:35:38.885 | Info | GUI | “Set Phone State to registration failed for at least one account” | frontier::ClientApplication::setPhoneState
[12-10-15]20:35:39.284 | Info | RESIP:DUM | “Got a DumFeatureMessage0D492AF8” |
[12-10-15]20:35:39.293 | Info | RESIP:TRANSPORT | “Creating TLS connection for domain [ V4 46.137.194.48:5061 TLS target domain=46.137.194.48 mFlowKey=0 ] on 2844” |
[12-10-15]20:35:40.002 | Info | USB Devices | “First attempt to connect device” | cpsi::CPolycomUSB::Connect
[12-10-15]20:35:40.003 | Info | USB Devices | “Failed to create ‘CLSID_PlcmGobiCtrl’ COM instance for USB device: ‘Polycom Communicator’. USB devices from this manufacturer may not function with this application.” | cpsi::CPolycomUSB::Connect
[/i]

david55 October 15, 2012, 5:39pm 2

Have you opened the ports used by SIP? Is there anything on the Asterisk log (it will give a clue as to whether the firewall blocked the REGISTER outbound, or the response, inbound)?

the_robust October 15, 2012, 5:56pm 3

as already mentioned, ports 5000-6000 are open on firewall… do i need to open other ports as well?

the_robust October 15, 2012, 7:11pm 4

UPDATE:
i have installed one more freepbx server on cloud with utterly no firewall. selinux and iptables also disabled but still unable to register SIP users.
Any suggestion?.. how could i retrieve logs (if any) from asterisk server?

david55 October 15, 2012, 8:26pm 5

The trace suggests that Bria is using much higher port numbers as its source port, and the one to which the reply should go.

Once you get registers to work, you need to open the port number ranges used by each side for RTP.

You will need TCP ports open for encrypted SIP.

the_robust October 15, 2012, 8:36pm 6

thatz weired… i have opened 10000-20000 ports for RTP and still its showing this

david55 October 16, 2012, 12:47pm 7

[12-10-15]20:34:11.325 | Info | RESIP:TRANSPORT | “Creating UDP transport host= port=[color=#FF0000]21263[/color] ipv4=1” |

I think you need to open 1024 through 65535 towards Bria, unless you can restrict its choice.

the_robust October 16, 2012, 12:51pm 8

Yeah… thatz my quest now… how cud i restrict Bria’s choice?

david55 October 16, 2012, 1:00pm 9

Probably be restricting the choice of the underlying OS. It is probably just asking the OS for a free port.

the_robust October 16, 2012, 1:09pm 10

Hmn… seems thatz gonna b a tough job on windows OS’s though :-/