ONLamp.com    
 Published on ONLamp.com (http://www.onlamp.com/)
 See this if you're having trouble printing code examples


FreeBSD Basics

IPFW Logging

06/21/2001

I've spent the last few articles creating rules to allow ipfw to just allow the IP traffic I wish to enter my FreeBSD computer. This week, I'd like to take a look at logging and will probably end up tweaking my firewall further as I do so.

Like creating rulesets, logging is a bit of a fine art. What you decide to log will depend upon your degree of curiosity, how important the data is that you're trying to protect with your firewall, the amount of disk space you have available to hold the logged information, and a realistic assessment of how much information you're willing to wade through to see if anything happened that you didn't want to happen.

Even if you don't explicitly add the log keyword to any of the rules in your ipfw ruleset, there are still several places that your FreeBSD kernel will record events as they occur. Let's spend some time examining the type of information that is recorded and the locations where that information is stored. Before we do so, let's take a look at my current ruleset as I've changed it slightly. Because I like to log denied packets, I've added the log keyword to rule 00301 and have added rule 00700 to log all packets that were not explicitly allowed by any of my rules:

ipfw show

00100 135946  11920244 allow ip from any to any via lo0
00200      0         0 deny ip from any to 127.0.0.0/8
00300      0         0 deny ip from 127.0.0.0/8 to any
00300      0         0 check-state
00301    753    112227 deny log logamount 10 tcp from any to any in established
00302 233176 107186044 allow tcp from any to any keep-state out setup
00400  15823   2353615 allow udp from 24.226.1.90 53 to any in recv ed1
00401   2787    155141 allow udp from 24.226.1.20 53 to any in recv ed1
00402   2781    154266 allow udp from 24.2.9.34 53 to any in recv ed1
00403  21503   1222215 allow udp from any to any out
00501   1785    694722 allow udp from 24.226.1.41 67 to any 68 in recv ed1
00600    607     34028 allow icmp from any to any icmptype 3
00601      0         0 allow icmp from any to any icmptype 4
00602      4       336 allow icmp from any to any out icmptype 8
00603      4       336 allow icmp from any to any in icmptype 0
00604     63      3528 allow icmp from any to any in icmptype 11
00700    135      7452 deny log logamount 10 ip from any to any
65535      0         0 deny ip from any to any

If you are not already in the habit of doing so, you should read the root user's email on a daily basis as several important bits of information are recorded by the cron daemon. As you read these daily e-mail messages, you'll become familiar with what is normal behavior for your FreeBSD system. When you read the "daily run output" email, take note of the "disk status" section; here's mine from this morning's output:

Disk status:
Filesystem  1K-blocks     Used    Avail Capacity  Mounted on
/dev/ad0s1a     99183    37359    53890    41%    /
/dev/ad0s1f   7851141  1164528  6058522    16%    /usr
/dev/ad0s1e     19815     5762    12468    32%    /var
procfs              4        4        0   100%    /proc
mfs:68852      257999        9   237351     0%    /tmp

Pay attention to the capacity of /var as this is where logged information is stored. You should find that its capacity will grow at a fairly steady daily rate; for example, mine grows at about 4 percent per day. Knowing this, you'll have an idea of how often you should clean out your /var partition. You'll also be alerted if there is a significant increase in capacity used. For example, if I were to read my email tomorrow and the capacity on /var had jumped up to 85 percent, I'd immediately take a look at my logs to see why the kernel had logged so many events.

You'll also want to read the "security check output" that is sent by email to the root user. Here is a copy of my output from last week:

****************************************************
>From root@.HOSTNAME. Sat Jun 2 09:18:02 2001
Date: Sat, 2 Jun 2001 03:01:03 -0400 (EDT)
From: Charlie Root <root>
To: undisclosed-recipients:  ;
Subject: hostname security check output

Checking setuid files and devices:

Checking for uids of 0:
root 0
toor 0

Checking for passwordless accounts:

hostname denied packets:
> 00301    14     560 deny log logamount 10 tcp from any to any in established
> 00700    28    1580 deny log logamount 10 ip from any to any

ipfw log limit reached:
00301    14     560 deny log logamount 10 tcp from any to any in established
00700    28    1580 deny log logamount 10 ip from any to any

hostname kernel log messages:
> Connection attempt to TCP 127.0.0.1:113 from 127.0.0.1:3198
> Connection attempt to TCP 127.0.0.1:113 from 127.0.0.1:3198
> Connection attempt to UDP 127.0.0.1:512 from 127.0.0.1:1307
> Connection attempt to TCP 127.0.0.1:113 from 127.0.0.1:3231
> Connection attempt to TCP 127.0.0.1:113 from 127.0.0.1:3231
> Connection attempt to UDP 127.0.0.1:512 from 127.0.0.1:1340
<snip as it goes on for a while>

hostname login failures:

hostname refused connections:
hostname checking for denied secondary zone transfers:
****************************************************

Let's pick apart the sections that deal with logged events. Note that you won't get any entries under "hostname denied packets" or "ipfw log limit reached" unless you add the log keyword to a rule in your ruleset. It looks like my firewall denied 14 packets that tried to make a TCP connection to my FreeBSD box (rule 00301), and it also denied 28 packets that didn't meet any of the allow rules in my ruleset (rule 00700).

Also in FreeBSD Basics:

Fun with Xorg

Sharing Internet Connections

Building a Desktop Firewall

Using DesktopBSD

Using PC-BSD

Under "hostname kernel log messages", I had a lot of entries. Not only did this make for a very large email, it also reflected the growing size of the file /var/log/messages as this section is really a copy of the changes made to that file within the last 24 hours. All of those changes are events that were recorded to the console found at ALT F1.

When I originally read that email, I took a look at the console and sure enough, it was flooded with entries regarding ports 113 (auth) and 512 (biff). What was happening was that every time I received an email message, Sendmail did an "auth" lookup on my user account, then it tried to notify the "biff" client to advise it that a new mail message had been received for my user account. I receive a lot of email and have configured fetchmail to check my POP3 account every 5 minutes, thus I had an amazing amount of console entries.

I wanted to disable these console messages for two reasons. One, if I get used to hundreds of trivial messages showing up on my console, I might miss an important console message. Two, I don't want to waste disk space on these entries as I already know that I receive a lot of email and I don't need to be notified everytime an email arrives.

Let's start by getting rid of the biff messages. I found the simplest way to do this was to become the superuser and edit the file /etc/services. I'll open up this file in vi and do a search for the word "biff":

vi /etc/services
/biff

biff   512/udp   comsat   #used by mail system to notify users
#                          of new mail received; currently
#                          receives messages only from
#                          processes on the same machine

I'll then put a # in front of the word "biff" in order to comment out this service and will save my changes. Once I'm finished, the kernel will no longer send entries to the console that deal with my Sendmail program contacting port 512.

We'll be seeing auth again as we start to pick apart our logs as many mail servers use the auth daemon; we'll find that how we configure ipfw to treat auth may make a difference in mail delivery speed. But for now, I just want to suppress the console messages that tell me that my Sendmail program did an auth check as it delivered my email. To do so, I'll open up /etc/inetd.conf, do a search for the word "auth", and press "n" to search for the second occurrence of that word:

vi /etc/inetd.conf
/auth
n

I'm now at this portion of the file:

# Provide internally a real "ident" service which provides ~/.fakeid support,
# provides ~/.noident support, reports UNKNOWN as the operating system type
# and times out after 30 seconds.
#
#auth stream tcp nowait root internal auth -r -f -n -o UNKNOWN -t 30

I'll remove the # next to the auth word and save my changes. Remember that changes to this file won't take effect until I notify inetd. I'll send a signal 1 to inetd to inform it of the configuration change by using the killall command:

killall -1 inetd

Once I did this, those messages stopped appearing on the console and now when I read my "security run output," I don't have to wade through all of those unnecessary entries.

Now let's take a look at /var/log to see which files contain information logged by the ipfw kernel. I'll do a long listing to see the size of the files in this directory:

ls -l /var/log 
total 520
drwxr-xr-x  2 root  wheel   1024 Jun 10 11:28 ./
drwxr-xr-x 19 root  wheel    512 May 30 12:48 ../
-rw-------  1 root  wheel  87489 Jun 10 11:25 cron
-rw-r-----  1 root  wheel  11150 Jun 10 03:05 dmesg.today
-rw-r-----  1 root  wheel  10503 Jun  9 03:05 dmesg.yesterday
-rw-r--r--  1 root  wheel    236 Jun  8 10:16 httpd-error.log
-rw-r-----  1 root  wheel    371 Jun 10 03:05 ipfw.today
-rw-r-----  1 root  wheel    359 Jun  9 03:05 ipfw.yesterday
-rw-r--r--  1 root  wheel  28056 Jun  9 19:49 lastlog
-rw-r--r--  1 root  wheel      0 Apr 21 05:10 lpd-errs
-rw-r--r--  1 root  wheel 296751 Jun 10 11:28 maillog
-rw-r--r--  1 root  wheel  78371 Jun  9 21:45 messages
-rw-r-----  1 root  wheel    140 Jun  9 03:05 mount.today
-rw-r-----  1 root  wheel    140 Jun  6 03:05 mount.yesterday
-rw-------  1 root  wheel      0 Apr 21 05:10 ppp.log
-rw-------  1 root  wheel   4870 Jun  9 19:50 security
-rw-r--r--  1 root  wheel    628 Jun 10 11:28 sendmail.st
-rw-r-----  1 root  wheel   5744 Jun  2 03:05 setuid.today
-rw-r-----  1 root  wheel   5744 May 27 03:04 setuid.yesterday
-rw-------  1 root  wheel      0 Apr 21 05:10 slip.log
-rw-------  1 root  wheel      0 Jun  4 08:56 userlog
-rw-r--r--  1 root  wheel   1232 Jun  9 19:49 wtmp

Let's start by taking a look at ipfw.today:

more /var/log/ipfw.today
00200 0 0 deny ip from any to 127.0.0.0/8
00300 0 0 deny ip from 127.0.0.0/8 to any
00301 751 112147 deny log logamount 10 tcp from any to any in established
00700 125 6520 deny log logamount 10 ip from any to any
65535 0 0 deny ip from any to any

You'll note that this is slightly different than the "hostname denied packets" section of the "security check output" as it shows all the rules that deny packets, not just the ones that have the log keyword. You can also compare it to ipfw.yesterday to get an indication of any anomalies in traffic. Again, if you do this consistently, you'll have a good idea of what is normal for your firewall and will more easily notice any strange behavior. These two logs are small, are over-written daily, and give a quick reference check on the number of packets that are being denied on a daily basis.

If I take a look at dmesg.today, I should recognize most of the entries from the "hostname kernel log messages" section of the "security check output." Again, this is just today's portion of the much larger file messages. It is useful to be aware of both, as they do record the same information, but in slightly different formats. I'll display the last 10 lines of each file using the tail command to demonstrate; you'll note that I've blocked out my IP address.

tail /var/log/dmesg.today
Connection attempt to UDP x.x.x.x:4780 from 24.226.1.20:53
Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
sigreturn: eflags = 0x13216

tail /var/log/messages
Jun 9 20:21:06 hostname /kernel: Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Jun 9 20:21:06 hostname /kernel: Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Jun 9 20:21:06 hostname /kernel: Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Jun 9 20:21:36 hostname /kernel: Connection attempt to TCP x.x.x.x:2058 from 209.75.20.41:80
Jun 9 20:21:36 hostname /kernel: Connection attempt to TCP x.x.x.x:2059 from 209.75.20.41:80
Jun 9 20:42:00 hostname gconfd (genisis-82257): Failed to load source `xml:readonly:/usr/X11R6/etc/gconf/gconf.xml.mandatory': Failed: Could not make directory `/usr/X11R6/etc/gconf/gconf.xml.mandatory': Permission denied
Jun 9 20:42:01 hostname gconfd (genisis-82257): Failed to load source `xml:readonly:/usr/X11R6/etc/gconf/gconf.xml.defaults': Failed: Could not make directory `/usr/X11R6/etc/gconf/gconf.xml.defaults': Permission denied
Jun 9 21:41:08 hostname /kernel: sigreturn: eflags = 0x13216
Jun 9 21:45:13 hostname gconfd (genisis-85334): Failed to load source `xml:readonly:/usr/X11R6/etc/gconf/gconf.xml.mandatory': Failed: Could not make directory `/usr/X11R6/etc/gconf/gconf.xml.mandatory': Permission denied
Jun 9 21:45:13 hostname gconfd (genisis-85334): Failed to load source `xml:readonly:/usr/X11R6/etc/gconf/gconf.xml.defaults': Failed: Could not make directory `/usr/X11R6/etc/gconf/gconf.xml.defaults': Permission denied

The log file dmesg.today is a little easier to read, but messages contains more details, such as the time the event was logged. Also, dmesg.today is overwritten on a daily basis, whereas messages is not. Because the newsyslog daemon is responsible for the growth of log files, let's take a look at its configuration file to see how large the messages log can become:

more /etc/newsyslog.conf
<snip to just show entries for messages and security>
# configuration file for newsyslog
# $FreeBSD: src/etc/newsyslog.conf,v 1.25.2.4 2001/02/26 09:26:11 phk Exp $
#
# logfilename [owner:group] mode count size when [ZB] [/pid_file] [sig_num]
/var/log/messages 644 5 100 * Z
/var/log/security 600 10 100 * Z

The "100" in the size column means this log will grow until it reaches 100 Kbytes in size. When it does, the Z in the [ZB] column indicates that it will be compressed, renamed to messages.0.gz, and a new messages log will be started. The count column indicates how many compressed logs will be kept before newsyslog will delete the oldest compressed log; in this case, there can be up to five.

If you need more information on newsyslog, click here.

You'll note that I also showed the entry for the security log, which is the last log that deals with ipfw. In the next article, I'd like to demonstrate what type of information to look for when reading the security log, and what you can do about the information you find in it.

Dru Lavigne is a network and systems administrator, IT instructor, author and international speaker. She has over a decade of experience administering and teaching Netware, Microsoft, Cisco, Checkpoint, SCO, Solaris, Linux, and BSD systems. A prolific author, she pens the popular FreeBSD Basics column for O'Reilly and is author of BSD Hacks and The Best of FreeBSD Basics.


Read more FreeBSD Basics columns.

Return to the BSD DevCenter.

Copyright © 2009 O'Reilly Media, Inc.