Newly restored system, outbound calls failing, some odd codec mismatch I think

Greetings, I have a system that I rebuilt from scratch and did a restore on. Post restore everything seems to be fine with the exception of outbound calling. It fails and I think it is a codec mismatch although EVERYTHING is manually set to ulaw at this point. The old system previously ran on 729 and I have a sneaking suspicion that even though it was changed to ulaw it was still running 729. And now that I have restored to a new system that has no 729 installed its failing on the outbound.

The system in question (and the previous one) were from the latest v13 Distro and are current in patches/updates.

Everything is set to ULAW , system, phones and trunks.

Here are some logging that is of importance I believe.

Thank you in advance

==========
[2016-10-17 15:39:11] WARNING[6693][C-00000004] channel.c: Unable to find a codec translation path: (gsm|alaw|ulaw) -> (g729)
[2016-10-17 15:39:11] WARNING[6693][C-00000004] file.c: Unable to open agent-loggedoff (format (g729)): No such file or directory
[2016-10-17 15:39:11] WARNING[6693][C-00000004] app_playback.c: Playback failed on SIP/501-0000000b for agent-loggedoff

[2016-10-17 15:59:25] WARNING[28580] res_odbc.c: res_odbc: Error SQLConnect=-1 errno=1045 [unixODBC][MySQL][ODBC 5.1 Driver]Access denied for user ‘freepbxuser’@‘localhost’ (using password:
[2016-10-17 15:59:25] NOTICE[28580] res_odbc.c: Registered ODBC class ‘asteriskcdrdb’ dsn->[MySQL-asteriskcdrdb]

[2016-10-17 16:45:15] WARNING[12927][C-0000000c]: channel.c:6405 ast_channel_make_compatible_helper: No path to translate from SIP/outbound-0000001f to SIP/508-0000001e

I’m not sure that all of the 729 references in your system have been purged, especially if you pulled the config from a backup. Specifically, I’m gonna guess that the extensions still have 729 listed as the primary codec. That’s just a guess, though.

For example, your agent-loggedoff message appears to be trying to go back to a phone that’s connected via 729. Your “make_compatible_helper” error in the last line looks like the same thing.

Try doing this from the console:

grep 729 /etc/asterisk/*.conf

You’ll probably get a bunch of false positives, but I think you’ll find at least one or two references to G729 in that list.

The middle one is just because the password changed on the new connection from the server to freepbxuser on MySQL. That one’s easy to fix, just log into the MySQL database and update the password for the freepbxuser to match the password in your config file.

So here is that output. But this is also something I noticed. I have settings on extensions that show in sip_additional.conf that I have removed in the GUI. For example I do see allow=g729 but those settings were removed from the extensions as of this morning following the issue. So it is as if those changes are not taking effect. I even deleted an extension and put it back with new settings but in that conf file it still shows all the old ones. See below.

namedpickupgroup=
allow=g729 <-- removed in gui
allow=ulaw <-- also removed (currently those settings are default for that ext)
dial=SIP/501

/etc/asterisk/musiconhold_additional.conf:format=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729
/etc/asterisk/sip_additional.conf:allow=g729

The _additional.conf files are all maintained my FreePBX, which pulls the information out of the FreePBX configuration tables. Changing the files won’t help you, because the next reload will just recreate them.

I don’t know all of the places that these options can get set, but I’d start with the SIP Settings in the Advanced menu. The defaults for the system are all maintained in there - perhaps the defaults are getting picked up there.

Another option would be to go through the various places that you see in your “grep” and set, then unset, the G729 options.

Maybe @lgaetz can help out with some insight into where these could be getting set outside of the basic extension configuration.

Right, but that is what I am saying. I have 729 removed from the gui settings but they are still showing in the conf files the system is generating for use.

Working from a restore means that the database gets polled and may not be reflected in the GUI. Setting the option in the GUI, saving, deploying, and the reversing the process may get the data out of the database.

Failing that, if you’re extremely brave and willing to accept the possibility that it may screw up your whole day, you can connect to the database directly and remove the items by hand.

I am not 100% sure what you mean here. Can you explain further? Right now it just seems to me the restore info is being used and when I attempt to change it, it shows correct in the GUI but not in the conf files.

Thank You

I’m guessing that the data in the database is actually broken, but the information in the GUI is what you see. Think of it as turning off a light bulb. If it’s already off, you can’t turn it off - all you can do is turn it on. Once it’s on, you can then actually turn it off.

Since you did a restore, it’s possible that the data in the file isn’t actually getting reset. Change the GUI to match the file (turn on G729) and then save it. Now the file matches the GUI. Now, turn it back off and see if it turns it off in the file.

OK so I go that a shot. I even deleted an extension and recreated and the settings don’t seem to change. So it appears changes to the gui are not being reflected in the system generated conf files. I even rebooted a time or 2 for the heck of it but that did not help either.

If it helps here is a grep for “ERROR” in my full log file.

Also I just realized this. While the system backup came from the same version of FreePBX that was restored to the previous system had Asterisk v11 and the new one is v13.

And with that said I see that all my “additional” conf files are from the backup time period and have not changed since. Another words they are all labeled october 12th from when I did the backup on the old system.

[2016-10-18 00:57:39] ERROR[20041] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 00:57:39] ERROR[20041] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20046] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20041] res_config_sqlite3.c: Missing config file ‘res_config_sqlite3.conf’
[2016-10-18 00:57:39] ERROR[20041] res_config_ldap.c: Cannot load configuration file: res_ldap.conf
[2016-10-18 00:57:39] ERROR[20041] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20041] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:57:39] ERROR[20041] cel_custom.c: Unable to load cel_custom.conf. Not logging CEL to custom CSVs.
[2016-10-18 00:57:39] ERROR[20041] cdr_custom.c: Unable to load cdr_custom.conf. Not logging custom CSV CDRs.
[2016-10-18 00:57:39] ERROR[20041] res_clialiases.c: res_clialiases configuration file ‘cli_aliases.conf’ not found
[2016-10-18 00:59:13] ERROR[21739] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 00:59:13] ERROR[21739] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21739] res_config_sqlite3.c: Missing config file ‘res_config_sqlite3.conf’
[2016-10-18 00:59:13] ERROR[21739] res_config_ldap.c: Cannot load configuration file: res_ldap.conf
[2016-10-18 00:59:13] ERROR[21739] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21739] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:13] ERROR[21739] cel_custom.c: Unable to load cel_custom.conf. Not logging CEL to custom CSVs.
[2016-10-18 00:59:13] ERROR[21739] cdr_custom.c: Unable to load cdr_custom.conf. Not logging custom CSV CDRs.
[2016-10-18 00:59:13] ERROR[21739] res_clialiases.c: res_clialiases configuration file ‘cli_aliases.conf’ not found
[2016-10-18 00:59:51] ERROR[22493] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 00:59:52] ERROR[22493] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[21747] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[22493] res_config_sqlite3.c: Missing config file ‘res_config_sqlite3.conf’
[2016-10-18 00:59:52] ERROR[22493] res_config_ldap.c: Cannot load configuration file: res_ldap.conf
[2016-10-18 00:59:52] ERROR[22493] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[22493] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 00:59:52] ERROR[22493] cel_custom.c: Unable to load cel_custom.conf. Not logging CEL to custom

These files should (if my experience is right) get rebuilt every time you hit “Apply Config”. These files should be “right about now”, not from a week ago.

Of course, I could be completely in the dark on this - maybe @xrobau can chime in.

This is worrisome as well. I think the res_config_sqlite3.conf file should be there. This may fall back to the problem you were having with the MySQL asteriskcdrdb database no being accessible.

Right that is what I thought to. The asterisk conf files should regen every “Apply Settings”. So as it seems that is not happening there must be a disconnect between the regen of conf files and reading the settings from the DB. Is the Freepbxuser password the issue there? Again the GUI reads fine and acts normal its just the conf files that are the issue I believe.

To further that thought I figured I might try another restore of just settings. But when I tried this is what I got.

Starting restore.
Exception: SQLSTATE[28000] [1045] Access denied for user ‘freepbxuser’@‘localhost’ (using password: YES)::SQLSTATE[28000] [1045] Access denied for user ‘freepbxuser’@‘localhost’ (using password: YES) in file /var/www/html/admin/libraries/utility.functions.php on line 202

That’s your problem. It looks like you’ve tried to restore your /etc/freepbx.conf file (which has your database credentials in it).

See if you’ve got a backup of it somewhere? There’s no really easily documented way of resetting it all back to defaults. It would probably be better to get on IRC and ask someone for help there, interactively.

OK so that is what I was afraid of. Since it is easy enough to do I am just going to regen a new system from image and this time just restore PBX settings. In my experience anything else is just a cluster.

So I tried another fresh system. But this time I restored ONLY PBX settings and custom/moh audio. Now it just seems to be a different flavor of the same thing. The conf files (which I did not restore) generated but they are from the fresh system build and not anything to do with the restored settings. So of course now it acts like there are no extensions even though I see them in the GUI just fine.

I do not understand what the deal is. The restore process is just a pain to say the least. It always gives me fits.

Here is a grep from my full log. This stuff just repeats over and over.

[2016-10-18 10:18:21] ERROR[2633] res_digium_phone.c: Could not create Avahi client.
[2016-10-18 10:20:06] ERROR[2005] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 10:20:07] ERROR[2005] config_options.c: Unable to load config file ‘statsd.conf’
[2016-10-18 10:20:08] ERROR[2005] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 10:20:08] ERROR[2005] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:20:08] ERROR[2005] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:20:08] ERROR[2005] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:20:08] ERROR[2005] config_options.c: Unable to load config file ‘xmpp.conf’
[2016-10-18 10:20:08] ERROR[2005] config_options.c: Unable to load config file ‘hep.conf’
[2016-10-18 10:20:08] ERROR[2005] res_calendar.c: Unable to load config calendar.conf
[2016-10-18 10:20:08] ERROR[2005] pbx_lua.c: Error loading extensions.lua: cannot open ‘/etc/asterisk/extensions.lua’ for reading: No such file or directory
[2016-10-18 10:20:08] ERROR[2005] res_config_sqlite.c: Unable to load res_config_sqlite.conf
[2016-10-18 10:20:08] ERROR[2005] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:20:08] ERROR[2005] config_options.c: Unable to load config file ‘motif.conf’
[2016-10-18 10:20:08] ERROR[2005] chan_motif.c: Unable to read config file motif.conf. Module loaded but not running.
[2016-10-18 10:20:09] ERROR[2005] chan_mobile.c: No Bluetooth devices found. Not loading module.
[2016-10-18 10:20:09] ERROR[2005] chan_ooh323.c: Can’t load ooh323 config file, OOH323 Disabled
[2016-10-18 10:20:09] ERROR[2005] netsock2.c: getaddrinfo(“ip-10-1-”, “(null)”, …): Name or service not known
[2016-10-18 10:20:09] ERROR[2005] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:20:09] ERROR[2005] config_options.c: Unable to load config file ‘agents.conf’
[2016-10-18 10:20:09] ERROR[2005] app_agent_pool.c: Unable to load config. Not loading module.
[2016-10-18 10:20:10] ERROR[2005] cdr_syslog.c: Unable to load cdr_syslog.conf. Not logging custom CSV CDRs to syslog.
[2016-10-18 10:20:10] ERROR[2005] pbx_dundi.c: Unable to load config dundi.conf
[2016-10-18 10:20:10] ERROR[2005] chan_phone.c: Unable to load config phone.conf
[2016-10-18 10:20:10] ERROR[2005] chan_unistim.c: Unable to load config unistim.conf
[2016-10-18 10:20:10] ERROR[2005] app_amd.c: Configuration file amd.conf missing.
[2016-10-18 10:21:28] ERROR[2754] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 10:21:28] ERROR[2754] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 10:21:28] ERROR[2756] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2756] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2756] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2756] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2756] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2754] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2754] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:21:28] ERROR[2152] netsock2.c: getaddrinfo(“ip-10-1-”, “(null)”, …): Name or service not known
[2016-10-18 10:35:39] ERROR[4220] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 10:35:39] ERROR[4220] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 10:35:39] ERROR[4228] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[4228] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[4228] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[4228] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[4228] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[4220] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:35:39] ERROR[2152] netsock2.c: getaddrinfo(“ip-10-1-”, “(null)”, …): Name or service not known
[2016-10-18 10:35:39] ERROR[4220] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16283] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 10:48:08] ERROR[16283] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2016-10-18 10:48:08] ERROR[16293] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16293] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16293] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16293] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16293] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:08] ERROR[16283] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:09] ERROR[16283] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2016-10-18 10:48:09] ERROR[2152] netsock2.c: getaddrinfo(“ip-10-1-”, “(null)”, …): Name or service not known
[2016-10-18 11:22:10] ERROR[2044] config_options.c: Unable to load config file ‘acl.conf’
[2016-10-18 11:22:11] ERROR[2044] config_options.c: Unable to load config file ‘statsd.conf’
[2016-10-18 11:22:12] ERROR[2044] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’

Dave do you have any thoughts on this?

This is the only thing I see that looks suspicious. Do you have a DNS set up for you 10.x.x.x network?

Yes sir DNS is there. And it appears to be functioning.

I am just baffled by the whole restore process. It restores but in each case I have tried here there seems to be this disconnect between the config in the DB and the conf files.

\_OO_/

I just don’t know. @jfinstrom has been a big help for lots of people with backup and restore issues, but I just don’t know what to tell you.

If you have you “original” system, try doing a “Bulk Handler” Dump and Reload. Maybe that will connect you better than what you’re trying now.

Sorry, I just can’t think of anything else to help you.

Dave, I really appreciate your help.

Here is my last shot. I found more interesting things when I looked through the warnings instead of the errors.

http://pastebin.com/DBnE799n