Problem with Apache2: Logging To A MySQL Database With mod_log_sql (Debian Etch)

Thank you Falko for the excellent tutorial on logging to MySQL. I refer
to it frequently when doing an install.

Now I'm up against a problem I cannot solve.

I am using:

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=8.04
DISTRIB_CODENAME=hardy
DISTRIB_DESCRIPTION="Ubuntu 8.04.2"

However, now my error.log always show an error as follows and I am
having a heck of a time solving it. It is filling up my logs. I
thought you might have a clue you could pass to me.

Thanks.

Jeffrey



[Sun Apr 26 18:10:01 2009] [error] [client 193.200.150.125] File does
not exist: /var/www/web1/web/keys.ccm
[Sun Apr 26 18:10:01 2009] [error] mysql_query returned (1)
[Sun Apr 26 18:10:01 2009] [error] table does not exist, preserving query
[Sun Apr 26 18:10:01 2009] [error] table doesn't exist...creating now
[Sun Apr 26 18:10:01 2009] [error] failed to create table: score_board
[Sun Apr 26 18:10:01 2009] [error] (1)Operation not permitted: child
attempted but failed to create one or more tables for 142.23.62.121,
preserving query
[Sun Apr 26 18:10:01 2009] [error] (13)Permission denied: attempted
append of local preserve file '/etc/apache2/logs/mod_log_sql-preserve'
but failed.
[Sun Apr 26 18:10:01 2009] [error] mysql_query returned (1)
[Sun Apr 26 18:10:01 2009] [notice] db reconnect successful
[Sun Apr 26 18:10:01 2009] [error] mysql_query returned (1)
[Sun Apr 26 18:10:01 2009] [error] second attempt failed
[Sun Apr 26 18:10:01 2009] [error] (13)Permission denied: attempted
append of local preserve file '/etc/apache2/logs/mod_log_sql-preserve'
but failed.

 

Are the MySQL login details in your Apache configuration correct?

Have you tried to turn on MySQL query logging to see what is going on?

 

Hi Falko. I am getting logging to my database, it's just that I am also getting the regular apache error logs filled up with those error messages. So the login credentials must be good. Here are the details of my configuration, followed by output of apache logs and mysql.log:


LogSQLLoginInfo mysql://loguser_login_name:loguser_login_password@localhost/apachelogs
LogSQLCreateTables on
LogSQLDBParam socketfile /var/run/mysqld/mysqld.sock
LogSQLTransferLogFormat AbHhmRSsTUuvI
LogSQLTransferLogTable web_log

<VirtualHost *:80>
ServerAdmin webmaster@localhost
ServerName mysite.com
ServerAlias www.msyite.com
DocumentRoot /home/path/public_html/directory
<Directory />
Options FollowSymLinks
AllowOverride None
</Directory>
<Directory /home/path/public_html/directory>
Options Indexes FollowSymLinks MultiViews
AllowOverride None
Order allow,deny
allow from all
</Directory>

ScriptAlias /cgi-bin/ /usr/lib/cgi-bin/
<Directory "/usr/lib/cgi-bin">
AllowOverride None
Options +ExecCGI -MultiViews +SymLinksIfOwnerMatch
Order allow,deny
Allow from all
</Directory>

ErrorLog /var/log/apache2/error.log

# Possible values include: debug, info, notice, warn, error, crit,
# alert, emerg.
LogLevel notice

CustomLog /var/log/apache2/access.log combined

Alias /doc/ "/usr/share/doc/"
<Directory "/usr/share/doc/">
Options Indexes MultiViews FollowSymLinks
AllowOverride None
Order deny,allow
Deny from all
Allow from 127.0.0.0/255.0.0.0 ::1/128
</Directory>

</VirtualHost>
=========================================================
output of mysql.log (I cannot see any errors here writing to the score_board table):

090429 15:13:40 115 Connect loguser@localhost on apachelogs
090429 15:13:47 114 Query insert into web1_access_log (agent,bytes_sent,request_protocol,remote_host,request_method,referer,time_stamp,st
atus,request_duration,request_uri,remote_user,virtual_host,id) values ('Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.10) Gecko/200904231
6 Firefox/3.0.10','181','HTTP/1.1','mail.domainname.com','GET','-','1241018027','404','0','/ship.ccm','-','domainname.com','Sfh8AAAEAAEW1BG8AAAA
A')
114 Query insert ignore into scoreboard (domain,vhost,month,year,count_impressions) values ('www','default-domain.tld','0
4','2009','0')
114 Query create table if not exists `score_board
114 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AN
D vhost='default-domain.tld' AND month='04' AND year='2009'
114 Quit
116 Connect loguser@localhost on apachelogs
116 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AN
D vhost='default-domain.tld' AND month='04' AND year='2009'
090429 15:13:59 117 Connect debian-sys-maint@localhost on
117 Quit

=========================================================
Yet the output of the apache error logs show this:

[Wed Apr 29 15:13:47 2009] [error] mysql_query returned (1)
[Wed Apr 29 15:13:47 2009] [error] table does not exist, preserving query
[Wed Apr 29 15:13:47 2009] [error] table doesn't exist...creating now
[Wed Apr 29 15:13:47 2009] [error] failed to create table: score_board
[Wed Apr 29 15:13:47 2009] [error] (1)Operation not permitted: child attempted but failed to create one or more tables for www.domainname.com, preserving query
[Wed Apr 29 15:13:47 2009] [error] mysql_query returned (1)
[Wed Apr 29 15:13:47 2009] [notice] db reconnect successful
[Wed Apr 29 15:13:47 2009] [error] mysql_query returned (1)
[Wed Apr 29 15:13:47 2009] [error] second attempt failed
[Wed Apr 29 15:14:07 2009] [notice] caught SIGTERM, shutting down

 

In the MySQL log, there are references to the tables score_board and scoreboard. Do both tables exist, just one (which one), or none of them?

 

Thank you for your help and patience, Falko.

I found this link

http://article.gmane.org/gmane.comp.apache.mod-log-sql/330


which gives me the sql code necessary to construct the scoreboard table in the log file (no code for score_board, though, that I could find). I'm curious why the code to create this table is not included anywhere else in your instructions ? I had to search all over the internet to find this small snippet of code. Is it included in your instructions somewhere where I couldn't see it? In any event, now with the scoreboard table included some of the the errors are gone but I'm still getting these filling up my log with every request:

[Fri May 01 16:07:25 2009] [error] [client 255.254.132.134] File does not exist: /home/path/to/my/public_folder/d.ccm
[Fri May 01 16:07:25 2009] [error] mysql_query returned (1)
[Fri May 01 16:07:25 2009] [notice] db reconnect successful
[Fri May 01 16:07:25 2009] [error] mysql_query returned (1)
[Fri May 01 16:07:25 2009] [error] second attempt failed

and in the mysql logs:

090501 16:15:16 110 Query insert into web1_access_log (agent,bytes_sent,request_protocol,remote_host,request_method,referer$
110 Query insert ignore into scoreboard (domain,vhost,month,year,count_impressions) values ('www','default-$
110 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE d$
110 Quit
115 Connect loguser@localhost on apachelogs
115 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE d$
090501 16:15:17 116 Connect loguser@localhost on apachelogs
090501 16:15:31 117 Connect debian-sys-maint@localhost on
117 Quit

 

My tutorial was for Debian Etch, and you're using Ubuntu 8.04, so you cannot expect that the instructions work 100% on your system. They did for me on Debian Etch.

Can you post an excerpt from the MySQL log from the same time (around Fri May 01 16:07:25 2009)?

 

This should help. both the mysql and apache error.log output is of the same time. scoreboard table exists and always contains only 1 record no matter how many times queried.

=============================================

[Mon May 04 02:19:05 2009] [notice] Apache/2.2.11 (Ubuntu) PHP/5.2.6-3ubuntu4.1 with Suhosin-Patch configured -- resuming normal operations
[Mon May 04 02:19:18 2009] [error] [client my-ip-address] File does not exist: /path/to/page/ukey.ccm
[Mon May 04 02:19:18 2009] [notice] mod_log_sql: child established database connection
[Mon May 04 02:19:18 2009] [error] mysql_query returned (1)
[Mon May 04 02:19:18 2009] [notice] db reconnect successful
[Mon May 04 02:19:18 2009] [error] mysql_query returned (1)
[Mon May 04 02:19:18 2009] [error] second attempt failed
[Mon May 04 02:19:18 2009] [error] [client my-ip-address] File does not exist: /path/to/page/favicon.ico
[Mon May 04 02:19:21 2009] [error] [client my-ip-address] File does not exist: /path/to/page/favicon.ico
[Mon May 04 02:19:34 2009] [notice] caught SIGTERM, shutting down









090504 2:19:13 109 Connect debian-sys-maint@localhost on
109 Query select @@version_comment limit 1
109 Query select count(*) into @discard from `phpmyadmin`.`pma_table_info`
109 Quit
090504 2:19:18 110 Connect loguser@localhost on apachelogs
110 Query insert into web1_access_log (agent,bytes_sent,request_protocol,remote_host,request_method,referer,time_stamp,status
,request_duration,request_uri,remote_user,virtual_host,id) values ('Mozilla/5.0 (Windows; U; Windows NT 6; en-US; rv:1.9.0.10) Gecko/2009042316 Firefo
x/3.0.10','181','HTTP/1.1','requesting.com','GET','-','1241403558','404','0','/ukey.ccm','-','server.com','Sf5Qpn8AAAECCDtWAkcAADAA')
110 Query insert ignore into scoreboard (domain,vhost,month,year,count_impressions) values ('www','default-domain.tld','05','
2009','0')
110 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AND vh
ost='default-domain.tld' AND month='05' AND year='2009'
110 Quit
111 Connect loguser@localhost on apachelogs
111 Query update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AND vh
ost='default-domain.tld' AND month='05' AND year='2009'
090504 2:19:19 112 Connect loguser@localhost on apachelogs
090504 2:19:33 111 Quit

 

Can you run the following queries manually (e.g. with phpMyAdmin) and see if you get an error message?

Code:

insert into web1_access_log (agent,bytes_sent,request_protocol,remote_host,req uest_method,referer,time_stamp,status
,request_duration,request_uri,remote_user,virtual_ host,id) values ('Mozilla/5.0 (Windows; U; Windows NT 6; en-US; rv:1.9.0.10) Gecko/2009042316 Firefo
x/3.0.10','181','HTTP/1.1','requesting.com','GET','-','1241403558','404','0','/ukey.ccm','-','server.com','Sf5Qpn8AAAECCDtWAkcAADAA')

Code:

insert ignore into scoreboard (domain,vhost,month,year,count_impressions) values ('www','default-domain.tld','05','
2009','0')

Code:

update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AND vh
ost='default-domain.tld' AND month='05' AND year='2009'

 

thank you Falko for taking the time to help me troubleshoot this. I do appreciate your efforts.

The first query produced a mysql error. The query is first, then followed by the error:

query:

Code:

insert into web1_access_log (agent,bytes_sent,request_protocol,remote_host,request_method,referer,time_stamp,status
,request_duration,request_uri,remote_user,virtual_ host,id) values ('Mozilla/5.0 (Windows; U; Windows NT 6; en-US; rv:1.9.0.10) Gecko/2009042316 Firefo
x/3.0.10','181','HTTP/1.1','requesting.com','GET','-','1241403558','404','0','/ukey.ccm','-','server.com','Sf5Qpn8AAAECCDtWAkcAADAA')

error:

#1064 - You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'host,id) values ('Mozilla/5.0 (Windows; U; Windows NT 6; en-US; rv:1.9.0.10) Gec' at line 2

The second query finally inserted a new record into the database without error. Here was that query:

Code:

insert ignore into scoreboard (domain,vhost,month,year,count_impressions) values ('www','default-domain.tld','05','
2009','0')

And the last query, code below, produced no error and updated the record successfully. Here is that query:

Code:

update scoreboard SET count_impressions = count_impressions+1, bytes_sent = bytes_sent+181 WHERE domain='www' AND vh
ost='default-domain.tld' AND month='05' AND year='2009'

 

There is aspace between virtual_ and host that shouldn't be there...

 

Okay, everything was inserted. Now what does that mean?

Thanks.

 

It seems as if there's a faulty SQL query in mod_log_sql - might be a bug in the Ubuntu package.