Posted on

23-Oct-2013

A very remarkable day
Well, in hindsight, because on the day itself you could never tell:
As turned out this morning, yesterday was a very remarkable day: No quaratained mail, no discarded mail.. Well, there is mail that was rejected, but that remains out of sight unless digging in the logifle. For yesterday, there were 17 ; of which 15 were rejected because they matched a rule I have defined; only two have been scanned to find they were junk. The total number however is rather normal. As well as the wto relay attempts – though there are days without, this isn’t unexpected.

But nothing quaratained or discarded: That feels weird 🙂

Posted on

27-Feb-2014

Mail failure
Very remarkable and unexpected: After last start of the spam filter all seemed well. It did mention status in the logfile on 25-feb-2014, but with no activity on any of the worker processes. But for the whole next day no activity was logged, as it usually does verey two hours. However, I did receive some messages. But this morniong none was received. Not even in the spam boxes. So I started an investigation and I found that all messages that I received since I restarted the service, had been blaclisted on the first entry in the list: rbl.map.vix.com. Even gmail messages – that server blocks gmail as I found out early in the process – that I had explicitly allowed, didn’t come through. So I edited the PMAS configuration, found an error in the gmail address (so it should pass now) and disabled both vox.com blacklists. After restarting the anti-spam filter, messages from gmail are now accepted, but any other is marked as blacklisted address – by the now first entry. Something is definietly wrong here…

Posted on

24-Sep-2013

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.

Posted on

23-Sep-2013

More on port 2525 traffic
There is another source for information to investigate: I have the PMAS set up so the worker processes log as well (default, it’s off) and I found a hint on what’s going on.
Both addresses have the same type of signature: Mail is received for procesing, a test is made to check whether the sender is located in a blacklist, and that connection is aborted:

23-SEP-2013 21:08:24.14: RelayPlug: Connection accepted from 208.75.123.163
23-SEP-2013 21:08:24.17: RelayPlug: External IP address, so set up to check MAIL FROM:....
23-SEP-2013 21:08:26.38: RelayPlug: MAIL FROM:<(some large 'name')@in.constantcontact.com>
23-SEP-2013 21:08:26.38: PMASplug: MAIL FROM: <(some large 'name')@in.constantcontact.com>
23-SEP-2013 21:08:26.38: DNSBLplug: MAIL FROM: <(some large 'name')@in.constantcontact.com>
23-SEP-2013 21:08:26.39: DNSBLplug: Checking address 208.75.123.163....
23-SEP-2013 21:08:26.39: DNSBLplug: Address action = 0 (OK (no match))
23-SEP-2013 21:08:26.39: DNSBLplug: Checking domain name in.constantcontact.com....
23-SEP-2013 21:08:26.39: DNSBLplug: Domain action = 0 (OK (no match))
Client connection error (connection reset by peer ); aborting session
23-SEP-2013 21:08:26.43: RelayPlug: End connection event triggered

So the domains are in.constantcontact.com (an email host) and mailing.internationalcardservices.nl – both respectable companies.

There has been a connection from in.constantcontact.com but that came from another address:

23-SEP-2013 20:16:59.24: RelayPlug: Connection accepted from 208.75.123.225
23-SEP-2013 20:16:59.24: RelayPlug: External IP address, so set up to check MAIL FROM:....
23-SEP-2013 20:17:01.88: RelayPlug: MAIL FROM:<(generated_username)@in.constantcontact.com>
23-SEP-2013 20:17:01.88: PMASplug: MAIL FROM: <(generated_username)@in.constantcontact.com> 23-SEP-2013 20:17:01.88: DNSBLplug: MAIL FROM: <(generated_username)@in.constantcontact.com>
23-SEP-2013 20:17:01.88: DNSBLplug: Checking address 208.75.123.225....
23-SEP-2013 20:17:01.88: DNSBLplug: Address action = 0 (OK (no match))
23-SEP-2013 20:17:01.90: DNSBLplug: Checking domain name in.constantcontact.com....
23-SEP-2013 20:17:01.90: DNSBLplug: Domain action = 0 (OK (no match))
23-SEP-2013 20:17:02.06: RelayPlug: RCPT TO:<(my address)>
23-SEP-2013 20:17:02.44: PMASplug: Created source header X-PMAS-External: name [address] (HELO (name))
23-SEP-2013 20:17:03.12: PMASplug: Message complete, deferred size is 37588
23-SEP-2013 20:17:03.13: PMASplug: Adding header: X-PMAS-External: name [address] (HELO (name))
23-SEP-2013 20:17:03.13: PMASplug: RCPT TO: (my address) / (my address)
23-SEP-2013 20:17:03.13: PMASplug: Calling PMAS to process the message....
23-SEP-2013 20:17:25.23: PMASplug: PMAS returned status: 1
23-SEP-2013 20:17:25.23: PMASplug: Number of recipients: 1, number of dispositions: 1
23-SEP-2013 20:17:25.23: PMASplug: Message quarantined or discarded for all recipients
23-SEP-2013 20:17:25.24: DNSBLplug: Reset event triggered
23-SEP-2013 20:17:25.39: RelayPlug: End connection event triggered

and that message is indeed found in the ‘discarded’ box.

Why this started happening in the first place? The protocol (eDonkey) is blocked from the beginning and these messages never appeared before. And just these two addresses? The only remarkable is the size of the FROM address: almost 90 characters. If this is similar to the eDonkey signature, it explains the behaviour…
A second question in this matter: in the firewall, I have defined these two addresses as objects to be blocked, but they still access the network: the messages keep appearing

So Draytek has to answer a question or two …

Posted on

08-Sep-2013

A family member sent a message – by SMS and Skype – that mail bounced. No mention of the reason,
A brief look into the system revealed that just the main process of PMAS was running – no worker processes. So I stopped PMAS – and got a number of error messages – mainly that logicals were not defined.
Next, I looked into the PMAS log files. The first strange thing was that there was a PMAS.LOG-2013-09-04, and a PMAS.LOG – dated 05-Sep-2013. I would expect files PMAS.LOG-2013-09-05, PMAS.LOG-2013-09-06 and PMAS.LOG-2013-09-07, but these were all missing.PMAS.LOG however ended with the last message at 22:26:34.06, a message being quarantined. But after that, it seems no new messages were received!
Looking into PMAS_STARTUP.LOG, that contains all messages also sent to OPCOM (and therefore, be logged in OPERATOR.LOG) revealed why:
5-SEP-2013 23:13:23.51 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 005D (2126D8E0) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,17314
This specific address (62.175.202.16) continues sending messages at a high rate, until
** 7-SEP-2013 08:57:25.13 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 022F (2126B0B5) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,50436
and after that, a number of other addresses took over – it might have been the same source using a anonymiser. These addresse included: 182.18.222.91, 201.240.162.58, 200.37.163.163, 123.16.92.3,
181.67.6.108, 113.172.23.195, and more.
At some point, the main program notices:
** 6-SEP-2013 00:12:25.18 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 9310 connections accepted; 0 workers currently active
This happens when someone tries to block the system for the same reason – as, for example in Jily, but the main process was able to restart a new workerprocess:
** 19-JUL-2013 02:12:24.88 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 4439 connections accepted; 0 workers currently active

** 19-JUL-2013 04:12:24.88 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 4441 connections accepted; 1 worker currently active
Pid Process Name State Connections Serviced
21257C5F PTSMTP 001D idle 2
and at some moments, the maximum of worker-processes (10) is reached, but it never caused a problem:
** 23-JUL-2013 23:05:44.23 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 4891 connections accepted; 10 workers currently active
Pid Process Name State Connections Serviced
21257F2D PTSMTP 0024 idle 226
212530A6 PTSMTP 0025 idle 27
21261FE7 PTSMTP 0026 exiting 1
21257068 PTSMTP 0027 exiting 1
2125FE69 PTSMTP 0028 exiting 1
2126236A PTSMTP 0029 exiting 1
2125D3ED PTSMTP 002A exiting 1
212602EE PTSMTP 002B exiting 1
2125D002 PTSMTP 002C exiting 1
2125F883 PTSMTP 002D exiting 1
since the surplus simply dies out.
But this aabuser had sent so many messages that the last ‘normal’ signal was written early 04-Sep-2013:
** 4-SEP-2013 04:12:25.17 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 8050 connections accepted; 2 workers currently active
Pid Process Name State Connections Serviced
2126DD69 PTSMTP 0055 idle 174
21265CA4 PTSMTP 0056 idle 16
After that, one of the server processes crashed, and a second was never brought into existence:

** 4-SEP-2013 06:12:25.17 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 8057 connections accepted; 1 worker currently active
Pid Process Name State Connections Serviced
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 117.217.5.97,10830

** 4-SEP-2013 06:12:25.17 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 8057 connections accepted; 1 worker currently active
Pid Process Name State Connections Serviced
21265CA4 PTSMTP 0056 idle 18

From that moment on, only one worker process remains – but when that one died, another was started. and when the bomb started, one after the other that was created went down:
** 5-SEP-2013 23:13:23.51 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 005D (2126D8E0) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,17314

** 5-SEP-2013 23:13:34.03 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 005A (2126A8DC) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,22436

** 5-SEP-2013 23:13:43.06 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 005E (212733E4) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,24835

** 5-SEP-2013 23:14:35.74 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 0060 (21272867) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,6114

** 5-SEP-2013 23:14:47.17 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 0061 (2126C1EC) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,37761
until at some moment, none was active:
** 6-SEP-2013 00:11:58.20 **
%PTSMTP-E-WORKERDIED, worker PTSMTP 007A (2126ED0A) terminated unexpectedly
-PTSMTP-I-WORKEREXIT, worker exiting
-PTSMTP-E-SOCKETFAILED, failed to create socket - -SYSTEM-W-DEVALLOC, device already allocated to another user
-PTSMTP-I-WORKERCONN, while processing connection from 62.175.202.16,60929

** 6-SEP-2013 00:12:25.18 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 9310 connections accepted; 0 workers currently active
and it continues. The last statusmessage – that is normally sen every 2 hours – was found to be:
** 8-SEP-2013 14:12:25.19 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 10417 connections accepted; 0 workers currently active
until I stopped the program:
** 8-SEP-2013 16:09:23.24 **
%PTSMTP-I-CTRLEXIT, PTSMTP exiting
-PTSMTP-I-EXITREQUESTED, exit requested by operator

** 8-SEP-2013 16:09:23.24 **
%PTSMTP-I-DBSTATUS, status for configuration PMAS_ROOT:[DATA]PTSMTP.CONF:
Total of 10464 connections accepted; 0 workers currently active
In the end – when I stopped the service, it has ‘processed’ about 2500 message in 3 days ; these are the ones that actually came through. The number of SYSTEM-W-DEVALLOC messages in those days is about 850, and the number of messages that the service limit has been exceed, is about 90.
The real amount is found in the router logging: from the beginning until I stopped the service, the mail filter had to handle over 2400 message – of which over 1100 sent by 62.175.202.16, several every second.
Too much for PMAS to handle.
From a certain point, several other senders kick in but My guess is these are trying this for a long time; and because PMAS had been overloaded and is unable to start new worker processes, these encounter the same problem as other legitimate senders.

In hypewrSpy – on eof the tools in which I check the system performance – there is no real clue on what was going on. I still have to look into the T4 data but I doubt there will some clue.

In retrospect, last Friday I also noted that there was very little mail coming in – either deliverable of blocked by the system (well – the spam filter).

I have informed Process.com of the issue: That PMAS was unable – for some reason – to create a new process, although the system has slots available (the maximum seen is 67 where I have room for 110 processes), and that PMQAS should block any repeated requests over a certain amount from one address, like I have set for WASD; and signal – by email, for instance, that a site tries to block access to ail.
And, of course, the offending address – owned by ono.com in Spain – has been denied access in the router – and I would like to inform ONO.COM if only I found an address. But the site is already mentions a a potentially dangerous one. Probably trying to relay – but even that cannot be determined. The last log is of 4-Sep-2013 – so there hasn’t been an attempt since than – or could not be written?