Quering /var/spool/postfix/plesk/passwd.db in order to relay from unauthorized source

[JoswaldM]

I''ve been receiving NDR from messages that we didnt' sent and I started to check the message error and the maillog in order to find what's happening.

First, I see a lot of requests for relaying but most of them with error because we have the relay only for authenticated users.

Second and the messages the really worried me:

Part 1:
May 17 04:04:15 u16198736 postfix/smtpd[6672]: connect from static-70-107-235-56.ny325.east.verizon.net[70.107.235.56]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: listen=6, status=5, dbpath='/var/spool/postfix/plesk/passwd.db', chroot=0, unprivileged=1
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: privileges set to (89:89) (effective 89:89)
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: main cycle started
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: new client (fd=10) registered
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: some read activity on client 10
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=0]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 7)=7
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=1]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=2]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 7)=7
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=3]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=4]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 4)=4
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=5]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=6]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=7]
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: Invalid mail address 'systest@'
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: some write activity on client 10
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: attempt to write(10, &buf, 4)
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: client 10 processed
May 17 04:04:15 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:15 u16198736 postfix/smtpd[6672]: warning: static-70-107-235-56.ny325.east.verizon.net[70.107.235.56]: SASL LOGIN authentication failed: authentication failure
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: new client (fd=10) registered
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: some read activity on client 10
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=0]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 7)=7
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=1]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=2]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 8)=8
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=3]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=4]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 4)=4
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=5]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=6]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=7]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: Invalid mail address 'systest@'
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: some write activity on client 10
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: attempt to write(10, &buf, 4)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: client 10 processed
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 postfix/smtpd[6672]: warning: static-70-107-235-56.ny325.east.verizon.net[70.107.235.56]: SASL LOGIN authentication failed: authentication failure
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: new client (fd=10) registered
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: some read activity on client 10
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=0]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 7)=7
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=1]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=2]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 10)=10
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=3]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=4]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 4)=4
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=5]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: read(10, &buf, 2)=2
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=6]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: processing client data chunk [state=7]
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: Invalid mail address 'systest@'
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: activity on 1 channel(s)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: some write activity on client 10
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: attempt to write(10, &buf, 4)
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: client 10 processed
May 17 04:04:16 u16198736 plesk_saslauthd[6676]: main cycle iteration
May 17 04:04:16 u16198736 postfix/smtpd[6672]: warning: static-70-107-235-56.ny325.east.verizon.net[70.107.235.56]: SASL LOGIN authentication failed: authentication failure
May 17 04:04:16 u16198736 postfix/smtpd[6672]: disconnect from static-70-107-235-56.ny325.east.verizon.net[70.107.235.56]
May 17 04:04:46 u16198736 plesk_saslauthd[6676]: activity on 0 channel(s)
May 17 04:04:46 u16198736 plesk_saslauthd[6676]: select timeout, exiting

Part2: (from other source)
May 17 08:43:42 u16198736 postfix/smtpd[31308]: connect from 125-224-225-100.dynamic.hinet.net[125.224.225.100]
May 17 08:43:49 u16198736 postfix/smtpd[31308]: 4979AD4A: client=125-224-225-100.dynamic.hinet.net[125.224.225.100], sasl_method=LOGIN, sasl_username=info@(removed domain for private purposes)
May 17 08:43:51 u16198736 postfix/cleanup[31313]: 4979AD4A: message-id=<84CD83B5.6E6A6E34@(removed domain for private purposes)>
May 17 08:43:51 u16198736 /usr/lib64/plesk-9.0/psa-pc-remote[1673]: handlers_stderr: SKIP
May 17 08:43:51 u16198736 /usr/lib64/plesk-9.0/psa-pc-remote[1673]: SKIP during call 'check-quota' handler
May 17 08:43:51 u16198736 postfix/qmgr[17842]: 4979AD4A: from=<info@(removed domain for private purposes)>, size=936, nrcpt=1 (queue active)
May 17 08:43:51 u16198736 postfix/smtpd[31308]: disconnect from 125-224-225-100.dynamic.hinet.net[125.224.225.100]
May 17 08:43:52 u16198736 postfix/smtp[31316]: 4979AD4A: to=<crzywvgrl09@cherrytap.com>, relay=mailgw01.fubar.com[66.109.102.243]:25, delay=4.4, delays=3.3/0/0.88/0.25, dsn=4.1.1, status=deferred (host mailgw01.fubar.com[66.109.102.243] said: 450 4.1.1 <crzywvgrl09@cherrytap.com>: Recipient address rejected: undeliverable address: unknown user: "crzywvgrl09" (in reply to RCPT TO command))
May 17 08:47:11 u16198736 postfix/anvil[31312]: statistics: max connection rate 1/60s for (smtp:125.224.225.100) at May 17 08:43:42
May 17 08:47:11 u16198736 postfix/anvil[31312]: statistics: max connection count 1 for (smtp:125.224.225.100) at May 17 08:43:42

I changed the password to the user in order to avoid that was spread on the internet by mistake, but I'm not sure if there is a way they can query effectively the passwd.db file for postfix and get access again to an account for relaying. I can't close relay because I have users outside my network that needs to send emails.

I hope you can help me.

Jos.

 

[Faris Raouf]

There is nothing unusual going on. In Part 1 we see authentication failure. This is normal. The bad guys try and try and try to guess passwords every minute of every day. So you'll see this in your logs all the time. In fact there are several botnets doing this constantly from millions of different IPs, as well as individuals using compromised servers, public wifi and so on to try to do the same thing.

In Part 2 we see authentication passed and spam sent.
The user may have had a weak password, or allowed a Trojan on their system, or used the same password/username on another system that was compromised. Changing the password will have solved the problem unless the user still has a virus on their system and the bad guys get the new password.

There is no way for the bad guys to access the password file unless they already own your server. And if that was the case, there would be much more spam going out and you would be unable to stop it, and all your sites would be infected etc.