Hi,

I have this really strange problem... I have a script, which is started
by cron every 5 minutes and which logs the data of some
temperature-sensors to a mysql-database. It does this for 5 sensors.

Now the strange thing: When I look at the tables, the data from 4 of 5
sensors isn't written to their tables, but only in the time from 9.30am
to 12.30pm. The first sensor's data is written correctly all the time.

Now the other strange thing: I look at my syslog:
Feb 9 12:05:03 helium /USR/SBIN/CRON[433]: (root) CMD
(/var/www/wetter/update.php >> /tmp/1wireerrors.log)
Feb 9 12:05:10 helium mysqld[9934]: 080209 12:05:10 [ERROR]
/usr/sbin/mysqld: Disk is full writing '/var/log/mysql/mysql-bin.000001'
(Errcode: 28). Waiting for someone to free space... Retry in 60 secs

It says disk is full, but /var/log/mysql is on the /var partition which
has 6.4GB free (according to df).


Can anyone me please? I don't see where the error is and why it's
only occurring for 3 hours in the morning. Thank you.

Christian wrote:

> Now the other strange thing: I look at my syslog:
> Feb 9 12:05:03 helium /USR/SBIN/CRON[433]: (root) CMD
> (/var/www/wetter/update.php >> /tmp/1wireerrors.log)
> Feb 9 12:05:10 helium mysqld[9934]: 080209 12:05:10 [ERROR]
> /usr/sbin/mysqld: Disk is full writing '/var/log/mysql/mysql-bin.000001'
> (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
>
> It says disk is full, but /var/log/mysql is on the /var partition which
> has 6.4GB free (according to df).

Usually the database is run as a unprivileged user, which means it won't have
full access to the disk space, as some are reserved for the root, but of
course to have 6.4GB reserved space would indicate that you have a really big
/var (10-20TB?). Another possibility is that you are running JFS, if you get a
read/write error, the slice is automatically remounted as read-only, which
prevents you from writing. Of course if doing as stupid as using vfat, then
you could have hit the max file size too.

I do suggest you check that the slice is read/write and then try to free some
space to see if change anything.


> Can anyone me please? I don't see where the error is and why it's
> only occurring for 3 hours in the morning. Thank you.

Something else is using up a lot of space around that time.


--

//Aho

On Sat, 09 Feb 2008 16:13:11 +0100, J.O. Aho wrote:
> Christian wrote:
>
>> Now the other strange thing: I look at my syslog:
>> Feb 9 12:05:03 helium /USR/SBIN/CRON[433]: (root) CMD
>> (/var/www/wetter/update.php >> /tmp/1wireerrors.log)
>> Feb 9 12:05:10 helium mysqld[9934]: 080209 12:05:10 [ERROR]
>> /usr/sbin/mysqld: Disk is full writing '/var/log/mysql/mysql-bin.000001'
>> (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
>>
>> It says disk is full, but /var/log/mysql is on the /var partition which
>> has 6.4GB free (according to df).
>
> Usually the database is run as a unprivileged user, which means it won't have
> full access to the disk space, as some are reserved for the root, but of
> course to have 6.4GB reserved space would indicate that you have a really big
> /var (10-20TB?). Another possibility is that you are running JFS, if you get a
> read/write error, the slice is automatically remounted as read-only, which
> prevents you from writing. Of course if doing as stupid as using vfat, then
> you could have hit the max file size too.
>
> I do suggest you check that the slice is read/write and then try to free some
> space to see if change anything.

The reserved space probably isn't reported on df anyway. It's just that
superusers would be able to push data onto a disk already reporting 100%
usage through df, getting it up to 105% usage or whatever. The reported
free space is what's available to mere mortals.

>> Can anyone me please? I don't see where the error is and why it's
>> only occurring for 3 hours in the morning. Thank you.
>
> Something else is using up a lot of space around that time.

Yup. Can't tell from looking now how full the disk was then, aside from
maybe seeing in some other logs as well. Maillog might be a good one to
check, as typically mail systems (even ones on database servers) use
/var/spool for things.

--
The pig is nothing but a giant dish which walks while waiting to be served.
--Grimod de La Reynière

Peter H. Coffin wrote:
>
> Yup. Can't tell from looking now how full the disk was then, aside from
> maybe seeing in some other logs as well. Maillog might be a good one to
> check, as typically mail systems (even ones on database servers) use
> /var/spool for things.
>

Thanks for this advice. I now know that this is the wrong mailinglist.
Other processes which try to write to /var have the same problem. There
are gaps in some logfiles for the time from 9.40 to 12.20 today.

And I found a nice correlation: my logs got rotated at 12.20 or
whichever time it was on the other days. There was a defunct
logrotate-process in my ps-output.
Maybe it works after I kill it?!

Well, sorry for posting to the wrong list. Btw it's an ext3-partition
with 130GB. Maybe I'm awake when it happens again and can investigate it
further.

Thank you.

>I have this really strange problem... I have a script, which is started
>by cron every 5 minutes and which logs the data of some
>temperature-sensors to a mysql-database. It does this for 5 sensors.
>
>Now the strange thing: When I look at the tables, the data from 4 of 5
>sensors isn't written to their tables, but only in the time from 9.30am
>to 12.30pm. The first sensor's data is written correctly all the time.
>
>Now the other strange thing: I look at my syslog:
>Feb 9 12:05:03 helium /USR/SBIN/CRON[433]: (root) CMD
>(/var/www/wetter/update.php >> /tmp/1wireerrors.log)
>Feb 9 12:05:10 helium mysqld[9934]: 080209 12:05:10 [ERROR]
>/usr/sbin/mysqld: Disk is full writing '/var/log/mysql/mysql-bin.000001'
>(Errcode: 28). Waiting for someone to free space... Retry in 60 secs
>
>It says disk is full, but /var/log/mysql is on the /var partition which
>has 6.4GB free (according to df).

Run df -i . Are you out of inodes?

Peter H. Coffin wrote:
> On Sat, 09 Feb 2008 16:13:11 +0100, J.O. Aho wrote:
>> Christian wrote:

>>> It says disk is full, but /var/log/mysql is on the /var partition which
>>> has 6.4GB free (according to df).
>> Usually the database is run as a unprivileged user, which means it won't have
>> full access to the disk space, as some are reserved for the root, but of
>> course to have 6.4GB reserved space would indicate that you have a really big
>> /var (10-20TB?).
> The reserved space probably isn't reported on df anyway. It's just that
> superusers would be able to push data onto a disk already reporting 100%
> usage through df, getting it up to 105% usage or whatever. The reported
> free space is what's available to mere mortals.

Yes, you are completely right there that df will report the same free for both
privileged and unprivileged users.


>>> Can anyone me please? I don't see where the error is and why it's
>>> only occurring for 3 hours in the morning. Thank you.
>> Something else is using up a lot of space around that time.
> Yup. Can't tell from looking now how full the disk was then, aside from
> maybe seeing in some other logs as well. Maillog might be a good one to
> check, as typically mail systems (even ones on database servers) use
> /var/spool for things.

A spam relay may be a cause for a such sudden extra usage of disk space.


>>> And I found a nice correlation: my logs got rotated at 12.20 or whichever
>>> time it was on the other days. There was a defunct logrotate-process in my
>>> ps-output. Maybe it works after I kill it?!

A defunct logrotate should just lead to that the rotation ain't done and the
"original" logfile keeps on growing instead of starting on a new one. But you
could try to kill it off and see what happens, it's not the whole world if a
log don't get rotated once in a while.

--

//Aho

J.O. Aho wrote:
>>>> Can anyone me please? I don't see where the error is and why it's
>>>> only occurring for 3 hours in the morning. Thank you.
>>> Something else is using up a lot of space around that time.
>> Yup. Can't tell from looking now how full the disk was then, aside from
>> maybe seeing in some other logs as well. Maillog might be a good one to
>> check, as typically mail systems (even ones on database servers) use
>> /var/spool for things.
>
> A spam relay may be a cause for a such sudden extra usage of disk space.
>
The MTA is configured to act only locally and is bound to the
loopback-interface, port 25 is firewalled.

>
>>>> And I found a nice correlation: my logs got rotated at 12.20 or whichever
>>>> time it was on the other days. There was a defunct logrotate-process in my
>>>> ps-output. Maybe it works after I kill it?!
>
> A defunct logrotate should just lead to that the rotation ain't done and the
> "original" logfile keeps on growing instead of starting on a new one. But you
> could try to kill it off and see what happens, it's not the whole world if a
> log don't get rotated once in a while.
>
If I understand logrotate correctly, it's started by cron daily, in my
config that's around 6am. It should exit when it has finished rotating
the logs. So a still-running logrotate would be quite unusual.