On Mon, Apr 27, 2015, at 11:45 PM, Adam Wolk wrote:
> 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
>
Does anyone have ideas on what might be causing this issue?
I'm seeing this frequently even after upgrading to a newer snapshot (May
2nd amd64)
# tail -f /var/log/daemon
May 9 15:35:04 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:36:05 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:37:06 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:38:07 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:39:07 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:40:08 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:41:09 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:42:10 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:43:10 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
May 9 15:44:11 tintagel spamd[30026]: can't delete 37.187.161.149
tau20.catalist.pl <subskrypcja-80119857-321649...@sub.4free.pl>
<kinga.w...@tintagel.pl> from spamd db (Error 22)
