freebsd security - Feb 2012 - periodic security run output gives false positives after 1 year

Hi,

I see it many times before, but never take a time to post about it.

Scrips in /etc/periodic are grepping logs for yesterday date, but 
without specifying year (because some logs do not have year logged).

This results in false positive alerts in security e-mails from our 
lightly loaded servers, where logs are not enough rotated.

For example /var/log/auth.log is 62KB (838 lines) and contains entries 
for almost 2 years.

Today I get following alert:

Feb 15 22:36:03 XXX sshd[89758]: Invalid user t1na from xxx.xxx.xxx.xxx
Feb 15 22:50:56 XXX sshd[89850]: Invalid user medina from xxx.xxx.xxx.xxx
Feb 15 22:50:57 XXX sshd[89852]: Invalid user student from xxx.xxx.xxx.xxx
Feb 15 22:50:58 XXX sshd[89854]: Invalid user student from xxx.xxx.xxx.xxx

(hostname and IP are replaced by X)

But looking in to auth.log I found zero entries from yesterday - Feb 15 
entries were logged 1 year ago!

So I propose to set all daemons / syslog to log year too (as %Y) and 
change  yesterday=`date -v-1d "+%b %e "`  to yesterday=`date -v-1d
"+%b
%e %Y"` in periodic scripts.

The affected scripts are:
460.status-mail-rejects
470.status-named
800.loginfail
900.tcpwrap

Maybe some others, I did just a quick grep -rsn 'date -v-1d' 
/etc/periodic and I don't know the logic used in other script to get 
yesterday messages.

What do you think about it?

Miroslav Lachman

On Thu, Feb 16, 2012 at 06:04:34PM +0100, Miroslav Lachman
wrote:
> Hi,
> 
> I see it many times before, but never take a time to post about it.
> 
> Scrips in /etc/periodic are grepping logs for yesterday date, but 
> without specifying year (because some logs do not have year logged).
> 
> This results in false positive alerts in security e-mails from our 
> lightly loaded servers, where logs are not enough rotated.
> 
> For example /var/log/auth.log is 62KB (838 lines) and contains entries 
> for almost 2 years.
> 
> Today I get following alert:
> 
> Feb 15 22:36:03 XXX sshd[89758]: Invalid user t1na from xxx.xxx.xxx.xxx
> Feb 15 22:50:56 XXX sshd[89850]: Invalid user medina from xxx.xxx.xxx.xxx
> Feb 15 22:50:57 XXX sshd[89852]: Invalid user student from xxx.xxx.xxx.xxx
> Feb 15 22:50:58 XXX sshd[89854]: Invalid user student from xxx.xxx.xxx.xxx
> 
> (hostname and IP are replaced by X)
> 
> But looking in to auth.log I found zero entries from yesterday - Feb 15 
> entries were logged 1 year ago!
> 
> So I propose to set all daemons / syslog to log year too (as %Y) and 
> change  yesterday=`date -v-1d "+%b %e "`  to yesterday=`date
-v-1d "+%b
> %e %Y"` in periodic scripts.
> 
> The affected scripts are:
> 460.status-mail-rejects
> 470.status-named
> 800.loginfail
> 900.tcpwrap
> 
> Maybe some others, I did just a quick grep -rsn 'date -v-1d' 
> /etc/periodic and I don't know the logic used in other script to get 
> yesterday messages.
> 
> What do you think about it?
> 
Rotating the appropriate logs daily/weekly/monthly/whatever will silence
these false alarms.

Glen

2012/2/16 Miroslav Lachman <000.fbsd@quip.cz>:
> Hi,
>
> I see it many times before, but never take a time to post about it.
>
> Scrips in /etc/periodic are grepping logs for yesterday date, but without
> specifying year (because some logs do not have year logged).
>
> This results in false positive alerts in security e-mails from our lightly
> loaded servers, where logs are not enough rotated.
>
> For example /var/log/auth.log is 62KB (838 lines) and contains entries for
> almost 2 years.
>
> Today I get following alert:
>
> Feb 15 22:36:03 XXX sshd[89758]: Invalid user t1na from xxx.xxx.xxx.xxx
> Feb 15 22:50:56 XXX sshd[89850]: Invalid user medina from xxx.xxx.xxx.xxx
> Feb 15 22:50:57 XXX sshd[89852]: Invalid user student from xxx.xxx.xxx.xxx
> Feb 15 22:50:58 XXX sshd[89854]: Invalid user student from xxx.xxx.xxx.xxx
>
> (hostname and IP are replaced by X)
>
> But looking in to auth.log I found zero entries from yesterday - Feb 15
> entries were logged 1 year ago!
>
> So I propose to set all daemons / syslog to log year too (as %Y) and change
> ?yesterday=`date -v-1d "+%b %e "` ?to yesterday=`date -v-1d
"+%b %e %Y"` in
> periodic scripts.
>
> The affected scripts are:
> 460.status-mail-rejects
> 470.status-named
> 800.loginfail
> 900.tcpwrap
>
> Maybe some others, I did just a quick grep -rsn 'date -v-1d'
/etc/periodic
> and I don't know the logic used in other script to get yesterday
messages.
>
> What do you think about it?
>
This is how the traditional BSD syslog was designed (and standardized
by RFC 3164). It has timestamp of fixed format: "Mmm dd hh:mm:ss".

In IETF this RFC is marked obsolete and replaced with RFC 5424 with
different timestamp format in ISO 8601 form. FreeBSD doesn't implement
5424 yet. Almost complete implementation was done in NetBSD in that
regard in 2008. NetBSD before RFC 5424 changes has had pretty similar
syslogd source, so if one could analyze and port that changes to FreeBSD,
that would be pretty nice.

-- 
wbr,
pluknet

I re-add list to CC.

Gregory Orange wrote:
> Hi Miroslav,
> I don't know if this message really contributes anything to the list,
so
> I'll email you directly.
>
> On 17/02/12 01:04, Miroslav Lachman wrote:
>> I see it many times before, but never take a time to post about it.
>
> Well, thank you for posting it. I'm fairly new to BSD admin (GNU/Linux
> for a few years prior), and generally to being the main person
> responsible for security.
I am really glad to see that my post helped to somebody.
>> But looking in to auth.log I found zero entries from yesterday - Feb 15
>> entries were logged 1 year ago!
>
> We've been concerned by some auth.log entries for a week or two, and
> only after reading your message and taking a closer look at the context
> of the logs did I think of that possibility. It's exactly my issue!
Be aware that adding shorter time (or lower file size) for log rotation 
is not enough. Script 800.loginfail is reading all available rotated 
compressed logs. So even if you will rotate more often, you will get 
false positive alerts if some 1 year old entries are stored on disk in 
/var/log/auth.log.X.bz2 files.

Default settings in newsyslog.conf is

/var/log/auth.log         600  7     500  *     JC

This means 7 old compressed archives taken after reaching 500kB in size 
of the original log. So it can contains more than 10 years of history on 
our mentioned server.

Until FreeBSD will log dates in format with year, you must do something 
to be sure that none of the files in /var/log stored entries over 364 days.

Cheers,
Miroslav Lachman

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 02/16/2012 08:08 PM, Sergey Kandaurov wrote:
> 5424 yet. Almost complete implementation was done in NetBSD in
> that regard in 2008. NetBSD before RFC 5424 changes has had pretty
> similar syslogd source, so if one could analyze and port that
> changes to FreeBSD, that would be pretty nice.
I implemented this and if anyone is interested I would be glad to help
with it. So far I just did not find the time to continue development
or even a FreeBSD port on my own (finishing university, looking for a
job, etc). -- The code is in NetBSD-Current and my own development
repository is now online at https://github.com/mschuett/nbsd-syslog

With regard to porting the biggest difference between systems is the
libevent library, which is included in NetBSD and used in the syslogd(8).

The main "problem" with the IETF/NetBSD syslogd(8) is that it does not
only change the message/protocol format, but at the same time implements
TLS communication and digital signatures. -- In combination these
functions really add size and complexity to the code.

To improve things I wonder if syslogd(8) could be restructured into a
plugin-based architecture. That might keep the different logging targets
(files, console, UDP, TLS) and optional features (new/old format,
signatures) separate and simpler. Of course only if it is simple enough
not to add yet another layer of overhead and complexity.

- -- 
Martin Sch?tte
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk8+Sp0ACgkQrb26LrIR2NllIACg7BieDyiVUabLww4n06vehhPe
JjoAoJAq9zAejj0BynH6mP+RBlearIdL
=xV69
-----END PGP SIGNATURE-----

Sergey Kandaurov wrote:
> In IETF this RFC is marked obsolete and replaced with RFC 5424 with
> different timestamp format in ISO 8601 form. FreeBSD doesn't implement
> 5424 yet. Almost complete implementation was done in NetBSD in that
> regard in 2008. NetBSD before RFC 5424 changes has had pretty similar
> syslogd source, so if one could analyze and port that changes to FreeBSD,
> that would be pretty nice.
Problem with that would be backwards compatibility, and it's not IMO
worth breaking everyone's syslog parsing scripts to fix an issue that
really isn't due to the date format as much as it is to log rotation.

That's not to say that security scripts don't need to parse archived
logs, just that they should perhaps check the date stamp of the archive
files before parsing.

Have to admit we don't use FreeBSD (or any other OS's) log rotation or
log-related periodic scripts.  Would love to submit replacements though.
Our logic is a bit different:

  * rotating current log files, to /var/log/$log.$i only when they grow
    larger than 100MB,

  * checking log file size hourly,

  * rotating all logs regardless of size only at the end of the month, to
    a compressed file with the date stamp as part of the filename,

  * maintaining monthly archived log files in a dedicated subdirectory
    (/var/log/logarchive),

  * writing each syslog facility to its own file (kern.log, local1.log,
    ...).

It is unfortunate that syslog is such a neglected and unoptimized aspect
of nearly all Unix and Linux default installs but SA's don't have to
restrict their systems to those defaults.

Roger Marquis