Just In Time
Purely coïncidental, but being there may prevent a problem.
At times it happens that my werkstation doesn’t get all settings form the DHCP server in one go and I need to renew the DHCP settings. Today was such a day: nothing seemed wrong when I started doing my thing, but as soon as I set up a connection to Diana using a terminal emulator, it failed because it’s logical address couldn’t be translated – meaning the DNS server (on Diana) didn’t respond. Renewal of the settings (ipconfig /renew) helped, but login hung – there was simply no response.
Luckily, it’s just a matter of rotating my chair to access the (graphical) console. $ SHO SYS revealed that there were 10 PMAS worker processes working – so it was obvious that, once more, someone was trying to break the mail server. BEcause there have been a number of issues lately with mail, I have the worker set up to log, so it soon became obvious that there was one particular server trying to fire large amount of connect requests that overwhelmed the spam agent:
24-SEP-2013 17:28:22.47: ======================================================
24-SEP-2013 17:28:22.47: RelayPlug: Connection accepted from 81.5.148.161
24-SEP-2013 17:28:22.48: RelayPlug: External IP address, so set up to check MAIL FROM:....
Failed to connect to 192.168.0.2-25 - connection refused
24-SEP-2013 17:28:22.49: RelayPlug: End connection event triggered
24-SEP-2013 17:28:22.67: ======================================================
24-SEP-2013 17:28:22.67: RelayPlug: Connection accepted from 81.5.148.161
24-SEP-2013 17:28:22.68: RelayPlug: External IP address, so set up to check MAIL FROM:...
Failed to connect to 192.168.0.2-25 - connection refused
24-SEP-2013 17:28:22.69: RelayPlug: End connection event triggered
24-SEP-2013 17:28:23.47: ======================================================
This went on, and on, and on…
To prevent further damage – because it was not to be expected the bombardment would stop by these actions – I blocked the address in the firewall.
Next, I started investigating.
These messages show the front-end couldn’t connect to port 25 – the SMPT port used for outgoing traffic. The fast – and easy – way to set things straight againwas sstopping the mail frontend, and restarting it. It removed the worker processes but left the main process in RWAST state. STOP/ID did indeed – after some time – stop the main frontend process.
Next, it was a matter of examining the firewall logs, and sure enough, that showed the full sequence. It started just before 17:00 (UTC) with a connect request to the mail server – by NAT, transferred to port 2525: the mail frontend. That responds with a test of the validity of that address. Before that is answered, the next requests arrives, causing a second request from the mail frontend, and so on. Within a minute, there was hardly any other traffic over the firewall than these mail connect requests and the forntend’s response:
Sep 24 16:56:05 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:02 ][@S:R=13:1, 81.5.148.161:52059->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=3513532061, Ack=0, Win=65535]
Sep 24 16:56:05 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:02 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:52059][TCP][HLen=20, TLen=44, Flag=AS, Seq=2090788352, Ack=3513532062, Win=16824]
Sep 24 16:56:05 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:02 ][@S:R=13:1, 192.168.0.2:42266->194.109.9.99:53][UDP][HLen=20, TLen=86]
Sep 24 16:56:05 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:02 ][@S:R=13:1, 192.168.0.2:60665->194.109.9.99:53][UDP][HLen=20, TLen=86]
Sep 24 16:56:05 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:02 ][@S:R=13:1, 192.168.0.2:7587->194.109.9.99:53][UDP][HLen=20, TLen=85]
Sep 24 16:56:05 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:02 ][@S:R=13:1, 192.168.0.2:44268->194.109.9.99:53][UDP][HLen=20, TLen=84]
Sep 24 16:56:06 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:03 ][@S:R=13:1, 192.168.0.2:25782->194.109.9.99:53][UDP][HLen=20, TLen=92]
Sep 24 16:56:07 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:04 ][@S:R=13:1, 192.168.0.2:46706->192.55.83.30:53][UDP][HLen=20, TLen=72]
Sep 24 16:56:09 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:06 ][@S:R=13:1, 192.168.0.2:21156->38.103.2.1:53][UDP][HLen=20, TLen=72]
Sep 24 16:56:09 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:06 ][@S:R=13:1, 192.168.0.2:36146->199.249.121.1:53][UDP][HLen=20, TLen=73]
Sep 24 16:56:11 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:08 ][@S:R=13:1, 192.168.0.2:62610->72.52.71.1:53][UDP][HLen=20, TLen=73]
Sep 24 16:56:11 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:08 ][@S:R=13:1, 81.5.148.161:50729->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2905819008, Ack=0, Win=65535]
Sep 24 16:56:11 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:08 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50729][TCP][HLen=20, TLen=44, Flag=AS, Seq=1903256155, Ack=2905819009, Win=16824]
Sep 24 16:56:11 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:08 ][@S:R=13:1, 81.5.148.161:50751->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=1608792645, Ack=0, Win=65535]
Sep 24 16:56:11 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:08 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50751][TCP][HLen=20, TLen=44, Flag=AS, Seq=491343422, Ack=1608792646, Win=16824]
Sep 24 16:56:11 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:08 ][@S:R=13:1, 81.5.148.161:50900->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2106594754, Ack=0, Win=65535]
Sep 24 16:56:11 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:08 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50900][TCP][HLen=20, TLen=44, Flag=AS, Seq=1610899123, Ack=2106594755, Win=16824]
Sep 24 16:56:12 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:09 ][@S:R=13:1, 69.197.128.26:47499->192.168.0.200:80][TCP][HLen=20, TLen=60, Flag=S, Seq=851656388, Ack=0, Win=14600]
Sep 24 16:56:12 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:09 ][@S:R=13:1, 192.168.0.200:80->69.197.128.26:47499][TCP][HLen=20, TLen=48, Flag=AS, Seq=1834372936, Ack=851656389, Win=61688]
Sep 24 16:56:12 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:09 ][@S:R=13:1, 81.5.148.161:52269->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=4034781716, Ack=0, Win=65535]
Sep 24 16:56:12 FW: [FILTER][Pass][LAN/RT/VPN->WAN, 476:36:09 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:52269][TCP][HLen=20, TLen=44, Flag=AS, Seq=3336740259, Ack=4034781717, Win=16824]
Sep 24 16:56:12 FW: [FILTER][Pass][WAN->LAN/RT/VPN, 476:36:09 ][@S:R=13:1, 81.5.148.161:52404->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=673951290, Ack=0, Win=65535]
and at some point, it was only the frontend trying to get to the sender, hundreds of attempts a minute.
After I blocked the adress, the frontend continued asking for the sender:
Sep 24 17:34:43 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:39 ][@S:R=13:1, 192.168.0.2:25747->194.109.9.99:53][UDP][HLen=20, TLen=84]
Sep 24 17:34:43 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:39 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50163][TCP][HLen=20, TLen=40, Flag=AF, Seq=345529474, Ack=3100051374, Win=16824]
Sep 24 17:34:44 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:14:39 ][@S:R=3:2, 81.5.148.161:50540->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2606349597, Ack=0, Win=65535]
Sep 24 17:34:44 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:39 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50794][TCP][HLen=20, TLen=40, Flag=AF, Seq=2937753010, Ack=3183395198, Win=16824]
Sep 24 17:34:44 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:40 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:0][TCP][HLen=20, TLen=44, Flag=AS, Seq=1040412343, Ack=310902461, Win=16824]
Sep 24 17:34:44 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:40 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:50280][TCP][HLen=20, TLen=40, Flag=AF, Seq=1422084251, Ack=3320381021, Win=16824]
Sep 24 17:34:44 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:40 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:52618][TCP][HLen=20, TLen=40, Flag=AF, Seq=4161431313, Ack=2911615049, Win=16824]
Sep 24 17:34:44 FW2: [FILTER][Pass][LAN/RT/VPN->WAN, 477:14:40 ][@S:R=13:1, 192.168.0.200:2525->81.5.148.161:53105][TCP][HLen=20, TLen=40, Flag=AF, Seq=3854292009, Ack=4072697059, Win=16824]
while the sender tried, and tried…Eventually, I stopped the frontend so these requests were now gone, and other traffic got a chance to get through:
Sep 24 17:57:44 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:37 ][@S:R=3:2, 81.5.148.161:52466->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=1711623955, Ack=0, Win=65535]
Sep 24 17:57:45 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:38 ][@S:R=3:2, 81.5.148.161:49595->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=3531258844, Ack=0, Win=65535]
Sep 24 17:57:46 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:39 ][@S:R=3:2, 81.5.148.161:50602->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2416492183, Ack=0, Win=65535]
Sep 24 17:57:46 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:39 ][@S:R=3:2, 81.5.148.161:51035->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=4075797788, Ack=0, Win=65535]
Sep 24 17:57:47 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:40 ][@S:R=3:2, 81.5.148.161:51649->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=1615220663, Ack=0, Win=65535]
Sep 24 17:57:48 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:41 ][@S:R=3:2, 81.5.148.161:53184->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=964671704, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:42 ][@S:R=3:2, 81.5.148.161:53108->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2694901457, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:42 ][@S:R=3:2, 81.5.148.161:50126->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2149152341, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50192->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=467935095, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50254->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=3213471951, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50316->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=614172963, Ack=0, Win=65535]
Sep 24 17:57:49 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50322->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=1804337752, Ack=0, Win=65535]
Sep 24 17:57:50 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50343->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=1710313407, Ack=0, Win=65535]
Sep 24 17:57:50 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:43 ][@S:R=3:2, 81.5.148.161:50554->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2321196107, Ack=0, Win=65535]
Sep 24 17:57:51 FW2: [FILTER][Block][WAN->LAN/RT/VPN, 477:37:44 ][@S:R=3:2, 81.5.148.161:51346->192.168.0.200:2525][TCP][HLen=20, TLen=48, Flag=S, Seq=2653175112, Ack=0, Win=65535]
In that time, I tried to figure out whose server this is:
$ dig -x 81.5.148.161
; < <>> DiG 9.3.1 < <>> -x 81.5.148.161
;; global options: printcmd
;; Got answer:
;; ->>HEADER< <- opcode: QUERY, status: NOERROR, id: 44357
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 3, ADDITIONAL: 0
;; QUESTION SECTION:
;161.148.5.81.in-addr.arpa. IN PTR
;; ANSWER SECTION:
161.148.5.81.in-addr.arpa. 7200 IN PTR mailhost2.cairnsbrown.co.uk.
;; AUTHORITY SECTION:
148.5.81.in-addr.arpa. 20819 IN NS dns2.as12513.net.
148.5.81.in-addr.arpa. 20819 IN NS dns1.as12513.net.
148.5.81.in-addr.arpa. 20819 IN NS dns1.eclipse.net.uk.
;; Query time: 416 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Wed Sep 25 07:30:05 2013
;; MSG SIZE rcvd: 164
$
It turned out to be a solliciter's firm, their mailserver is behaving badly, is badly configured (an open relay?), hacked or otherwise compromised. So I warned them - by mail. But I couldn't connect to the SMTP server. So I stopped and restarted it, but found that a number of TCPIP$SMTP processes were stalled in RWAST. I could stop two of them by STOP/ID - it tool a minute or so to get them off the hook - but two of them were waiting for a mailbox to be read. It was sufficient to open a channel to that mailbox, read it twice and close it, and these two were gone as well.
Now I could send the message.
But during the time I was composing the message, the offending server all of a sudden stopped bothering me; and no more mesages were sent after 18:05.
There now is a request to Process.com: If one address sends messages in this rate: several within a second: don't bother to process them but simply disconnect.
Tuned the firewall rules
I fine-tuned teh firewall rules so I can still block eDonkey traffic but still have the forntend communicate to the two sites found yesterday. No others – yet.
What goes on behind the doors of the (private) data center