Can't Register with SIP Trunk

[jnthodge (Jason)]

I have an asterisk/freepbx setup that is connecting to a clearfly SIP Trunk. Problem is, we lost power for 4 days due to a storm. When we got power back, it’s not connecting to the SIP Trunk. Here are the contents of some of the log files when I tailed the logs in /var/logs/asterisk while I issue a “sip reload” from the CLI in FreePBX Admin:

Are there any hints in there as to why my server will no longer attempt to register to the SIP Trunk? Clearfly has confirmed that they are not receiving any registration requests.

Thanks!!

==> fail2ban <==
[2020-09-13 19:16:22] SECURITY[2375] res_security_log.c: SecurityEvent=“FailedACL”,EventTV=“2020-09-13T19:16:22.313+0000”,Severity=“Error”,Service=“PJSIP”,EventVersion=“1”,AccountID=“anonymous”,SessionID=“444007907-532038660-445775167”,LocalAddress=“IPV4/UDP/192.168.10.36/5060”,RemoteAddress=“IPV4/UDP/185.108.106.251/59664”,ACLName=“registrar_attempt_without_configured_aors”
[2020-09-13 19:16:25] WARNING[4712][C-0000002b] Ext. s: “Rejecting unknown SIP connection from 77.247.178.140:59625”
[2020-09-13 19:16:29] WARNING[4713][C-0000002c] Ext. s: “Rejecting unknown SIP connection from 45.143.220.225:65500”
[2020-09-13 19:16:41] WARNING[4715][C-0000002d] Ext. s: “Rejecting unknown SIP connection from 77.247.178.141:65251”
[2020-09-13 19:16:50] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:16:50.120+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff10c000b10”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39924”,UsingPassword=“0”,SessionTV=“2020-09-13T19:16:50.120+0000”
[2020-09-13 19:16:54] WARNING[4734][C-0000002e] Ext. s: “Rejecting unknown SIP connection from 37.49.229.237:16674”
[2020-09-13 19:16:55] WARNING[2326] res_pjsip_registrar.c: Endpoint ‘anonymous’ has no configured AORs
[2020-09-13 19:16:55] SECURITY[2375] res_security_log.c: SecurityEvent=“FailedACL”,EventTV=“2020-09-13T19:16:55.297+0000”,Severity=“Error”,Service=“PJSIP”,EventVersion=“1”,AccountID=“anonymous”,SessionID=“157996911-1562040402-1123550758”,LocalAddress=“IPV4/UDP/192.168.10.36/5060”,RemoteAddress=“IPV4/UDP/185.108.106.251/63933”,ACLName=“registrar_attempt_without_configured_aors”
[2020-09-13 19:17:01] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:01.718+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff11c0009d0”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39930”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:01.718+0000”
[2020-09-13 19:17:05] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:05.168+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff114000bb0”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39936”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:05.168+0000”

==> fail2ban-20200913 <==
[2020-09-13 03:11:02] WARNING[9555][C-000000a5] Ext. s: “Rejecting unknown SIP connection from 45.143.220.225:57839”
[2020-09-13 03:11:20] SECURITY[2810] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T03:11:20.744+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff494002880”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/51038”,UsingPassword=“0”,SessionTV=“2020-09-13T03:11:20.744+0000”
[2020-09-13 03:11:26] SECURITY[2810] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T03:11:26.284+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff490001530”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/51044”,UsingPassword=“0”,SessionTV=“2020-09-13T03:11:26.284+0000”
[2020-09-13 03:11:38] WARNING[2760] res_pjsip_registrar.c: Endpoint ‘anonymous’ has no configured AORs
[2020-09-13 03:11:38] SECURITY[2810] res_security_log.c: SecurityEvent=“FailedACL”,EventTV=“2020-09-13T03:11:38.738+0000”,Severity=“Error”,Service=“PJSIP”,EventVersion=“1”,AccountID=“anonymous”,SessionID=“233421537-885491550-1737642707”,LocalAddress=“IPV4/UDP/192.168.10.36/5060”,RemoteAddress=“IPV4/UDP/185.108.106.251/50248”,ACLName=“registrar_attempt_without_configured_aors”
[2020-09-13 03:11:41] WARNING[9630][C-000000a6] Ext. s: “Rejecting unknown SIP connection from 77.247.178.140:58507”
[2020-09-13 03:11:51] WARNING[9631][C-000000a7] Ext. s: “Rejecting unknown SIP connection from 46.166.151.103:62246”
[2020-09-13 03:11:53] WARNING[9633][C-000000a8] Ext. s: “Rejecting unknown SIP connection from 77.247.178.141:60684”
[2020-09-13 03:11:56] SECURITY[2810] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T03:11:56.011+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff4b00016b0”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/51052”,UsingPassword=“0”,SessionTV=“2020-09-13T03:11:56.011+0000”
[2020-09-13 03:11:58] WARNING[9652][C-000000a9] Ext. s: “Rejecting unknown SIP connection from 45.143.220.225:53915”

==> ucp_err.log <==
2020-09-13 00:20 +00:00: { Error: Can’t connect to MySQL server on ‘127.0.0.1’ (111 “Connection refused”) code: 2003 }
2020-09-13 00:20 +00:00: There was an error with MySQL Connection
2020-09-13 00:20 +00:00: { Error: Can’t connect to MySQL server on ‘127.0.0.1’ (111 “Connection refused”) code: 2003 }
2020-09-13 00:20 +00:00: There was an error with MySQL Connection
2020-09-13 00:20 +00:00: { Error: Can’t connect to MySQL server on ‘127.0.0.1’ (111 “Connection refused”) code: 2003 }
2020-09-13 00:20 +00:00: There was an error with MySQL Connection
2020-09-13 10:30 +00:00: { Error: MySQL server has gone away code: 2006 }
2020-09-13 10:30 +00:00: There was an error with MySQL Connection
2020-09-13 18:30 +00:00: { Error: MySQL server has gone away code: 2006 }
2020-09-13 18:30 +00:00: There was an error with MySQL Connection

==> ucp_out.log <==
2020-09-13 18:57 +00:00: Secure Server up and running at 8003 port
2020-09-13 19:06 +00:00: Starting FreePBX…2020-09-13 19:06 +00:00: FreePBX is Ready!
2020-09-13 19:06 +00:00: Asterisk version is: 16.13.0
2020-09-13 19:06 +00:00: Loading all UCP Modules…
2020-09-13 19:06 +00:00: Loading…conferencespro.js
2020-09-13 19:06 +00:00: Loading…ucphelloworld.js
2020-09-13 19:06 +00:00: Loading…xmpp.js
2020-09-13 19:06 +00:00: Done!
2020-09-13 19:06 +00:00: Server up and running at 8001 port
2020-09-13 19:06 +00:00: Secure Server up and running at 8003 port

==> xmpp_err.log <==
at Pool.emit (events.js:211:7)
at Connection. (/var/www/html/admin/modules/xmpp/node/node_modules/mongoose/node_modules/mongodb-core/lib/connection/pool.js:280:12)
at Object.onceWrapper (events.js:317:30)
at emitTwo (events.js:126:13)
at Connection.emit (events.js:214:7)
at Socket. (/var/www/html/admin/modules/xmpp/node/node_modules/mongoose/node_modules/mongodb-core/lib/connection/connection.js:189:49)
at Object.onceWrapper (events.js:315:30)
at emitOne (events.js:116:13)
at Socket.emit (events.js:211:7)
2020-09-13 19:06 +00:00: (node:3016) DeprecationWarning: open() is deprecated in mongoose >= 4.11.0, use openUri() instead, or set the useMongoClient option if using connect() or createConnection(). See http://mongoosejs.com/docs/4.x/docs/connections.html#use-mongo-client

==> fail2ban <==
[2020-09-13 19:17:09] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:09.346+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff118001f80”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39942”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:09.346+0000”
[2020-09-13 19:17:19] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:19.718+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff120029df0”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39948”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:19.718+0000”

==> fail2ban <==
[2020-09-13 19:17:25] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:25.360+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x1f56b30”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39956”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:25.360+0000”
[2020-09-13 19:17:25] WARNING[4842][C-0000002f] Ext. s: “Rejecting unknown SIP connection from 45.143.220.225:58667”
[2020-09-13 19:17:26] WARNING[4843][C-00000030] Ext. s: “Rejecting unknown SIP connection from 46.166.151.103:52118”
[2020-09-13 19:17:29] SECURITY[2375] res_security_log.c: SecurityEvent=“SuccessfulAuth”,EventTV=“2020-09-13T19:17:29.434+0000”,Severity=“Informational”,Service=“AMI”,EventVersion=“1”,AccountID=“admin”,SessionID=“0x7ff070004920”,LocalAddress=“IPV4/TCP/127.0.0.1/5038”,RemoteAddress=“IPV4/TCP/127.0.0.1/39962”,UsingPassword=“0”,SessionTV=“2020-09-13T19:17:29.434+0000”

[dicko]

2020-09-13 10:30 +00:00: { Error: MySQL server has gone away code: 2006 }

why is mysqld/mariadb not starting?

[jnthodge (Jason)]

I’ve no idea. Is that the root issue? I checked all the databases and they came back OK. I’ll look more into that this evening. Is it always used by asterisk/free-pbx, or might there be an alternative data store?

Thanks for looking at this. I’m a newby, but not un-technical.

Jason

[dicko]

It is always used and essential, it converts the GUI stuff to conf files that asterisk can work with. depending on your version of FreePBX/OS it might be mysql(d) or mariadb, either-way, from a shell, :-

mysql

should return you a mysql CLI with versioning included. If it doesn’t you need to fix that.

[jnthodge (Jason)]

It looks like I got a good connection locally:

[root@freepbx ~]# mysql
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 2093
Server version: 5.5.65-MariaDB MariaDB Server

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.

But I see what you’re saying as well in the logs. I don’t necessarily know what’s next, but this is a strong hint. I’ll start pulling on this thread.

Thanks!

[jnthodge (Jason)]

Which log files are the most important to watch for information about SIP Trunk registration failures?

[dicko]

/var/log/asterisk/full

[jnthodge (Jason)]

Is Redis also a critical component of asterisk? I’m getting lots of these:

[2020-Sep-13 19:22:15] [freepbx.INFO]: Connection attmempt to AMI failed [] []
[2020-Sep-13 19:22:15] [freepbx.INFO]: Redis enabled but not running, falling back to filesystem [Redis server went away]. Either fix Redis or remove the php redis extension [] []
[2020-Sep-13 19:22:50] [freepbx.INFO]: Connection attmempt to AMI failed [] []

in the logs. I also get this upon issuing “service asterisk restart” from the Linux command-line:

[root@freepbx asterisk]# service asterisk restart
Restarting asterisk (via systemctl): Job for asterisk.service failed. See “systemctl status asterisk.service” and “journalctl -xe” for details.
[FAILED]

journalctl -xe yields this result:

[root@freepbx asterisk]# journalctl -xe
Sep 14 01:47:01 freepbx.sangoma.local systemd[1]: Started Session 74 of user asterisk.
– Subject: Unit session-74.scope has finished start-up
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit session-74.scope has finished starting up.

– The start-up result is done.
Sep 14 01:47:01 freepbx.sangoma.local systemd[1]: Started Session 75 of user asterisk.
– Subject: Unit session-75.scope has finished start-up
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit session-75.scope has finished starting up.

– The start-up result is done.
Sep 14 01:47:01 freepbx.sangoma.local systemd[1]: Started Session 76 of user asterisk.
– Subject: Unit session-76.scope has finished start-up
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit session-76.scope has finished starting up.

– The start-up result is done.
Sep 14 01:47:01 freepbx.sangoma.local CROND[6608]: (asterisk) CMD ([ -e /usr/sbin/fwconsole ] && sleep $((RANDOM%30)) && /usr/sbin/fwconsole job --run --quiet 2>&1 > /dev/
Sep 14 01:47:01 freepbx.sangoma.local CROND[6609]: (asterisk) CMD (/usr/sbin/fwconsole util cleanplaybackcache -q)
Sep 14 01:47:01 freepbx.sangoma.local CROND[6610]: (asterisk) CMD (/usr/sbin/fwconsole queuestats --syncall >> /tmp/reader.log 2>&1)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6656]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6658]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6660]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6662]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6664]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6665]: (asterisk) REPLACE (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6667]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6669]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6670]: (asterisk) REPLACE (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local crontab[6672]: (asterisk) LIST (asterisk)
Sep 14 01:47:09 freepbx.sangoma.local systemd[1]: Removed slice User Slice of asterisk.
– Subject: Unit user-995.slice has finished shutting down
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit user-995.slice has finished shutting down.
Sep 14 01:47:14 freepbx.sangoma.local runuser[6702]: pam_unix(runuser:session): session opened for user asterisk by (uid=0)
Sep 14 01:47:14 freepbx.sangoma.local runuser[6702]: pam_unix(runuser:session): session closed for user asterisk

[jnthodge (Jason)]

I rebooted the server and checked the asterisk status (service asterisk status):

● asterisk.service - LSB: Asterisk PBX
Loaded: loaded (/etc/rc.d/init.d/asterisk; bad; vendor preset: disabled)
Active: inactive (dead)
Docs: man:systemd-sysv-generator(8)
[root@freepbx ~]#
Broadcast message from [email protected] (Mon Sep 14 01:55:34 2020):

Firewall service now starting.

[jnthodge (Jason)]

Never mind, I’m stupid. I just read this: Asterisk won't restart?
…and learned that the service control tooling on linux isn’t supposed to manage asterisk or report its status correctly. I did the “asterisk -r” command and it is indeed running.

Connected to Asterisk 16.13.0 currently running on freepbx (pid = 2332)
freepbx*CLI>

What to do at this prompt, I have no idea. But there it is.

[jnthodge (Jason)]

By the way, /var/log/asterisk/full is completely empty. I verified its ownership, it’s asterisk:asterisk.

Still doesn’t register the SIP Trunk, btw.

[lgaetz (Lorne Gaetz)]

@jnthodge

/var/log/asterisk/full is completely empty

Bug in Asterisk Logfiles Module ver 15.0.4

Last week a security update was published for the Asterisk Logfiles module to resolve a cross site scripting vulnerability, version 15.0.4. Many (perhaps most) systems would have received the update and installed it automatically in the early morning of August 19. In addition to the XSS fix, there were improvements in logfiles browsing as well as updates on the way the logfiles are managed. Version 15.0.4 has a new bug that changed the default settings for the full log and console such that log…

[jnthodge (Jason)]

Well, I recreated the SIP Trunk using chan_sip. It immediately started working. It might have worked equally well if I’d re-created it using pjsip as originally configured, don’t know. It was late.

One thing to note, it was transmitting the wrong caller id. I had to remove one “fromuser” attribute from the connect properties, and it started working perfectly. I found this line: " 1. If your outbound calls never have the correct Caller ID, delete the fromuser= line." at this URL: https://wiki.freepbx.org/display/F2/Trunk+Sample+Configurations

This issue was happening because Clearfly originally setup my account using a starter phone number before we decided which phone numbers to port to the new setup. This sample phone number has remained as our account number.

In the end, I would guess that something got corrupted during our outage in the pjsip settings for that trunk. Re-creating it should probably be my normative approach to troubleshooting these connectivity/registration issues in the future.

I will re-attempt to re-create the trunk using pjsip in the near future, as chan_sip seems to be deprecated. For the moment, I’m up and running. Thanks for the hints and guidance. I learned a lot during this painful saga.