On Mon, Apr 27, 2015, at 10:52 PM, Adam Wolk wrote:
> On Mon, Apr 27, 2015, at 10:43 PM, Adam Wolk wrote:
> > On Mon, Apr 27, 2015, at 10:22 PM, Todd C. Miller wrote:
> > > On Mon, 27 Apr 2015 20:06:59 +0200, Adam Wolk wrote:
> > >
> > > > Apr 27 19:54:55 tintagel spamd[27724]: can't delete 66.111.4.25
> > > > out1-smtp.messagingengine.com <adam.w...@koparo.com>
> > > > <adam.w...@tintagel.pl> from spamd db (Error 22)
> > > >
> > > > Does anyone know how serious that error is (should I be worried) and
> > > > what might have caused it?
> > >
> > > Error 22 is EINVAL. I'm not sure how that can happen in this case
> > > though. Have you tried restating spamd?
> > >
> >
> > Hi Todd,
> >
> > Indeed I tried restarting spamd and the issue is the same each time.
> > With a spamd restart the error happens immediately startup:
> >
> > Apr 27 22:27:52 tintagel spamd[3732]: can't delete 66.111.4.25
> > out1-smtp.messagingengine.com <adam.w...@koparo.com>
> > <adam.w...@tintagel.pl> from spamd db (Error 0)
> > Apr 27 22:28:51 tintagel spamd[25915]: listening for incoming
> > connections.
> > Apr 27 22:28:51 tintagel spamd[7233]: can't delete 66.111.4.25
> > out1-smtp.messagingengine.com <adam.w...@koparo.com>
> > <adam.w...@tintagel.pl> from spamd db (Error 0)
> >
>
> Just noticed, that right after a previous restart it's no longer Error
> 22 but Error 0
> Apr 27 21:50:27 tintagel spamd[27724]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 22)
> Apr 27 21:51:27 tintagel spamd[27724]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 22)
> Apr 27 21:52:18 tintagel spamd[8450]: listening for incoming
> connections.
> Apr 27 21:52:18 tintagel spamd[20180]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 0)
> Apr 27 21:52:25 tintagel spamd[6924]: listening for incoming
> connections.
> Apr 27 21:52:25 tintagel spamd[3732]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 0)
> Apr 27 21:53:26 tintagel spamd[3732]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 0)
> Apr 27 21:54:26 tintagel spamd[3732]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 0)
> Apr 27 21:55:27 tintagel spamd[3732]: can't delete 66.111.4.25
> out1-smtp.messagingengine.com <adam.w...@koparo.com>
> <adam.w...@tintagel.pl> from spamd db (Error 0)
>
> # ls -l /var/db/spamd
> -rw-r--r-- 1 _spamd _spamd 6881280 Apr 27 22:51 /var/db/spamd
>
> here's my process output limited to spamd
> # ps aux | grep -i spamd
> root 30279 0.0 3.3 68000 67956 ?? Ss Sun11PM 1:22.68 perl:
> /usr/local/bin/spamd -d -u _spamdaemon -P (perl)
> _spamdaemon 10621 0.0 0.4 68016 8872 ?? S Sun11PM 0:00.59
> perl: spamd child (perl)
> _spamdaemon 29838 0.0 0.4 68016 8936 ?? S Sun11PM 0:00.83
> perl: spamd child (perl)
> _spamd 7233 0.0 0.1 9860 1704 ?? Is 10:28PM 0:00.73 spamd:
> (pf <spamd-white> update) (spamd)
> _spamd 25915 0.0 0.3 10308 5220 ?? I 10:28PM 0:00.12 spamd:
> [priv] (greylist) (spamd)
> _spamd 14894 0.0 0.0 9656 1020 ?? I 10:28PM 0:00.00 spamd:
> (/var/db/spamd update) (spamd)
> root 30162 0.0 0.0 636 4 p7 R+ 10:52PM 0:00.00 grep
> -i spamd (ksh)
> #
>
>
> > > You might also try running:
> > >
> > > $ spamdb | fgrep 66.111.4.25
> >
> > Here is the output:
> > $ spamdb | fgrep 66.111.4.25
> > WHITE|66.111.4.25|||1430096342|1430098533|1433208963|4|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<mulan...@tintagel.pl>|1430146234|1430148635|1430160634|3|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<mulan...@tintagel.pl>|1430146234|1430148635|1430160634|3|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<adam.w...@tintagel.pl>|1430142855|1430145035|1430157255|4|0
> >
> >
> > >
> > > to see if that entry is really in the database and if so see if
> > > "spamdb -d" can remove it.
> > >
> >
> > # spamdb -d 66.111.4.25
> > # echo $?
> > 0
> > # spamdb | fgrep 66.111.4.25
> > WHITE|66.111.4.25|||1430096342|1430098533|1433208963|4|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<mulan...@tintagel.pl>|1430146234|1430148635|1430160634|3|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<mulan...@tintagel.pl>|1430146234|1430148635|1430160634|3|0
> > GREY|66.111.4.25|out1-smtp.messagingengine.com|<adam.w...@koparo.com>|<adam.w...@tintagel.pl>|1430142855|1430145035|1430157255|4|0
> >
> >
> > > - todd
> > >
> >
> > The weird thing is - it just started happening. I did see other weird
> > issues
> > like spamdb not showing any entries in short periods of time but I
> > assumed
> > that it was expired hosts and they always came back after a while.
> >
> > I did make a copy of my /var/db/spamd in case it's a corrupt db. Though
> > nothing
> > specific was happening with the host when the errors started.
> >
> > I started looking at /usr/src which makes me think the issue comes from:
> >
> > /usr/src/libexec/spamd/grey.c
> > case DBC_DEL:
> > memset(&dbk, 0, sizeof(dbk));
> > dbk.size = strlen(dbc->key);
> > dbk.data = dbc->key;
> > if (db->del(db, &dbk, 0)) {
> > syslog_r(LOG_ERR, &sdata,
> > "can't delete %s from spamd db
> > (%m)",
> > dbc->key);
> > ret = -1;
> > }
> > break;
> >
> > which uses the hash version of db.h
> > /usr/src/lib/libc/db/hash/hash.c
> >
> > hash_delete(const DB *dbp, const DBT *key,
> > u_int32_t flag) /* Ignored */
> > {
> > HTAB *hashp;
> >
> > hashp = (HTAB *)dbp->internal;
> > if (flag && flag != R_CURSOR) {
> > hashp->err = errno = EINVAL;
> > return (ERROR);
> > }
> > if ((hashp->flags & O_ACCMODE) == O_RDONLY) {
> > hashp->err = errno = EPERM;
> > return (ERROR);
> > }
> > return (hash_access(hashp, HASH_DELETE, (DBT *)key, NULL));
> > }
> >
> > The line with EINVAL like you correctly pointed out.
> > While here, why is flag marked as /* ignored */ and the error I'm
> > hitting looks like code which verifies if that parameter was properly
> > set?
> >
> > The if shouldn't have a way to trigger since del is passed 0 as the flag
> > parameter so I'm a bit dumbfounded here. I couldn't find any other
> > part of the code that could result in the exact same error message.
> >
> > I am trying to write a small C program to open the db file to try and
> > delete
> > the entry from a reduced use case - so far it's being going really slow
> > to get
> > a useful test case. Not sure if I will be able to whip it up in a
> > reasonable time frame.
> >
> > Regards,
> > Adam
>
Here is the sample program:
- https://gist.github.com/mulander/6c09065f550de4ef63c0
I'm checking if the key exists, trying to delete it and checking again.
Tested on the amd64 snapshot from April 25 (the server) and my local
amd64 snapshot
from Apr 19.
In both boxes when:
char *key = "66.111.4.25";
$ ./dbtest
malloc dbc
malloc key
dbopen
before null check
after dbopen
Checking if the key exists
key found
Key deleted
key found
when key does't exist:
char *key = "66.111.4.252";
$ ./dbtest
malloc dbc
malloc key
dbopen
before null check
after dbopen
Checking if the key exists
key not in db
can't delete from spamd db: Undefined error: 0
key not in db
That's as much as I managed to whip up. You can download a copy
of the spamd database I copied from my server here:
- http://mulander.kewlnet.tk/spamd-test-db
md5 - 4239040d57007ab243534cdad2da5268 spamd-test-db
size -rw------- 1 mulander users 6.6M Apr 27 23:42 spamd-test-db
I'm now stopping spamd, removing /var/db/spamd and restarting the
process
to see if that helps.
So far after a restart there's no message but now there is of course no
thing to
delete from it.
Regards,
Adam
