repeated error in maillog file

RW-Taylor · 07-28-2014, 11:08 AM

Just got a new job, and I'm going through their servers, getting a feel for things.

I noticed that on the syslog server, in the file /var/log/maillog every 10 minutes (to the second) the following error shows up.

Code:

Jul 28 10:49:35 rwsyslog sendmail[21659]: s6SFnZ1I021659: localhost.localdomain [127.0.0.1] did not issue MAIL/EXPN/VRFY/ETRN during connection to MTA
Jul 28 10:59:35 rwsyslog sendmail[21696]: s6SFxZWA021696: localhost.localdomain [127.0.0.1] did not issue MAIL/EXPN/VRFY/ETRN during connection to MTA

Any clue on how I can find out what process is trying to use sendmail every 10 minutes?

I have tried using tcpdump to pull a packet capture, but it didn't really show me anything useful.

Any help would be greatly appreciated

Thanks!

Taylor

unSpawn · 07-28-2014, 12:57 PM

Quote:

Originally Posted by RW-Taylor

Just got a new job,

Congrats.

Quote:

Originally Posted by RW-Taylor

and I'm going through their servers, getting a feel for things.

Good, good...

Quote:

Originally Posted by RW-Taylor

Any clue on how I can find out what process is trying to use sendmail every 10 minutes?

Every ten minutes? I'd try cron jobs (/etc/cron.*/, /etc/crontab, /var/spool/cron/) first...

Quote:

Originally Posted by RW-Taylor

I have tried using tcpdump to pull a packet capture, but it didn't really show me anything useful.

Packet capture on its own won't as it doesn't have a concept of process Ids and such but together with audit rules and log correlation you prolly could.

RW-Taylor · 07-28-2014, 01:11 PM

whoops! Neglected to mention that I did check cron jobs using

Code:

for user in $(cut -f1 -d: /etc/passwd); do echo $user; crontab -u $user -l; done

and the only cron job listed

Code:

#00,20,40 * * * * /usr/local/scripts/runvpndur.sh

is run as root, and is a script that dumps info from the syslog about our vpnusers.

I checked the script, and it doesn't use sendmail at all...

unSpawn · 07-28-2014, 01:22 PM

What OS and what release? Does it come with the audit service? Does it have psacct? Iptables? Or else: are you allowed to install or modify software?

RW-Taylor · 07-28-2014, 01:29 PM

cat/etc/*-release shows
CentOS release 5.10 (Final)

I don't know if it comes with audit service. psacct appears to be installed. It does have Iptables, but there aren't any chains setup.

I can install and modify software.

unSpawn · 07-30-2014, 02:44 AM

Sorry for late reply.

In essence you would want a rule something like this:

Code:

-A INPUT -i lo -d 127.0.0.0/255.255.0.0 --ctstate NEW -m tcp --dport 25 -m owner -j LOG --log-prefix "SMTP_lo_in " --log-uid

but when I tried to add it I ended up with something like this:

Code:

awk -F':' '{print $1}' /etc/passwd | egrep -vie "(shutdown)" | while read _OWNER; do iptables -A OUTPUT -o lo -m conntrack \
--ctstate NEW -m owner --uid-owner ${_OWNER} -j LOG --log-prefix "${_OWNER_}SMTP_lo_in " --log-uid; done

That's a bit overkill but then again you wouldn't want to have this running for more than say two hours anyway before checking /var/log/messages, right?

RW-Taylor · 07-30-2014, 08:55 AM

I tried that command, and the results that are output to the /var/log/messages file every 10 minutes are

Code:

Jul 30 08:39:39 rwsyslog kernel: SMTP_lo_in IN= OUT=lo SRC=127.0.0.1 DST=127.0.0.1 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=26299 DF PROTO=TCP SPT=41770 DPT=25 WINDOW=32792 RES=0x00 SYN URGP=0 UID=0

If i'm not mistaken, this shows us the user that is running the process has UID 0 (which is root), and the PID of the process was 26299 (??? I'm not sure the ID is the PID)

at 8:49:39, the /var/log/messages file had this logged to it

Code:

Jul 30 08:49:39 rwsyslog kernel: SMTP_lo_in IN= OUT=lo SRC=127.0.0.1 DST=127.0.0.1 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=6570 DF PROTO=TCP SPT=41783 DPT=25 WINDOW=32792 RES=0x00 SYN URGP=0 UID=0

I tried running

Code:

top -b -d 1 -n 10 >> top-file.txt

just before 8:49:39, to capture the next run in top, and here is it's output

Code:

top - 08:49:39 up 136 days, 21:28,  1 user,  load average: 0.15, 0.04, 0.01
Tasks:  93 total,   1 running,  92 sleeping,   0 stopped,   0 zombie
Cpu(s):  1.0%us,  1.0%sy,  0.0%ni, 98.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:    254960k total,   231492k used,    23468k free,     8404k buffers
Swap:   524280k total,       72k used,   524208k free,    74632k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
32280 root      15   0  2316 1008  808 R  1.0  0.4   0:00.07 top
    1 root      15   0  2176  600  520 S  0.0  0.2   0:01.38 init
    2 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 migration/0
    3 root      34  19     0    0    0 S  0.0  0.0   0:00.77 ksoftirqd/0
    4 root      10  -5     0    0    0 S  0.0  0.0   0:02.15 events/0
    5 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 khelper
    6 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 kthread
    9 root      10  -5     0    0    0 S  0.0  0.0   0:43.91 kblockd/0
   10 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kacpid
  170 root      18  -5     0    0    0 S  0.0  0.0   0:00.00 cqueue/0
  173 root      18  -5     0    0    0 S  0.0  0.0   0:00.00 khubd
  175 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 kseriod
  243 root      24   0     0    0    0 S  0.0  0.0   0:00.01 khungtaskd
  244 root      15   0     0    0    0 S  0.0  0.0   3:01.80 pdflush
  245 root      15   0     0    0    0 S  0.0  0.0   4:14.73 pdflush
  246 root      10  -5     0    0    0 S  0.0  0.0   0:15.78 kswapd0
  247 root      18  -5     0    0    0 S  0.0  0.0   0:00.00 aio/0
  465 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 kpsmoused
  496 root      10  -5     0    0    0 S  0.0  0.0   0:00.35 mpt_poll_0
  497 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 mpt/0
  498 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_0
  501 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kstriped
  510 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 ksnapd
  521 root      10  -5     0    0    0 S  0.0  0.0  29:04.77 kjournald
  546 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 kauditd
  579 root      16  -4  2412  736  408 S  0.0  0.3   0:00.60 udevd
 1241 root      12  -5     0    0    0 S  0.0  0.0   0:00.00 ata/0
 1242 root      12  -5     0    0    0 S  0.0  0.0   0:00.00 ata_aux
 1752 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kmpathd/0
 1753 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kmpath_handlerd
 1772 root      10  -5     0    0    0 S  0.0  0.0   0:00.10 kjournald
 2375 root      15   0 37068 3316 2680 S  0.0  1.3  31:30.63 vmtoolsd
 2489 root      17  -5     0    0    0 S  0.0  0.0   0:00.00 iscsi_eh
 2523 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 cnic_wq
 2526 root       5 -20     0    0    0 S  0.0  0.0   0:00.00 bnx2i_thread/0
 2539 root      19  -5     0    0    0 S  0.0  0.0   0:00.00 ib_addr
 2545 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 ib_mcast
 2546 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 ib_inform
 2547 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 local_sa
 2552 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 iw_cm_wq
 2554 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 ib_cm/0
 2557 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 rdma_cm
 2573 root      10 -10 22520  21m 1732 S  0.0  8.8   0:00.02 iscsiuio
 2578 root      15   0  2372  464  392 S  0.0  0.2   0:07.72 iscsid
 2579 root       5 -10  2836 2832 1900 S  0.0  1.1   0:02.61 iscsid
 2816 root      17   0  1832  588  496 S  0.0  0.2   7:44.94 syslogd
 2819 root      18   0  1780  420  352 S  0.0  0.2   0:00.00 klogd
 2873 rpc       20   0  1928  544  448 S  0.0  0.2   0:00.00 portmap
 2907 root      12  -5     0    0    0 S  0.0  0.0   0:00.00 rpciod/0
 2913 rpcuser   25   0  1980  744  636 S  0.0  0.3   0:00.01 rpc.statd
 2949 root      25   0  2328  480  316 S  0.0  0.2   0:00.00 rpc.idmapd
 2980 dbus      15   0  2968  976  728 S  0.0  0.4   0:16.95 dbus-daemon
 2993 root      22   0  2272  772  672 S  0.0  0.3   0:00.00 hcid
 3024 root      15 -10     0    0    0 S  0.0  0.0   0:00.00 krfcommd
 3067 root      25   0 12848 1332  636 S  0.0  0.5   0:15.85 pcscd
 3081 root      18   0  1776  532  452 S  0.0  0.2   0:00.00 acpid
 3102 root      24   0  2024  456  376 S  0.0  0.2   0:00.00 hidd
 3141 root      24   0 30464 1412 1088 S  0.0  0.6   0:24.63 automount
 3162 root      18   0 10272 2328 1692 S  0.0  0.9   0:00.03 cupsd
 3178 root      15   0  7328 1060  644 S  0.0  0.4   0:02.48 sshd
 3201 ntp       15   0  4424 4420 3432 S  0.0  1.7   0:09.15 ntpd
 3224 root      15   0  9380 1888  808 S  0.0  0.7   0:11.15 sendmail
 3232 smmsp     18   0  8292 1520  648 S  0.0  0.6   0:00.46 sendmail
 3246 root      15   0  2016  484  408 S  0.0  0.2   0:00.02 gpm
 3259 root      18   0  5392 1104  572 S  0.0  0.4   0:01.02 crond
 3287 root      18   0  2376  436  316 S  0.0  0.2   0:00.08 atd
 3313 avahi     15   0  2708 1292 1108 S  0.0  0.5   0:01.37 avahi-daemon
 3314 avahi     25   0  2708  440  296 S  0.0  0.2   0:00.00 avahi-daemon
 3327 haldaemo  15   0  6536 4604 1696 S  0.0  1.8   6:27.64 hald
 3328 root      25   0  3280 1092  932 S  0.0  0.4   0:00.01 hald-runner
 3335 haldaemo  17   0  2124  816  724 S  0.0  0.3   0:00.00 hald-addon-acpi
 3341 haldaemo  15   0  2124  816  720 S  0.0  0.3   0:00.00 hald-addon-keyb
 3350 root      15   0  2076  676  592 S  0.0  0.3 191:42.48 hald-addon-stor
 3708 root      15   0  4284 2584 1520 S  0.0  1.0   0:02.03 caagentd
 3710 root      34  19 29604  13m 2216 S  0.0  5.5   0:30.84 yum-updatesd
 3712 root      34  19  2676 1180  988 S  0.0  0.5   0:07.55 gam_server
 3830 root      15   0 15016 1240  752 S  0.0  0.5   0:29.64 wrapper-linux-x
 3832 root      24   0  312m  87m  15m S  0.0 35.1 406:04.88 java
 3909 root      18   0  5760  568  280 S  0.0  0.2   0:00.00 smartd
 3913 root      18   0  1764  468  404 S  0.0  0.2   0:00.00 mingetty
 3914 root      18   0  1764  464  404 S  0.0  0.2   0:00.00 mingetty
 3915 root      19   0  1764  460  404 S  0.0  0.2   0:00.00 mingetty
 3916 root      20   0  1764  464  404 S  0.0  0.2   0:00.00 mingetty
 3917 root      21   0  1764  464  404 S  0.0  0.2   0:00.00 mingetty
 4554 root      15   0  1764  468  404 S  0.0  0.2   0:00.00 mingetty
20958 root      23   0 10184 3280 2700 S  0.0  1.3   0:01.17 sshd
20960 admin     15   0 10340 1748 1140 S  0.0  0.7   0:12.99 sshd
20961 admin     15   0  4784 1520 1228 S  0.0  0.6   0:00.09 bash
21050 root      16   0 10184 2928 2356 S  0.0  1.1   0:01.15 sshd
21052 admin     15   0 10340 1816 1176 S  0.0  0.7   0:01.61 sshd
21053 admin     15   0  6772 1664 1216 S  0.0  0.7   0:00.06 sftp-server
21072 root      16   0  5032 1316 1056 S  0.0  0.5   0:00.00 su
21075 root      16   0  4784 1540 1240 S  0.0  0.6   0:00.65 bash

unSpawn · 07-31-2014, 01:47 AM

You now know it's a root-owned process. Two approaches I can think of now: 0) have a go at this (the logging socket calls part) or 1) stop the sendmail service (on the loopback interface) and see if something errors out (or not, its just a hunch).

RW-Taylor · 07-31-2014, 09:33 AM

unSpawn - I tried option 1 first, and unfortunately stopping sendmail (by running service sendmail stop) didn't generate any errors when the sendmails would have ran. I let it sit for about 20 minutes and then checked the logs.

I then started the sendmail service, and tried option 0. I skipped straight ahead to the socket calls logging part of the page you linked. I ran the following command (I changed the architecture to b64 because we are running 64bit)

Code:

awk '/^#define.SYS_/ {print "-a entry,always -F arch=b64 -S socketcall -F auid=0 -F a0="$3" -k "$2}' /usr/src/kernels/$(uname -r)-$(uname -m)/include/linux/net.h | while read LINE; do auditctl $LINE; done

and it returned this error

Code:

awk: cmd. line:1: fatal: cannot open file `/usr/src/kernels/2.6.18-371.6.1.el5-i686/include/linux/net.h' for reading (No such file or directory)

I will admit, I am not very familiar with awk. is it possible that my net.h is in a different location because I am running 64 bit?

Thanks in advance for your help, it is MOST appreciated!

Taylor

hua · 08-01-2014, 11:27 AM

Maybe you can use lsof -i to identify the process which is initiating a connection on the SMTP port. You can use various outputs or grep for the important data:

Quote:

lsof -i | grep -i smtp
lsof -i -P -n | grep ":25"
lsof -i -P -n -r 2 | grep ":25"

You should see a connection and the related process which initiated the connection.

Hope this helps.

frndrfoe · 08-01-2014, 12:46 PM

It looks like you have something like Nagios checking to see if SMTP is responding.

RW-Taylor · 08-01-2014, 01:33 PM

Unfortunately Nagios and Hyperic (the two systems we use for monitoring) aren't monitoring this server. That was a good thought though!

I ran "lsof -i -r 1 | grep -i smtp" at the top of a ten minute mark and this is what it returned, over and over again with no variation.

Code:

sendmail   5581    root    4u  IPv4 13312108      0t0  TCP localhost.localdomain:smtp (LISTEN)

Thoughts?

unSpawn · 08-02-2014, 12:30 AM

Quote:

Originally Posted by RW-Taylor

(..) is it possible that my net.h is in a different location because I am running 64 bit?

No, it's because you don't have your kernel source package installed.

RW-Taylor · 08-06-2014, 12:46 PM

I installed the kernel source package, and ran the code from option 0 again. This resulted in the following rules being added to my auditctl list

Code:

LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=1 (0x1) key=SYS_SOCKET syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=2 (0x2) key=SYS_BIND syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=3 (0x3) key=SYS_CONNECT syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=4 (0x4) key=SYS_LISTEN syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=5 (0x5) key=SYS_ACCEPT syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=6 (0x6) key=SYS_GETSOCKNAME syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=7 (0x7) key=SYS_GETPEERNAME syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=8 (0x8) key=SYS_SOCKETPAIR syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=9 (0x9) key=SYS_SEND syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=10 (0xa) key=SYS_RECV syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=11 (0xb) key=SYS_SENDTO syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=12 (0xc) key=SYS_RECVFROM syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=13 (0xd) key=SYS_SHUTDOWN syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=14 (0xe) key=SYS_SETSOCKOPT syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=15 (0xf) key=SYS_GETSOCKOPT syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=16 (0x10) key=SYS_SENDMSG syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=17 (0x11) key=SYS_RECVMSG syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=18 (0x12) key=SYS_ACCEPT4 syscall=socketcall
LIST_RULES: entry,always arch=1073741827 (0x40000003) auid=0 a0=19 (0x13) key=SYS_RECVMMSG syscall=socketcall

unfortunately, nothing is being logged to /var/log/audit/audit.log, it hasn't been touched since October of 2009.

I checked my /etc/audit/audit.conf and verified that /var/log/audit/audit.log is infact where the audit service
dumps it's logs...

Any thoughts?

Thanks again for all your help folks!