Milter-greylist

Greetings,

Of late I have been attempting to use the DKIM support in 
milter-greylist. Where at first I thought it was working, I am now 
convinced that I have either unintentionally broken it through my ACL 
syntax or through some compilation mistake.

After reading the fine documentation and sifting though the mailing 
lists archives, I've attempted to do something close to this:

racl whitelist list "my network"
racl whitelist auth /.*/
racl greylist spf softfail delay 5m
racl blacklist spf fail
racl whitelist default
dacl whitelist auth /.*/
dacl blacklist dkim fail
dacl whitelist dkim pass spf pass
dacl whitelist default

The idea was to be slightly more friendly to those who pass both SPF and 
DKIM. However, simple testing with the following combinations:

SPF + DKIM both pass (verified by other milters and methods)
SPF pass, no DKIM signature 

both result in:

Mail from=<xxxx@domain>, rcpt=(nil), 
addr=host.name.net[IP.AD.DR.ESS] is matched by entry dacl 38 whitelist 
dkim pass spf pass

I thought this strange and returned to update the dACLs to have

dacl whitelist auth /.*/
dacl blacklist dkim fail
* dacl greylist dkim none delay 1m
dacl whitelist dkim pass spf pass
dacl whitelist default

only to see the same results. It appears to me that no matter what ACL 
is set, the DKIM result is always PASS. Since dkimcheck.c lacks the 
debug logging that the spf code has, I was unable to verify what exactly 
milter-greylist thinks it is seeing. I ktraced it and can see 
milter-greylist calling the SPF library, but there does not ever seem to 
be a DKIM call made (DKIM signature header there or not).

I have tried linking milter-greylist against multiple versions of 
libDKIM and libOpenDKIM with the same results. I have also tried using 
both $current and $development versions to the same results.

On a side note, SPF is working just fine. So the ACL above: dacl 
whitelist dkim pass spf pass is not being misleading about the SPF 
status; racl entries also verify this.

Any insight would be helpful,

John

John Wood <john-misc@...> wrote:

> only to see the same results. It appears to me that no matter what ACL
> is set, the DKIM result is always PASS. Since dkimcheck.c lacks the 
> debug logging that the spf code has, I was unable to verify what exactly
> milter-greylist thinks it is seeing. I ktraced it and can see 
> milter-greylist calling the SPF library, but there does not ever seem to
> be a DKIM call made (DKIM signature header there or not).

What do you get by running nm milter-greylist ? 
Any reference to dkim stuff?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> What do you get by running nm milter-greylist ? 
> Any reference to dkim stuff?

Sure, both ldd and nm show it (not stripped):

nyima:~$ ldd /usr/local/bin/milter-greylist 
/usr/local/bin/milter-greylist:        
        libGeoIP.so.5 => /usr/local/lib/libGeoIP.so.5 (0x280b6000)
        libcurl.so.6 => /usr/local/lib/libcurl.so.6 (0x280e7000)        
        libspf2.so.3 => /usr/local/lib/libspf2.so.3 (0x2812f000)
        libdkim.so.0 => /usr/local/lib/libdkim.so.0 (0x28146000)
        libcrypto.so.7 => /usr/local/lib/libcrypto.so.7 (0x2815e000)
        libmilter.so.4 => /usr/local/lib/libmilter.so.4 (0x282c2000)
        libthr.so.3 => /lib/libthr.so.3 (0x282d0000)
        libc.so.7 => /lib/libc.so.7 (0x282e5000)
        libcares.so.2 => /usr/local/lib/libcares.so.2 (0x283ff000)
        libssl.so.7 => /usr/local/lib/libssl.so.7 (0x2840c000)
        libz.so.5 => /lib/libz.so.5 (0x2845a000)

nyima:~$ nm /usr/local/bin/milter-greylist | grep -i dkim
08065b70 T acl_add_dkim
08065ae0 T acl_print_dkim
         U dkim_body         
         U dkim_close
         U dkim_eoh
         U dkim_eom
         U dkim_free         
         U dkim_getresultstr
         U dkim_header         
         U dkim_init
08094368 b dkim_ptr         
         U dkim_verify
08065d20 T dkimcheck_body
08065f70 T dkimcheck_clear
08065d70 T dkimcheck_eoh
08065ce0 T dkimcheck_eom
08065bf0 t dkimcheck_error
080659b0 T dkimcheck_free
08065db0 T dkimcheck_header
08065f20 T dkimcheck_init
080659e0 T dkimcheck_validate

John Wood <john-misc@...> wrote:

> Sure, both ldd and nm show it (not stripped):

I amaffraid you will have to add a few printf in the code to debug this.

In dkim.c, you will want to watch what happens to priv->priv_dkimstat

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> I amaffraid you will have to add a few printf in the code to debug 
> this.
> 
> In dkim.c, you will want to watch what happens to priv->priv_dkimstat

Alright, I've done this by using gdb on a live session. The results are 
somewhat interesting:

(gdb) break dkimcheck_validate
Breakpoint 1 at 0x806b2d6: file dkimcheck.c, line 235.
(gdb) cont
Continuing.
[Switching to Thread 285b9b00 (LWP 100095)]

Breakpoint 1, dkimcheck_validate (ad=0x28512318, stage=AS_DATA, 
ap=0xbf5f98e8, priv=0x286aed00) at dkimcheck.c:235
235             if (stage != AS_DATA) {
(gdb) bt
#0  dkimcheck_validate (ad=0x28512318, stage=AS_DATA, ap=0xbf5f98e8, 
priv=0x286aed00) at dkimcheck.c:235
#1  0x0806551a in acl_filter (stage=AS_DATA, ctx=0x28640180, 
priv=0x286aed00) at acl.c:1902
#2  0x0804cb50 in real_eom (ctx=0x28640180) at milter-greylist.c:938
#3  0x0804b3b6 in mlfi_eom (ctx=0x28640180) at milter-greylist.c:265
#4  0x282ccc54 in st_bodyend () from /usr/local/lib/libmilter.so.4
#5  0x282ccfd2 in mi_engine () from /usr/local/lib/libmilter.so.4
#6  0x282ceb75 in mi_worker () from /usr/local/lib/libmilter.so.4
#7  0x282dc75f in pthread_getprio () from /lib/libthr.so.3
#8  0x00000000 in ?? ()
(gdb) n
240             stat = ad ? *(enum spf_status *)ad : MGSPF_PASS;
(gdb) n
242             switch (stat) {
(gdb) n
275                     result = (priv->priv_dkimstat == 
DKIM_STAT_NOSIG);
(gdb) n
276                     break;
(gdb) p stat
$1 = MGSPF_NONE
(gdb) p result
$2 = 0
(gdb) p priv->priv_dkimstat
$3 = 0
(gdb) p ad
$4 = (acl_data_t *) 0x28512318
(gdb) p *ad
$5 = {netblock = {addr = 0x6, mask = 0x30000000, salen = 1342177282, 
cidr = 1610612740},
  string = 0x6 <Error reading address 0x6: Bad address>, regex = {re = 
0x6,
    re_copy = 0x30000000 <Error reading address 0x30000000: Bad 
address>, nmatch = 1342177282}, list = 0x6,
  macro = 0x6, dnsrbl = 0x6, urlcheck = 0x6, prop = 0x6, opnum = {op = 
6, num = 805306368}, clockspec = 0x6,
  spf_status = MGSPF_NONE, dkim_status = MGSPF_NONE, ratelimit_conf = 
0x6}
(gdb) p *(enum spf_status *)ad
$6 = MGSPF_NONE
(gdb) up
#1  0x0806551a in acl_filter (stage=AS_DATA, ctx=0x28640180, 
priv=0x286aed00) at acl.c:1902
1902                            if ((found = (*ac->ac_acr->acr_filter)

It looks like result = (priv->priv_dkimstat == DKIM_STAT_NOSIG); is the 
reason. This is strange because milter-greylist is linked against the 
same library as the DKIM milter running, which validates the signature 
just fine. While I don't understand all of the code, it is also 
interesting to point out that while it seems to get NOSIG, the ACL for 
"pass" is matching; which also seems incorrect? as it should be NONE and 
not match: spf pass dkim pass.

John

John Wood <john-misc@...> wrote:

> It looks like result = (priv->priv_dkimstat == DKIM_STAT_NOSIG); is the
> reason. This is strange because milter-greylist is linked against the
> same library as the DKIM milter running, which validates the signature
> just fine. While I don't understand all of the code, it is also 
> interesting to point out that while it seems to get NOSIG, the ACL for
> "pass" is matching; which also seems incorrect? as it should be NONE and
> not match: spf pass dkim pass.

Indeed, but perhaps we should focus on the first bug, that is:
DKIM_STAT_NOSIG.

In dkimcheck_error(), there is a log call. Do you get it in the logs?
And when do you reach it? A breakpoint and backtrace might be
insightful.

        case DKIM_STAT_NOSIG:
                mg_log(LOG_DEBUG, "DKIM failed: %s",
                       dkim_getresultstr(priv->priv_dkimstat));

                retval = SMFIS_CONTINUE;

Note the retval, which perhaps explains the match.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> Indeed, but perhaps we should focus on the first bug, that is: 
> DKIM_STAT_NOSIG.
> 
> In dkimcheck_error(), there is a log call. Do you get it in the logs? 
> And when do you reach it? A breakpoint and backtrace might be 
> insightful.
> 
>         case DKIM_STAT_NOSIG:
>                 mg_log(LOG_DEBUG, "DKIM failed: %s",
>                        dkim_getresultstr(priv->priv_dkimstat));
> 
>                 retval = SMFIS_CONTINUE;
> 
> Note the retval, which perhaps explains the match.

Strange, it never gets there. Rather, setting a break point for 
dkimcheck_error never results in a break (and no, there is nothing 
logged). This makes me think that NOSIG is never arriving...

John

John Wood <john-misc@...> wrote:

> Strange, it never gets there. Rather, setting a break point for 
> dkimcheck_error never results in a break (and no, there is nothing 
> logged). This makes me think that NOSIG is never arriving...

Now you can stuff breakpoints in each dkim related function and see how
it fills priv->priv_dkimstat

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> Now you can stuff breakpoints in each dkim related function and see 
> how it fills priv->priv_dkimstat

OK, dkimcheck_header was the first breakpoint to trip:

Breakpoint 7, dkimcheck_header (name=0x28865c80 "DKIM-Signature",
    value=0x28865c8f "v=1; a=rsa-sha256; c=relaxed/simple; 
d=domain.com;\n\ts=selector; 
t=1283742375;\n\tbh=+Pby8GPvv2IKr1c2RXTBWpjtkx1p0IqCseWIVKxoTt8=;\n\th=
Date:From:To:Subject:Message-ID:MIME-Version:Content-Type;\n\tb=DghH"...,
    priv=0x286ad400) at dkimcheck.c:151
151             if (priv->priv_dkim == NULL) {
(gdb) p priv->priv_dkimstat
$2 = 0

Despite looking at what clearly is a DKIM signature, $2 is 0. Stepping 
back a bit, the end of dkimcheck_error has:

      if (priv->priv_dkim != DKIM_STAT_OK) {
                (void)dkim_free(priv->priv_dkim);
                priv->priv_dkim = NULL;
        }

It looks like the pointer priv->priv_dkim is being compared to a 
constant (DKIM_STAT_OK). DKIM_STAT_OK is defined as zero, so I think we 
end up with a null pointer in this situation. Hence every time we get to 
line 151 priv_dkim is already NULL.

John

John Wood <john-misc@...> wrote:

>       if (priv->priv_dkim != DKIM_STAT_OK) {

This should probably be changed as:
         if (priv->priv_dkimstat != DKIM_STAT_OK) {

Can you give it a try?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> John Wood <john-misc@...> wrote:
> 
> >       if (priv->priv_dkim != DKIM_STAT_OK) {
> 
> This should probably be changed as:
>          if (priv->priv_dkimstat != DKIM_STAT_OK) {
> 
> Can you give it a try?

Aye, I'd actually tried that but it results in a crash/core.

Sep  5 21:26:40 nyima milter-greylist: DKIM failed: Bad signature
Sep  5 21:26:41 nyima sm-mta[24579]: o864QYGu024579: 
milter_sys_read(milter-greylist): cmd read returned 0, expecting 5
Sep  5 21:26:41 nyima sm-mta[24579]: o864QYGu024579: Milter 
(milter-greylist): to error state

and the core:

#0  0x0804ca90 in real_eom (ctx=Cannot access memory at address 
0xbf000008
) at milter-greylist.c:918
918             if ((stat = dkimcheck_eom(priv)) != SMFIS_CONTINUE)

Hrm, possibly an over-aggressive free in there...

John

John Wood <john-misc@...> wrote:

> #0  0x0804ca90 in real_eom (ctx=Cannot access memory at address 
> 0xbf000008
> ) at milter-greylist.c:918
> 918             if ((stat = dkimcheck_eom(priv)) != SMFIS_CONTINUE)
> 
> Hrm, possibly an over-aggressive free in there...

ctx is at unreachable address, this seems quite rotten. The interesing
question is when did it happen: before kimcheck_eom or inside it?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> ctx is at unreachable address, this seems quite rotten. The interesing 
> question is when did it happen: before kimcheck_eom or inside it?

Hrmph, it is not cooperating today. The gdb output is mostly useless:

[ after bt ] 

(gdb) up
Cannot access memory at address 0xbf000004
(gdb) info threads
  7 Thread 28501140 (LWP 100101)  warning: Couldn't find general-purpose 
registers in core file.

0x0804ca90 in real_eom (ctx=Cannot access memory at address 0xbf000008
) at milter-greylist.c:918
  6 Thread 285ba140 (LWP 100084)  0x28401227 in __error () from 
/lib/libthr.so.3
  5 Thread 285b9ec0 (LWP 100089)  0x28401227 in __error () from 
/lib/libthr.so.3
  4 Thread 285b9d80 (LWP 100090)  0x2831e6e9 in sigwait () from 
/lib/libc.so.7
  3 Thread 285b9c40 (LWP 100094)  0x2836bb1f in poll () from 
/lib/libc.so.7
  2 Thread 285b9b00 (LWP 100095)  0x28401227 in __error () from 
/lib/libthr.so.3
* 1 Thread 285b99c0 (LWP 100145)  0x0804ca90 in real_eom (ctx=Cannot 
access memory at address 0xbf000008
) at milter-greylist.c:918
Cannot access memory at address 0xbf000004

up just results in: Cannot access memory at address 0xbf000004

John

> * 1 Thread 285b99c0 (LWP 100145)  0x0804ca90 in real_eom (ctx=Cannot 
> access memory at address 0xbf000008
> ) at milter-greylist.c:918
> Cannot access memory at address 0xbf000004
> 
> up just results in: Cannot access memory at address 0xbf000004

Alright, in an attempt to make some progress I tried using the 
milter-greylist dev tree ( 4.3.8 ). This has got the proper

if (priv->priv_dkimstat != DKIM_STAT_OK) {

on line 151 there, and the milter does not crash. So, I assume whatever 
has changed outside dkimcheck.c makes the difference. That being said
stepping through dkimcheck_header/dkimcheck_validate and dkimcheck_error

priv->priv_dkimstat stays:

priv_dkim = 0x287eb600, priv_dkimstat = 0

through out stepping through. The result with 4.3.8 is that header or
not, the dkim pass ACL matches every time. I added some debug printing
to dkimcheck_error like so (for each case): 

 case DKIM_STAT_NOSIG: 
                mg_log(LOG_DEBUG, "DKIM failed: %s",
                       dkim_getresultstr(priv->priv_dkimstat));

                retval = SMFIS_CONTINUE;
                break;

Logging results in:

Sep 10 05:35:23 nyima milter-greylist: DKIM: Pass

So, now that we know line 151 isn't causing this to fail where should I 
poke around next? It still seems that there is either a misinterpreted 
return value or a default (pass?) is just plain untouched.

John

> So, now that we know line 151 isn't causing this to fail where should 
> I poke around next? It still seems that there is either a 
> misinterpreted return value or a default (pass?) is just plain 
> untouched.

Well, I think this is it. Watch what happens to priv_dkim.

(gdb) print priv->priv_dkim
$17 = (DKIM *) 0xffb6afe8
(gdb) n
809             len = strlen(name) + strlen(sep) + strlen(value) + 
strlen(crlf);
(gdb) where
#0  real_header (ctx=0x2863fb80, name=0x286f9400 "Date", 
value=0x286f9405 "Wed, 15 Sep 2010 22:05:37 -0700")
    at milter-greylist.c:809
#1  0x0804b244 in mlfi_header (ctx=0x2863fb80, header=0x286f9400 "Date", 
    value=0x286f9405 "Wed, 15 Sep 2010 22:05:37 -0700") at 
milter-greylist.c:236
#2  0x282e0f36 in st_header () from /usr/local/lib/libmilter.so.4
#3  0x282e1fd2 in mi_engine () from /usr/local/lib/libmilter.so.4
#4  0x282e3b75 in mi_worker () from /usr/local/lib/libmilter.so.4
#5  0x2813b75f in pthread_getprio () from /lib/libthr.so.3
#6  0x00000000 in ?? ()
(gdb) n
810             priv->priv_msgcount += len;
(gdb) n
812             if (priv->priv_msgcount > conf.c_maxpeek) {
(gdb) n
820             if ((h = malloc(sizeof(*h))) == NULL) {
(gdb) n
825             len = strlen(name) + strlen(sep) + strlen(value) + 
strlen(crlf);
(gdb) n
826             if ((h->h_line = malloc(len + 1)) == NULL) {
(gdb) n
830             h->h_line[0] = '\0';
(gdb) n
831             strcat(h->h_line, name);
(gdb) n
832             strcat(h->h_line, sep);
(gdb) n
833             strcat(h->h_line, value);
(gdb) n
834             strcat(h->h_line, crlf);
(gdb) n
835             h->h_len = len;
(gdb) print priv->priv_dkim
$18 = (DKIM *) 0x0

..which actually happens here:

$1 = (DKIM *) 0xffb6afe8
(gdb) n
809             len = strlen(name) + strlen(sep) + strlen(value) + 
strlen(crlf);
(gdb) print priv->priv_dkim
$2 = (DKIM *)  0x0

Name, sep, value and crlf are all sane.

This happens in the same manner in both 4.3.8 and 4.2.6, so I guess 
there is a memory leak somewhere (if strlen was busted, the OS would be 
in a world of pain). I've yet to try this on another system, so I cannot 
rule out something on FreeBSD 8.1REL being the culprit.

John

> $1 = (DKIM *) 0xffb6afe8
> (gdb) n
> 809             len = strlen(name) + strlen(sep) + strlen(value) + 
> strlen(crlf);
> (gdb) print priv->priv_dkim
> $2 = (DKIM *)  0x0

Actually I think this is OK, sigh. *priv before line 809 is 
uninitialized and full of garbage/invalid data. Post 809 is populated 
with the correct data, including priv_dkim.

John

John Wood <john-misc@...> wrote:

> where should I poke around next? I

In dkimcheck_validate(), shoudn't this:

        stat = ad ? *(enum spf_status *)ad : MGSPF_PASS;

Be in fact something more like this (not tested, not even built)

        stat = ad ? ad->dkim_status : MGSPF_PASS;

And same problem in acl_print_dkim(). Of couse, ad being an union, it
should not makeany difference, but how knows how the compiler builds it?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

Alright, I *think* I've made some progress.

> In dkimcheck_validate(), shoudn't this:
> 
>         stat = ad ? *(enum spf_status *)ad : MGSPF_PASS;
> 
> Be in fact something more like this (not tested, not even built)
> 
>         stat = ad ? ad->dkim_status : MGSPF_PASS;
> 
> And same problem in acl_print_dkim(). Of couse, ad being an union, it
> should not makeany difference, but how knows how the compiler builds it?

Adjusting those appears to have made the strlen I reported earlier sane
at both points. However, stepping through dkimcheck_validate shows me 
that:

Breakpoint 1, dkimcheck_validate (ad=0x28512318, stage=AS_DATA, 
ap=0xbf5f98b8, priv=0x286acd00) at dkimcheck.c:249
249                     result = (priv->priv_dkimstat == DKIM_STAT_OK);
(gdb) s
250                     break;
(gdb) p ad->dkim_status
$7 = MGSPF_PASS
(gdb) p priv->priv_dkimstat
$8 = 0
(gdb) p priv->priv_dkim
$9 = (DKIM *) 0x0

on a message without a signature. priv_dkim|dkimstat are correct 0/NULL 
(as there is no header that is a signature that validates), but this

(dkimcheck.c ~ 248ish)

switch (stat) {
        case MGSPF_PASS:
                result = (priv->priv_dkimstat == DKIM_STAT_OK);
                break;

is always the final destination. I'm wondering if milter-greylist.c's

#ifdef USE_DKIM
        priv->priv_dkim = NULL;
        priv->priv_dkimstat = DKIM_STAT_OK;

is passing all the way through unmodified. Indeed, if I set:

#ifdef USE_DKIM
        priv->priv_dkim = NULL;
        priv->priv_dkimstat = DKIM_STAT_NOSIG 

that is exactly what happens (I get a NOSIG match in greylist.conf). So 
the ACL not matching is not a bug, it works just fine. What appears to 
be the problem is that our two friends priv_dim and priv_dkimstat are 
never populated with the results from the results of dkim_verify (or the 
results from the call are erroneously 0), so they remain the default 
all the way through. Breaking at the various dkimstat_* shows them never 
changing from NULL|a pointer and 0.

So, when there is no signature and priv_dkim is NULL, 
dkimcheck_eom's line:

priv->priv_dkimstat = dkim_eom(priv->priv_dkim, &testkey);

is never called (which is correct). However, NOSIG is never set or 
returned at any point. On mail with a signature the same thing happens. 
We see it hit dkimcheck_eom, but being null it gets to the above line.

So, dkimcheck_header's line:

priv->priv_dkim = dkim_verify(dkim_ptr, priv->priv_queueid,
                                              NULL, &priv->priv_dkimstat);

is what I think is failing. I pushed through mail with a faulty 
signature to see. 

Breakpoint 1, dkimcheck_header (name=0x2882c380 "DKIM-Signature",
    value=0x2882c38f 
"v=1;a=rsa-sha256;c=relaxed/relaxed;d=gmail.com;s=gamma;h=domainkey-signature:mime-version:received:received:in-reply-to:references:date:message-id:subject:from:to:content-type:content-transfer-encodin"...,
    priv=0x288c0700) at dkimcheck.c:152
152             if (priv->priv_dkim == NULL) {
(gdb) s
160                     if (priv->priv_dkimstat != DKIM_STAT_OK)
(gdb) s
163                     priv->priv_dkim = dkim_verify(dkim_ptr, 
priv->priv_queueid,
(gdb) s
165                     syslog(LOG_NOTICE, "%p %d", priv->priv_dkim, 
priv->priv_dkimstat);
(gdb) p priv->priv_dkim
$3 = (DKIM *) 0x28643600
(gdb) p priv->priv_dkimstat
$4 = 0

This is probably why checking dkimcheck_* never showed anything but NULL 
(or a pointer) and 0 (OK). 

John

On Fri, Sep 17, 2010 at 06:17:28PM +0900, John Wood wrote:
> So, when there is no signature and priv_dkim is NULL, 
> dkimcheck_eom's line:
> 
> priv->priv_dkimstat = dkim_eom(priv->priv_dkim, &testkey);
> 
> is never called 

I suspect it should be initialized to DKIM_NOSIG, so that we
get this result when there is no signature.

-- 
Emmanuel Dreyfus
manu@...

> I suspect it should be initialized to DKIM_NOSIG, so that we get this 
> result when there is no signature.

I thought that might be the case, however it doesn't explain what
is going on with dkim_verify when it sees a dkim header. 

I'll try pushing a signed message through when DKIM_NOSIG is set. I 
suspect that dkim_verify will not change priv_dkimstat and it will still 
end up as NOSIG.

John

> I thought that might be the case, however it doesn't explain what is 
> going on with dkim_verify when it sees a dkim header.
> 
> I'll try pushing a signed message through when DKIM_NOSIG is set. I 
> suspect that dkim_verify will not change priv_dkimstat and it will 
> still end up as NOSIG.

Actually, before I do that I think I see what is wrong with dkim_verify. 
Rather, it seems to work but watch (data details obscured):

Breakpoint 1, dkimcheck_header (name=0x2884bec0 "Received", 
    value=0x2884bec9 "from hostname.domain
(hostname.domain [111.11.111.111])\n\t(authenticated 
bits=0)\n\tby another.host.com (Sendmail version/Sendmail version) with ESMTP 
id o8HFnwdZ007274\n\t(version=TLSv1/SSLv"..., 
    priv=0x288bd800) at dkimcheck.c:152
152             if (priv->priv_dkim == NULL) {
(gdb) s
160                     if (priv->priv_dkimstat != DKIM_STAT_OK)
(gdb) s
163                     priv->priv_dkim = dkim_verify(dkim_ptr, 
priv->priv_queueid,
(gdb) p priv->priv_dkim
$1 = (DKIM *) 0x0
(gdb) p priv->priv_dkimstat
$2 = 0
(gdb) s

(added by me)

165                     syslog(LOG_NOTICE, "%p %d", priv->priv_dkim, 
priv->priv_dkimstat);
(gdb) s
166                     if (priv->priv_dkim == NULL) {
(gdb) s
175             len = strlen(name) + strlen(value) + 2;
(gdb) s
176             if ((header = malloc(len + 1)) == NULL) {
(gdb) s
182             (void)snprintf((char *)header, len, "%s: %s", name, 
value);
(gdb) s
183             priv->priv_dkimstat = dkim_header(priv->priv_dkim, 
header, len + 1);
(gdb) p priv->priv_dkim
$3 = (DKIM *) 0x28719600

OK, so there's the handle 

(gdb) p priv->priv_dkimstat
$4 = 0

Yup..

(gdb) cont
Continuing.

and here comes the next header...

Breakpoint 1, dkimcheck_header (name=0x286f53d0 "X-DKIM", 
    value=0x286f53d7 "Header Blah Blah Blah", priv=0x288bd800)
    at dkimcheck.c:152
152             if (priv->priv_dkim == NULL) {
(gdb) p priv->priv_dkim
$5 = (DKIM *) 0x0

Handle.. lost? The comments for dkimcheck_header indicate that 
priv->priv_dkim is only null if a header has not been processed before. 
So it looks like every time dkimcheck_header fires it gets a null value 
for priv->priv_dkim. Are we losing the verify handles here?

John

On Sat, Sep 18, 2010 at 01:03:34AM +0900, John Wood wrote:
> Handle.. lost? The comments for dkimcheck_header indicate that 
> priv->priv_dkim is only null if a header has not been processed before. 
> So it looks like every time dkimcheck_header fires it gets a null value 
> for priv->priv_dkim. Are we losing the verify handles here?

I think you spoted a bug.

-- 
Emmanuel Dreyfus
manu@...

> I think you spoted a bug.

Fixing it is probably a bit beyond me, just getting this right(?) is 
about the limit of my meager debug abilities.

John

... As it turns out, it was definitely beyond me. Thanks to Jörgen Lundman (lundman _at_ lundman.net), this is now working properly. The attached diff is for

John Wood <john-misc@...> wrote:

> I've also tested linking against the OpenDKIM libs, the current active
> DKIM tree. This also works.

Great. I checked in your patch.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...