On Wed, May 27, 2009 at 10:54:22PM +0200, Petar Bogdanovic wrote:
> On Wed, May 27, 2009 at 08:02:32PM +0000, Vernon Schryver wrote:
> > Does snooping with tcpdump or ethereal show that the DCC requests are
> > going out? Being answered?
>
> I'll try 1.3.104 again today or during the next few days, check the
> traffic with tcpdump and report back.
Lets begin with `re-resolve on first use' vs. `cdcc rtt'. map contains
names which were not resolved during the initial installation (due to
lack of DNS):
# spamassassin -D <gtube.txt 2>&1 | grep -i dcc
(...)
[669] dbg: dcc: dccifd is available: /var/dcc/dccifd
[669] dbg: dcc: dccifd got response: X-DCC--Metrics: MYHOST 0; Body=1
Fuz1=1 Fuz2=1
# grep dcc /var/log/maillog
dccifd[501]: 1.3.104 listening to /var/dcc/dccifd for ASCII protocol
dccifd[501]: no working DCC servers dcc1.dcc-servers.net
dcc2.dcc-servers.net dcc3.dcc-servers.net ... at 127.0.0.1
dccifd[501]: continue not asking DCC 124 seconds after failure
Ok, lets wait.
# cdcc info
# 05/27/09 23:32:28 CEST /var/dcc/map
# Re-resolve names after 01:23:53 Check RTTs after 23:38:53
# 1 total, 0 working servers
# skipping asking DCC server 4 seconds more
Only 4 more seconds..
# cdcc info
# 05/27/09 23:32:36 CEST /var/dcc/map
# Re-resolve names after 01:23:53 Check RTTs after 23:38:53
# 1 total, 0 working servers
Ready? Lets try.
# spamassassin -D <gtube.txt 2>&1 | grep -i dcc
(...)
[669] dbg: dcc: dccifd is available: /var/dcc/dccifd
[669] dbg: dcc: dccifd got response: X-DCC--Metrics: MYHOST 0; Body=1
Fuz1=1 Fuz2=1
# cdcc info
# 05/27/09 23:32:46 CEST /var/dcc/map
# Re-resolve names after 01:23:53 Check RTTs after 23:38:53
# 1 total, 0 working servers
# skipping asking DCC server 508 seconds more
Not really.
# cdcc rtt
# 05/27/09 23:35:42 CEST /var/dcc/map
# Re-resolve names after 01:35:37 Check RTTs after 23:50:42
# 1347.14 ms threshold, 1222.97 ms average 12 total, 10 working
servers
IPv6 on version=3
dcc1.dcc-servers.net,- RTT+1000 ms anon
# 137.208.8.26,- wuwien ID
1290
# protocol version 8
# 100% of 3 requests ok 1031.91+1000 ms RTT 100 ms queue wait
# 209.169.14.26,- x.dcc-servers ID
104
# 100% of 1 requests ok 322.07+1000 ms RTT 100 ms queue wait
# 209.169.14.29,- x.dcc-servers ID
104
# 100% of 1 requests ok 321.08+1000 ms RTT 100 ms queue wait
dcc2.dcc-servers.net,- RTT+1000 ms anon
# *195.20.8.232,- EATSERVER ID
1166
# 100% of 1 requests ok 122.97+1000 ms RTT 100 ms queue wait
# 203.81.36.6,- PacNet-SG ID
1358
# 100% of 2 requests ok 569.62+1000 ms RTT 200 ms queue wait
dcc3.dcc-servers.net,- RTT+1000 ms anon
# 194.228.41.73,- CTc-dcc1 ID
1030
# protocol version 8
# 100% of 1 requests ok 134.76+1000 ms RTT 100 ms queue wait
# 209.169.14.27,- x.dcc-servers ID
104
# 100% of 1 requests ok 322.75+1000 ms RTT 100 ms queue wait
dcc4.dcc-servers.net,- RTT+1000 ms anon
# 152.20.253.5,- dcc.uncw.edu ID
1201
# 100% of 1 requests ok 247.14+1000 ms RTT 100 ms queue wait
# 194.228.41.13,- CTc-dcc2 ID
1031
# protocol version 8
# 100% of 1 requests ok 135.25+1000 ms RTT 100 ms queue wait
dcc5.dcc-servers.net,- RTT+1000 ms anon
# 209.34.225.42,-
# not answering
# 216.240.97.12,- dmv.com ID
1181
# protocol version 8
# 100% of 1 requests ok 211.29+1000 ms RTT 100 ms queue wait
All right, thats better. Lets retry SpamAssassin.
# spamassassin -D <gtube.txt 2>&1 | grep -i dcc
(...)
[554] dbg: dcc: dccifd is available: /var/dcc/dccifd
[554] dbg: dcc: dccifd check timed out after 8 secs.
# grep dcc /var/log/maillog
dccifd[501]: no DCC answer from dcc4.dcc-servers.net
(152.20.253.5,6277) after 6050 ms
dccifd[501]: write(MTA socket,76): Broken pipe
As expected. Lets run SpamAssassin a couple of times.
# for i in $(seq 1 100); do spamassassin -D <gtube.txt 2>&1 | grep -i
dcc; done
(...)
Minutes later..
# cdcc info
# 05/27/09 23:42:52 CEST /var/dcc/map
# Re-resolve names after 01:35:37 Check RTTs after 23:50:42
# 8000.00 ms threshold, 1222.97 ms average 12 total, 10 working
servers
IPv6 on version=3
dcc1.dcc-servers.net,- RTT+1000 ms anon
# 137.208.8.26,- wuwien ID
1290
# protocol version 8
# 27% of 11 requests ok 4000.00+1000 ms RTT 100 ms queue wait
# 209.169.14.26,- x.dcc-servers ID
104
# 20% of 5 requests ok 4000.00+1000 ms RTT 100 ms queue wait
# 209.169.14.29,- x.dcc-servers ID
104
# 20% of 5 requests ok 4000.00+1000 ms RTT 100 ms queue wait
dcc2.dcc-servers.net,- RTT+1000 ms anon
# 195.20.8.232,- EATSERVER ID
1166
# 8% of 13 requests ok 4000.00+1000 ms RTT 100 ms queue wait
# 203.81.36.6,- PacNet-SG ID
1358
# 33% of 6 requests ok 4000.00+1000 ms RTT 200 ms queue wait
dcc3.dcc-servers.net,- RTT+1000 ms anon
# 194.228.41.73,- CTc-dcc1 ID
1030
# protocol version 8
# 8% of 13 requests ok 4000.00+1000 ms RTT 100 ms queue wait
# 209.169.14.27,- x.dcc-servers ID
104
# 20% of 5 requests ok 4000.00+1000 ms RTT 100 ms queue wait
dcc4.dcc-servers.net,- RTT+1000 ms anon
# 152.20.253.5,- dcc.uncw.edu ID
1201
# 8% of 13 requests ok 4000.00+1000 ms RTT 100 ms queue wait
# 194.228.41.13,- CTc-dcc2 ID
1031
# protocol version 8
# 8% of 13 requests ok 4000.00+1000 ms RTT 100 ms queue wait
dcc5.dcc-servers.net,- RTT+1000 ms anon
# 209.34.225.42,-
# not answering
# 216.240.97.12,- dmv.com ID
1181
# protocol version 8
# 8% of 13 requests ok 4000.00+1000 ms RTT 100 ms queue wait
It seems that I don't get any answers at all. Lets tcpdump one session.
# spamassassin -D <gtube.txt 2>&1 | grep -i dcc
(...)
[1047] dbg: dcc: dccifd is available: /var/dcc/dccifd
[1047] dbg: dcc: dccifd check timed out after 8 secs.
# tcpdump -vvvv -i rtk0 udp port 6277
tcpdump: listening on rtk0, link-type EN10MB (Ethernet), capture size
96 bytes
23:50:10.094242 IP (... length: 180) MYHOST.65500 >
dcc-1.eatserver.nl.6277: UDP, length: 152
23:50:10.217154 IP (... length: 116) dcc-1.eatserver.nl.6277 >
MYHOST.65500: UDP, length: 88
23:50:10.444220 IP (... length: 180) MYHOST.65500 >
dcc-1.eatserver.nl.6277: UDP, length: 152
23:50:10.569212 IP (... length: 116) dcc-1.eatserver.nl.6277 >
MYHOST.65500: UDP, length: 88
23:50:11.044208 IP (... length: 180) MYHOST.65500 >
dcc-1.eatserver.nl.6277: UDP, length: 152
23:50:11.165145 IP (... length: 116) dcc-1.eatserver.nl.6277 >
MYHOST.65500: UDP, length: 88
23:50:12.144210 IP (... length: 180) MYHOST.65500 >
dcc-1.eatserver.nl.6277: UDP, length: 152
23:50:12.265192 IP (... length: 116) dcc-1.eatserver.nl.6277 >
MYHOST.65500: UDP, length: 88
23:50:16.144244 IP (... length: 180) MYHOST.65500 >
h4-vjs.colo.indra.com.6277: UDP, length: 152
23:50:16.374800 IP (... length: 116) h4-vjs.colo.indra.com.6277 >
MYHOST.65500: UDP, length: 88
23:50:16.494252 IP (... length: 180) MYHOST.65500 >
h4-vjs.colo.indra.com.6277: UDP, length: 152
23:50:16.726501 IP (... length: 116) h4-vjs.colo.indra.com.6277 >
MYHOST.65500: UDP, length: 88
23:50:17.094246 IP (... length: 180) MYHOST.65500 >
h4-vjs.colo.indra.com.6277: UDP, length: 152
23:50:17.352498 IP (... length: 116) h4-vjs.colo.indra.com.6277 >
MYHOST.65500: UDP, length: 88
23:50:18.194257 IP (... length: 180) MYHOST.65500 >
h4-vjs.colo.indra.com.6277: UDP, length: 152
23:50:18.447587 IP (... length: 116) h4-vjs.colo.indra.com.6277 >
MYHOST.65500: UDP, length: 88
I can't really read that output but it seems to me that I'm actually
getting an answer every time I'm asking for one. Lets see (log) what
ipfilter sees.
pass out log proto udp from any to any port = 6277 keep state # DCC
^^^
ipmon[317]: 23:54:09.999847 rtk0 @0:16 p MYHOST,65500 ->
209.169.14.27,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:10.237437 rtk0 @0:16 p 209.169.14.27,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:10.349835 rtk0 @0:16 p MYHOST,65500 ->
209.169.14.27,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:10.583213 rtk0 @0:16 p 209.169.14.27,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:10.949831 rtk0 @0:16 p MYHOST,65500 ->
209.169.14.27,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:11.180647 rtk0 @0:16 p 209.169.14.27,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:12.049829 rtk0 @0:16 p MYHOST,65500 ->
209.169.14.27,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:12.278444 rtk0 @0:16 p 209.169.14.27,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:16.049879 rtk0 @0:16 p MYHOST,65500 ->
203.81.36.6,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:16.619082 rtk0 @0:16 p 203.81.36.6,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:16.719552 rtk0 @0:16 p MYHOST,65500 ->
203.81.36.6,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:17.288365 rtk0 @0:16 p 203.81.36.6,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:17.958900 rtk0 @0:16 p MYHOST,65500 ->
203.81.36.6,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:18.527800 rtk0 @0:16 p 203.81.36.6,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
ipmon[317]: 23:54:20.337624 rtk0 @0:16 p MYHOST,65500 ->
203.81.36.6,6277 PR udp len 20 180 K-S OUT
ipmon[317]: 23:54:20.906424 rtk0 @0:16 p 203.81.36.6,6277 ->
MYHOST,65500 PR udp len 20 116 K-S IN
Again, this just seems good to *me*. Why am I using SpamAssassin
anyway? Lets try dccproc a couple of times.
# for i in $(seq 1 100); do dccproc <gtube.txt | grep -i dcc; done
no DCC answer from dcc2.dcc-servers.net (195.20.8.232,6277) after 15838
ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc1.dcc-servers.net (209.169.14.29,6277) after
15882 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc4.dcc-servers.net (152.20.253.5,6277) after 15882
ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc1.dcc-servers.net (209.169.14.26,6277) after
16000 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc3.dcc-servers.net (209.169.14.27,6277) after
15883 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc1.dcc-servers.net (137.208.8.26,6277) after 15840
ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc4.dcc-servers.net (194.228.41.13,6277) after
15844 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc5.dcc-servers.net (216.240.97.12,6277) after
15875 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
no DCC answer from dcc3.dcc-servers.net (194.228.41.73,6277) after
15974 ms
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
continue not asking DCC 64 seconds after failure
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
continue not asking DCC 64 seconds after failure
X-DCC--Metrics: MYHOST 0; Body=1 Fuz1=1 Fuz2=1
continue not asking DCC 64 seconds after failure
(...)
That's all I have for now. And I don't get it. As soon as I replace
1.3.104 with 1.3.103 all this suddenly works.
Petar Bogdanovic
_______________________________________________
DCC mailing list [email protected]
http://www.rhyolite.com/mailman/listinfo/dcc
