[Home]

Summary:ASTERISK-19266: flood of SQL warnings on 1.8 - 10.1 upgrade
Reporter:Sean Darcy (seandarcy)Labels:
Date Opened:2012-01-29 12:04:05.000-0600Date Closed:2012-02-09 14:17:04.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Core/General
Versions:10.1.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Fedora 15, x86-64Attachments:( 0) 10.1-rpm-file.list
Description:I've just upgraded from 1.8.8.0 to 10.1.0-rc2. Now I'm getting a flood of:

WARNING[5100]: db.c:295 ast_db_put: Couldn't execute statment: SQL logic error or missing database

rpm -q sqlite-devel
sqlite-devel-3.7.5-3.fc15.x86_64

whereis astdb2sqlite3
astdb2sqlite3: /usr/sbin/astdb2sqlite3

core show settings
.........
Directories
 -------------
 Configuration file:          /etc/asterisk/asterisk.conf/asterisk.conf
 Configuration directory:     /etc/asterisk
 Module directory:            /usr/lib64/asterisk/modules
 Spool directory:             /var/spool/asterisk
 Log directory:               /var/log/asterisk
 Run/Sockets directory:       /var/run/asterisk
 PID file:                    /var/run/asterisk/asterisk.pid
 VarLib directory:            /var/lib/asterisk
 Data directory:              /var/lib/asterisk
 ASTDB:                       /var/spool/asterisk/astdb

But:

ls -l /var/spool/asterisk/astdb
-rw-r--r--. 1 asterisk asterisk 8192 Jan 25 20:33 /var/spool/asterisk/astdb

locate astdb
.....
/var/lib/asterisk/astdb
/var/spool/asterisk/astdb
/var/spool/asterisk/astdb.sqlite3

ls -l /var/spool/asterisk/ast*
-rw-r--r--. 1 asterisk asterisk 8192 Jan 25 20:33 /var/spool/asterisk/astdb
-rw-r--r--. 1 root     root     6144 Jan 29 12:33 /var/spool/asterisk/astdb.sqlite3

cat /etc/asterisk/asterisk.conf
[directories](!)
astetcdir => /etc/asterisk
astmoddir => /usr/lib64/asterisk/modules
astvarlibdir => /var/lib/asterisk
astdatadir => /var/lib/asterisk
astagidir => /var/lib/asterisk/agi-bin
astspooldir => /var/spool/asterisk
astrundir => /var/run
astlogdir => /var/log/asterisk

Comments:By: Sean Darcy (seandarcy) 2012-01-29 12:05:05.231-0600

And asterisk is running as root.
By: Sean Darcy (seandarcy) 2012-01-29 13:48:47.185-0600

Ran:
/usr/sbin/astdb2sqlite3  /var/lib/asterisk/astdb

Now have :

-rw-r--r--. 1 root root 8192 May 29  2010 /var/lib/asterisk/astdb
-rw-r--r--. 1 root root 3072 Jan 29 14:43 /var/lib/asterisk/astdb.sqlite3

astdb.sqlite3 is new.

restarted. Same flood of warnings.
By: Matt Jordan (mjordan) 2012-01-30 06:54:10.180-0600

Look at the beginning of the logs when Asterisk starts. Is there an error printed about a failed DB conversion? If so, it will have instructions on how to resolve the error. Are there any other errors or warnings at the beginning of the log regarding accessing the astdb database?

What was the process you went through to do the upgrade? Is Asterisk installed in someplace non-standard?


By: Sean Darcy (seandarcy) 2012-01-30 10:25:29.570-0600

Here's the beginning for the startup:

Asterisk 10.1.0-rc2, Copyright (C) 1999 - 2011 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
 == Parsing '/etc/asterisk/asterisk.conf':   == Found
ESC[0;37mESC[1;30m  == ESC[0mParsing '/etc/asterisk/extconfig.conf': ESC[1;30m  == ESC[0mFound
ESC[1;30m  == ESC[0mParsing '/etc/asterisk/logger.conf': ESC[1;30m  == ESC[0mFound
ESC[1;30m  == ESC[0mParsing '/etc/asterisk/asterisk.conf': ESC[1;30m  == ESC[0mFound
ESC[1;30m  == ESC[0mManager registered action DBGet
ESC[1;30m  == ESC[0mManager registered action DBPut
ESC[1;30m  == ESC[0mManager registered action DBDel
ESC[1;30m  == ESC[0mManager registered action DBDelTree
ESC[1;30m  == ESC[0mRegistered custom function 'ESC[1;36mMESSAGEESC[0m'
ESC[1;30m  == ESC[0mRegistered custom function 'ESC[1;36mMESSAGE_DATAESC[0m'
ESC[1;30m  == ESC[0mRegistered application 'ESC[1;36mMessageSendESC[0m'
ESC[1;30m  == ESC[0mManager registered action DataGet
ESC[1;30m  == ESC[0mParsing '/etc/asterisk/codecs.conf': ESC[1;30m  == ESC[0mFound
ESC[1;30m ESC[0mAsterisk Dynamic Loader Starting:
ESC[1;30m  == ESC[0mParsing '/etc/asterisk/modules.conf': ESC[1;30m  == ESC[0mFound

It's installed in what I think is the standard locations:

/usr/sbin/asterisk

/etc/asterisk

I upgraded by building an rpm. Uninstalled 1.8. Installed with the new rpm. I'm attaching the file list from the rpm.
By: Sean Darcy (seandarcy) 2012-01-30 10:26:58.379-0600

results of rpm -qlp on rpm built with asterisk 10.1.0-rc2
By: Matt Jordan (mjordan) 2012-01-30 12:03:46.920-0600

Sean - can you go ahead and attach a DEBUG log from startup through "Asterisk Ready." statement?  That should contain all of the pertinent log messages.
By: Sean Darcy (seandarcy) 2012-01-30 18:30:44.652-0600

Nothing in debug:
ls -l /var/log/asterisk/debug
-rw-r--r--. 1 root root 0 Jan 30 19:18 /var/log/asterisk/debug

I think I did it correctly. Set debug => debug in logger.conf, then restarted. And got this on cli:

logger show channels
Channel                             Type     Status    Configuration
-------                             ----     ------    -------------
/var/log/asterisk/messages          File     Enabled    - NOTICE WARNING ERROR
                                   Console  Enabled    - DEBUG NOTICE WARNING ERROR
/var/log/asterisk/debug             File     Enabled    - DEBUG

By: Sean Darcy (seandarcy) 2012-01-30 19:42:25.613-0600

I think it's because asterisk init.d sets the user as "asterisk" and /var/lib/asterisk/astdb is owned by root. In other words, a permission problem. I'll investigate tomorrow. And I'm not seeing any problems/debug because I've been starting asterisk directly - no SQL warnings - and not with init.d. Though odd why this problem didn't arise with 1.8.
By: Matt Jordan (mjordan) 2012-01-31 08:23:48.907-0600

Sean:

If there's nothing in DEBUG, then Asterisk most likely doesn't have permissions to create a file in that directory.  So yes, it sounds like you have permission problems - in places other then /var/lib/asterisk/ as well.

The reason why you would run into this when upgrading from 1.8 => 10 is due to the database upgrade that is necessary between the two versions.  Asterisk 10 uses sqlite3 for its internal database; previous versions used a Berkeley DB.  There is some information about the upgrade in Asterisk 10 here:

https://wiki.asterisk.org/wiki/display/AST/SQLite3+astdb+back-end
By: Sean Darcy (seandarcy) 2012-01-31 12:29:22.863-0600

I think there's still another issue.

core show settings
............
ASTDB:                       /var/spool/asterisk/astdb

-rw-r--r--. 1 asterisk asterisk 8192 Jan 25 20:33 /var/spool/asterisk/astdb
-rw-r--r--. 1 asterisk root     6144 Jan 31 09:44 /var/spool/asterisk/astdb.sqlite3

so even though all the permissions are correct - it's not checking the sqlite db, but the old berkeley db.

I copied /var/spool/asterisk/astdb.sqlite3 to astdb. That seemed to fix it.
By: Terry Wilson (twilson) 2012-01-31 12:58:31.946-0600

Yes, if you are running asterisk non-root, astdb.sqlite3 (and the spool directory) need to be writable by the user that is running Asterisk. ASTDB will still say /var/spool/asterisk/astdb, but that is to be expected. It should be absolutely impossible for Asterisk to *actually* use the old db because the code (except for the conversion) has absolutely no ability to deal with it anymore.

The upgrade process was broken in some way. It looks as if 1.8 was run non-root (/var/spool/asterisk/astdb owned by asterisk:asterisk), then 10 was upgraded and run as root the first time which did the conversion as root (/var/spool/asterisk/astdb.sqlite3 owned by root:root), then later run non-root, and thus lots of errors due to lack of proper permissions.