[[APi]TheMan]

I've been working on writing a script that parses /var/log/system.log to find failed logins over ssh due to bad passwords and illegal users, but what I've found is that my server is too busy and the logs get rotated too fast for this to be reliable.

I thought I would be able to monkey around with syslogd and /etc/syslog.conf to send output for authentication services to another file just for my special usage, but I've learned that this behavior is not handled by syslogd. Through reading the manpages for syslogd and syslog.conf I've learned the basic structure of the configuration file, and I've attempted to add an entry for sending authentication logs to another file but I've found that the information logged by the authpriv facility is not as useful as sshd's log information.

From a failed login attempt over ssh due to a bad password:

As syslogd's authpriv facility would have it:

Nov 20 14:19:06 csucub1 com.apple.SecurityServer: authinternal failed to authenticate user joe for right system.login.tty.

Note: syslogd puts this particular information in a file readable only by root at /var/log/secure.log

Here's sshd's output to system.log, notice the useful information included:

Nov 20 14:19:06 csucub1 sshd[15902]: Failed password for joe from 192.168.1.3 port 51259 ssh2

So, is there any way to change where sshd outputs its logs?

[[APi]TheMan]

I don't even need to make up an example, when I got home from work I checked my powerbook's logs:

[aorth@nacho: ~]$ grep Illegal /var/log/system.log
Nov 20 15:21:43 localhost sshd[4984]: Illegal user patrick from 195.214.208.251
Nov 20 15:21:46 localhost sshd[4988]: Illegal user patrick from 195.214.208.251
Nov 20 15:22:10 localhost sshd[5004]: Illegal user rolo from 195.214.208.251
Nov 20 15:22:14 localhost sshd[5006]: Illegal user iceuser from 195.214.208.251
Nov 20 15:22:16 localhost sshd[5010]: Illegal user horde from 195.214.208.251
Nov 20 15:22:27 localhost sshd[5018]: Illegal user wwwrun from 195.214.208.251
Nov 20 15:22:30 localhost sshd[5020]: Illegal user matt from 195.214.208.251
Nov 20 15:22:33 localhost sshd[5022]: Illegal user test from 195.214.208.251
Nov 20 15:22:36 localhost sshd[5026]: Illegal user test from 195.214.208.251
Nov 20 15:22:39 localhost sshd[5028]: Illegal user test from 195.214.208.251
Nov 20 15:22:42 localhost sshd[5030]: Illegal user test from 195.214.208.251
Nov 20 15:22:45 localhost sshd[5032]: Illegal user www-data from 195.214.208.251
Nov 20 15:22:52 localhost sshd[5038]: Illegal user operator from 195.214.208.251
Nov 20 15:22:55 localhost sshd[5040]: Illegal user adm from 195.214.208.251
Nov 20 15:22:58 localhost sshd[5044]: Illegal user apache from 195.214.208.251
Nov 20 15:23:01 localhost sshd[5046]: Illegal user irc from 195.214.208.251
Nov 20 15:23:05 localhost sshd[5048]: Illegal user irc from 195.214.208.251
Nov 20 15:23:07 localhost sshd[5052]: Illegal user adm from 195.214.208.251
Nov 20 15:23:22 localhost sshd[5062]: Illegal user jane from 195.214.208.251
Nov 20 15:23:25 localhost sshd[5064]: Illegal user pamela from 195.214.208.251
Nov 20 15:23:48 localhost sshd[5094]: Illegal user cosmin from 195.214.208.251
Nov 20 15:26:17 localhost sshd[5206]: Illegal user cip52 from 195.214.208.251
Nov 20 15:26:20 localhost sshd[5208]: Illegal user cip51 from 195.214.208.251
Nov 20 15:26:27 localhost sshd[5215]: Illegal user noc from 195.214.208.251
Nov 20 15:26:48 localhost sshd[5231]: Illegal user webmaster from 195.214.208.251
Nov 20 15:26:51 localhost sshd[5233]: Illegal user data from 195.214.208.251
Nov 20 15:26:54 localhost sshd[5235]: Illegal user user from 195.214.208.251
Nov 20 15:26:57 localhost sshd[5239]: Illegal user user from 195.214.208.251
Nov 20 15:27:00 localhost sshd[5241]: Illegal user user from 195.214.208.251
Nov 20 15:27:04 localhost sshd[5243]: Illegal user web from 195.214.208.251
Nov 20 15:27:06 localhost sshd[5247]: Illegal user web from 195.214.208.251
Nov 20 15:27:09 localhost sshd[5249]: Illegal user oracle from 195.214.208.251
Nov 20 15:27:12 localhost sshd[5251]: Illegal user sybase from 195.214.208.251
Nov 20 15:27:14 localhost sshd[5253]: Illegal user master from 195.214.208.251
Nov 20 15:27:18 localhost sshd[5257]: Illegal user account from 195.214.208.251
Nov 20 15:27:21 localhost sshd[5259]: Illegal user backup from 195.214.208.251
Nov 20 15:27:25 localhost sshd[5261]: Illegal user server from 195.214.208.251
Nov 20 15:27:28 localhost sshd[5266]: Illegal user adam from 195.214.208.251
Nov 20 15:27:31 localhost sshd[5268]: Illegal user alan from 195.214.208.251
Nov 20 15:27:34 localhost sshd[5270]: Illegal user frank from 195.214.208.251
Nov 20 15:27:37 localhost sshd[5274]: Illegal user george from 195.214.208.251
Nov 20 15:27:40 localhost sshd[5276]: Illegal user henry from 195.214.208.251
Nov 20 15:27:43 localhost sshd[5278]: Illegal user john from 195.214.208.251
Nov 20 15:28:06 localhost sshd[5294]: Illegal user test from 195.214.208.251

And then a bunch of these:

[aorth@nacho: ~]$ grep Failed /var/log/system.log
Nov 20 15:21:39 localhost sshd[4982]: Failed password for nobody from 195.214.208.251 port 40321 ssh2
Nov 20 15:21:50 localhost sshd[4990]: Failed password for root from 195.214.208.251 port 40654 ssh2
Nov 20 15:21:54 localhost sshd[4992]: Failed password for root from 195.214.208.251 port 40763 ssh2
Nov 20 15:21:59 localhost sshd[4996]: Failed password for root from 195.214.208.251 port 40877 ssh2
Nov 20 15:22:03 localhost sshd[4998]: Failed password for root from 195.214.208.251 port 40998 ssh2
Nov 20 15:22:06 localhost sshd[5002]: Failed password for root from 195.214.208.251 port 41103 ssh2
Nov 20 15:22:20 localhost sshd[5012]: Failed password for cyrus from 195.214.208.251 port 41483 ssh2
Nov 20 15:22:24 localhost sshd[5014]: Failed password for www from 195.214.208.251 port 41594 ssh2
Nov 20 15:22:49 localhost sshd[5036]: Failed password for mysql from 195.214.208.251 port 42315 ssh2
Nov 20 15:23:12 localhost sshd[5054]: Failed password for root from 195.214.208.251 port 42962 ssh2
...
...
...
Nov 20 15:28:03 localhost sshd[5292]: Failed password for root from 195.214.208.251 port 51644 ssh2

While the possibility of someone getting in is very small (my passwords are fairly strong and root is not even enabled), I am somewhat discomforted. I'm on a dynamic host, and I really don't have any enemies, so this can't be something targetted. Probably just sweeping portscans from some junior high kid in Kiev, sitting around eating bagel bites in his dirty boxers.

This week it's coming from the Ukraine, last week it was from Korea and Colorado... who will try to get in next week?

[utidjian]

Interesting problem...

I fooled around with it for a bit and it is a bit mysterious. I did get it to work (depending on your definittion of work).

1. I created a file called sshes.log in /var/log/

sudo su -
touch /var/log/sshes.log
chmod 0600 /var/log/sshes.log
chown root:admin /var/log/sshes.log

2. Then I created an entry in /etc/syslog.conf ponting to that file:

auth.info /var/log/sshes.log

3. Then I restarted syslogd:

killall -HUP syslogd

4. Then I tested it by opening another terminal and running a tail on the file:

sudo tail -f /var/log/sshes.log

5. While that was running I sshed in from another machine and played around with successful and unsuccessful logins. It logs both.

I actually did quite a few loops of the above before I got it to work. It seems like the syslog facility is a tad buggy. In any case, it works.

Incidentally, do you know why /var/log/secure.log, /var/log/system.log and (now) /var/log/sshes.log should always be root:admin mode 0600? (Can be mode 0640 for system.log).

While your sshd log messages are unsettling it is nothing all that unusual. I have been getting those for months on all my systems that have port 22 open to the internet. At first it was just for root, admin, user and guest but recently the bots have changed their tactics and are looking for default or no passwords on a whole dictionary of userids. If you have multiuser systems so exposed (as do I) you should run John the Ripper or something similar on the shadow file if you can get it. Unfortunately (or fortunately, depending how you look at it) you can't just do:

nidump passwd .

any more on Mac OS X to get the password hashes to run JtR on anymore. So once a user creates a password there is no way to test it to see if it is a good one. On my Linux servers I run JtR on the /etc/shadow file once a month. I lock all accounts that have easily crackable passwords and tell the users to change them.

Your /var/log/system.log files get "rotated" daily (see /etc/daily) and are compressed. The default keeps a weeks worth of /var/log/system.log.N.gz files around. If you want to read them just do:

sudo zcat /var/log/system.log.N.gz | less

where N is 0,1,2...7 and you can pipe it through grep instead of less if you like.

/etc/daily is a really clunky file IMO. It would be far more useful to use a utility like logrotate in Linux. You can get logrotate via fink.

[[APi]TheMan]

Originally posted by utidjian:
2. Then I created an entry in /etc/syslog.conf ponting to that file:

auth.info /var/log/sshes.log

How'd you know to use auth.info? In hindsight I could have inferred that from the fact that *.info is set to write to the system.log, but I wouldn't really have any way of knowing that a "Possible break-in attempt" would be a log status of "info" (more of an error or critical, no?). In any case, thanks!

Originally posted by utidjian:
Unfortunately (or fortunately, depending how you look at it) you can't just do:

nidump passwd .

any more on Mac OS X to get the password hashes to run JtR on anymore. So once a user creates a password there is no way to test it to see if it is a good one. On my Linux servers I run JtR on the /etc/shadow file once a month. I lock all accounts that have easily crackable passwords and tell the users to change them.

True, and for those that hadn't seen how passwords work in OS X, it requires a little bit more digging. Password hashes live in a shadow file in /var/db/shadow/hashes/, in which there are 2 files for each user account. To find which one is a certain user's shadow file:

nireport . /users name generateduid

Those big ugly numbers are the key to each users' shadow file. /var/db/shadow/hashes/<generateduid_from_above> will hold a rather long 104 character hash, which is actually comprised of two separate kinds of hashes of the user's password. The hashes directory, and the files in it, are readable by only root, though, so they're not totally vulnerable, but still accessible.

Originally posted by utidjian:
Your /var/log/system.log files get "rotated" daily (see /etc/daily) and are compressed. The default keeps a weeks worth of /var/log/system.log.N.gz files around.

See, I was trying to figure out the science behind that, actually. My logs aren't rotating daily on my Mac OS X server:

Code:
[aorth@csucub1: ~]$ head -1 /var/log/system.log
Nov 20 03:15:02 csucub1 syslogd: restart

[aorth@csucub1: ~]$ tail -1 /var/log/system.log
Nov 21 03:06:38 csucub1 sshd[20266]: Accepted publickey for aorth from 67.117.26.203 port 64887 ssh2

Originally posted by utidjian:
/etc/daily is a really clunky file IMO. It would be far more useful to use a utility like logrotate in Linux. You can get logrotate via fink.

I should check it out. It will be nice to log auth.info to a separate file that I can play with and not have to dance around with temp files, appending lines, copying/rotating scripts manually, etc.. Thanks for the tip, man.

[Arkham_c]

Just FYI, you can use "gzcat" to cat all the .zg-compressed files, just like "cat" will do on the uncompressed files. So doing:

Code:

gzcat /var/log/system.*gz | grep -i illegal

becomes pretty trivial. I don't think this necessarily addresses your root issue, but it does help you get info out of the logs even after they've been rotated.

[[APi]TheMan]

Originally posted by Arkham_c:
Just FYI, you can use "gzcat" to cat all the .zg-compressed files, just like "cat" will do on the uncompressed files. So doing:

gzcat /var/log/system.*gz | grep -i illegal

Interesting, I was just noticing that, on my Gentoo box, my logs are bzipped after they've been rotated and archived, and not only do I have a bzcat, I have a bzgrep!

[utidjian]

Originally posted by [APi]TheMan:
Interesting, I was just noticing that, on my Gentoo box, my logs are bzipped after they've been rotated and archived, and not only do I have a bzcat, I have a bzgrep!

On my Fedora Core 1, 2 and 3 systems 'less somefile.[gz,Z,bz2...etc]' automatically handles the compressed formats. Damn handy.

[utidjian]

Originally posted by [APi]TheMan:
How'd you know to use auth.info?

I didn't. I figured it out by reading /etc/syslog.conf, the manpage and experiment. In a typical /etc/syslog.conf file there will be a line like this:

*.notice;*.info;authpriv,remoteauth,ftp,install.no ne;kern.debug;mail.crit /var/log/system.log

which means, roughly parsed to english:

Send everything of priority 'notice' to the file /var/log/system.log.

Send everything of priority 'info' to the file /var/log/system.log.

Send nothing ('none') from authpriv, remoteauth, ftp, and install to the file /var/log/system.log. These get handled separately with their own log files.
authpriv,remoteauth,ftp,install.none; is shorthand for authpriv.none;remoteauth.none;ftp.none;install.non e;

Send everything from the kernel of priority 'debug' to the file /var/log/system.log.

Send everything from mail of priority 'crit' to the file /var/log/system.log.

Basically:

facility.priority /var/log/file.log

Wildcards '*' are allowed so something like:

*.* /var/log/everything.log

Would log everything at any level to /var/log/everything.log.

For more info on all this see the manpages and /usr/include/sys/syslog.h.

In hindsight I could have inferred that from the fact that *.info is set to write to the system.log, but I wouldn't really have any way of knowing that a "Possible break-in attempt" would be a log status of "info" (more of an error or critical, no?).

Well info is just one 'priority level'... there are many others (see syslog.h). It all depends on how sshd makes those calls to syslog. The 'info' will send everything that is encoded as "informational"; this includes successful and unsuccessful login attempts. I like the fact that they appear together in the same logfile because it is pretty common to see one or two botched attempts from the same user together with a successful attempt. It is also not unusual to see several unsuccessful attempts from a regular user all in a row... sometimes as many as 4 to 6 attempts. Usually this is because they forgot their password or they are typing in the wrong one for that particular system/account.

It is quite common in larger installations to have ALL machines forward certain logs to a central logserver. The logserver is a good use for an old slow machine that is no longer useful as a workstation or server. The line in /etc/syslog.conf on each workstation and server would be something like this:

*.info;mail,authpriv,cron.none @192.168.1.99

Which will forward every log entry of priority info except mail, authpriv and cron to the logserver with IP address 192.168.1.99. The logserver would be so locked down that it has no ports open other than the one for syslog. No user accounts. Nothing.

In any case... you can create as many logfiles as you want and name them whatever you want and have logging data sent to them at whatever priority level. What actually gets logged is determined by how the syslog calls are written in the program or daemon you are interested in. Many daemons have the ability to turn on extra logging which is useful for debugging. sshd in Mac OS X has the -d N option (where N = 1, 2, or 3) for different levels of debug messages snt to the system log. However, if you use the -d option it severely limits sshd to one connection and it will not background. It is purely for debugging purposes. The other main limitation is how much diskspace one has available for /var/log/.

Red Hat and Fedora Core Linux systems come with a handy program called 'logwatch', configured and enabled by default. Each day it emails me a nice summary of important system information distilled from the log files. Stuff like disk usage, ALL ssh login attempts, summaries on cronjobs, etc... From the manpage:

DESCRIPTION
LogWatch is a customizable, pluggable log-monitoring system. It will go through
your logs for a given period of time and make a report in the areas that you wish
with the detail that you wish. Easy to use - works right out of the package on
almost all systems.

It doesn't seem to be available for Mac OS X yet via fink.


Thanks for the info on shadow passwords in Mac OS X.