I noticed that a ResolverTracing option was available with
opendkim-2.3.1 so I decided to test it. I get about 50 debug lines
for each e-mail message. Most of it looks reasonable, but I did
notice that the filter made three identical DNS queries for a single
e-mail message. I saw the same thing with a locally-originated
message and an external one.
Is this normal and expected, or is something wrong? If it's normal,
perhaps a cache would improve performance. Here are the syslog lines
for a local message:
Mar 30 08:39:42 setup01 opendkim[15100]: [ID 482974 mail.info] OpenDKIM Filter v2.3.1 starting (args: -x /etc/mail/opendkim.conf)
Mar 30 08:39:42 setup01 opendkim[15100]: [ID 612694 mail.debug] arlib: dispatcher starting
Mar 30 08:39:42 setup01 opendkim[15100]: [ID 866719 mail.debug] arlib: dispatcher pausing
Mar 30 08:41:03 setup01 sm-mta[15120]: [ID 801593 mail.info] p2UDf3EQ015120: from=<mills_at_cc.umanitoba.ca>, size=842, class=0, nrcpts=1, msgid=<20110330134103.GA23697_at_cc.umanitoba.ca>, proto=ESMTP, daemon=MTA, relay=root_at_electra.cc.umanitoba.ca [130.179.16.34]
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 301746 mail.debug] arlib: added query 80b5c00 'cc.umanitoba.ca'
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 301746 mail.debug] arlib: added query 80b5d70 'cc.umanitoba.ca'
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 301746 mail.debug] arlib: added query 80b5ee0 'cc.umanitoba.ca'
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778763 mail.debug] arlib: waiting for query 80b5c00
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 782338 mail.debug] arlib: control socket
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 866719 mail.debug] arlib: dispatcher pausing
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 782338 mail.debug] arlib: control socket
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 996875 mail.debug] arlib: sending 80b5c00 'cc.umanitoba.ca' id=8156
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (4.999989s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 782338 mail.debug] arlib: control socket
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 996875 mail.debug] arlib: sending 80b5d70 'cc.umanitoba.ca' id=8412
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (4.999476s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 240705 mail.debug] arlib: reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 633405 mail.debug] arlib: full reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 650186 mail.debug] arlib: 80b5c00 (id 8156) reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 316912 mail.debug] arlib: 80b5c00 signaling
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 996875 mail.debug] arlib: sending 80b5ee0 'cc.umanitoba.ca' id=8668
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (4.998994s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 240705 mail.debug] arlib: reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 633405 mail.debug] arlib: full reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 650186 mail.debug] arlib: 80b5d70 (id 8412) reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 316912 mail.debug] arlib: 80b5d70 signaling
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (4.999398s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778291 mail.debug] arlib: wait for 80b5c00 succeeded
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778763 mail.debug] arlib: waiting for query 80b5d70
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 200393 mail.debug] arlib: wait for 80b5d70 successful
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778763 mail.debug] arlib: waiting for query 80b5ee0
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 240705 mail.debug] arlib: reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 633405 mail.debug] arlib: full reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 650186 mail.debug] arlib: 80b5ee0 (id 8668) reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 316912 mail.debug] arlib: 80b5ee0 signaling
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (10000000.000000s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778291 mail.debug] arlib: wait for 80b5ee0 succeeded
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 249062 mail.debug] arlib: canceling query 80b5c00
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 249062 mail.debug] arlib: canceling query 80b5d70
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 249062 mail.debug] arlib: canceling query 80b5ee0
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 301746 mail.debug] arlib: added query 80b5ee0 '_adsp._domainkey.cc.umanitoba.ca'
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778763 mail.debug] arlib: waiting for query 80b5ee0
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 782338 mail.debug] arlib: control socket
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 866719 mail.debug] arlib: dispatcher pausing
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 996875 mail.debug] arlib: sending 80b5ee0 '_adsp._domainkey.cc.umanitoba.ca' id=8924
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (4.999995s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 240705 mail.debug] arlib: reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 633405 mail.debug] arlib: full reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 650186 mail.debug] arlib: 80b5ee0 (id 8924) reply received
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 316912 mail.debug] arlib: 80b5ee0 signaling
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 314702 mail.debug] arlib: dispatcher pausing (10000000.000000s)
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 778291 mail.debug] arlib: wait for 80b5ee0 succeeded
Mar 30 08:41:03 setup01 opendkim[15100]: [ID 249062 mail.debug] arlib: canceling query 80b5ee0
Mar 30 08:41:03 setup01 sm-mta[15120]: [ID 801593 mail.info] p2UDf3EQ015120: Milter delete: header X-DCC-UofM-Metrics: electra; whitelist
Mar 30 08:41:03 setup01 sm-mta[15120]: [ID 801593 mail.info] p2UDf3EQ015120: Milter add: header: X-DCC-UofM-Metrics: setup01; whitelist
Mar 30 08:41:04 setup01 sm-mta[15122]: [ID 801593 mail.info] p2UDf3EQ015120: to=<mills_at_testing.umanitoba.ca>, delay=00:00:01, xdelay=00:00:01, mailer=local, pri=31078, relay=localhost, dsn=2.0.0, stat=Sent
--
-Gary Mills- -Unix Group- -Computer and Network Services-
Received on Wed Mar 30 2011 - 14:08:36 PST