Hi Jukka, I looked for a while at the packet log you posted. In particular I'm looking at the interaction between your filter (apparently listening on port 1026) and the MTA talking from port 63915.
Two important points: 1) For which domains are you configured to sign? 2) Do you have any -C (command line) or "On-" (config file) options in use? Everything is fine up to the packet at 12:43:20.657588 from the filter. It sends a message with a command of "c", meaning "continue", in response to the message body which was the large packet right before that. (Only the final five bytes, namely four length bytes and a command byte, are important there; the rest is probably TCP headers and such.) The next message is from the MTA, at 12:43:20.658002. It sends down the message's job ID as a macro, then sends "E" meaning end-of-message. This tells the filter to run verification on the message. This is also normal. At 12:43:20.856643, the filter sends an ACK to the MTA. The next message at 12:48:20.691603 is from the MTA and is a FIN packet, meaning it is shutting down the connection (timeout; note five minutes have elapsed, which I'm assuming is postfix's milter timeout). The next packet is an ACK from the filter. Two hours later, the filter gives up waiting for more data from the MTA and shuts down its side of the connection. The same happens for the interaction with MTA socket 63916. The only thing I can think of is that mlfi_eom() is returning without a proper milter status somehow. This would cause libmilter's sendreply() function to do nothing because it will only send to the MTA reply codes it understands. I found a possible cause for this but it would only be happening on signing. This will be fixed in 2.5.0. However, I can't spot a code path for it while verifying. The reason I asked about your signing domains and configuration is to determine whether your filter might have been in signing mode for that message, or an exceptional condition might've caused something strange to be returned to libmilter. As for the rest of the sessions you mentioned in the "notes1" file: 63868: The MTA told the filter to abort (see packet at 12:58:47.231272). This is usually caused by another filter making a final decision about the message while processing this one. 63860: Normal completion, showing the Authentication-Results: header being added at 13:00:43.825737 and the X-DKIM: header at 13:00:44.016634, followed by an "accept" instruction. Strangely, the MTA replies by sending down a recipient-stage macro, then aborting and quitting. The session was far past recipient processing there, so that looks pretty odd to me. 63840: no packets for this session were present in the dump 63837: same as 63915, 63916 63835: same as 63915, 63916 63831: same as 63915, 63916 63666: same as 63860 63664: same as 63860 -MSK ------------------------------------------------------------------------- This SF.net email is sponsored by: Microsoft Defy all challenges. Microsoft(R) Visual Studio 2008. http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/ _______________________________________________ dkim-milter-discuss mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/dkim-milter-discuss
