Monitoring Text Logs

The most basic method to monitor a log in real time is to use the tail command’s -f option, which continuously reads a file and outputs new lines to stdout as they are added. As in previous chapters, we will use an Apache web server access log for examples, but the techniques presented can be applied to any text-based log. To monitor the Apache access log with tail:

tail -f /var/logs/apache2/access.log

Commands can be combined to provide more-advanced functionality. The output from tail can be piped into grep so only entries matching specific criteria will be output. The following example monitors the Apache access log and outputs entries matching a particular IP address:

tail -f /var/logs/apache2/access.log | grep '10.0.0.152'

Regular expressions can also be used. In this example, only entries returning an HTTP status code of 404 Page Not Found will be displayed; the -i option is added to ignore character case:

tail -f /var/logs/apache2/access.log | egrep -i 'HTTP/.*" 404'

To clean up the output, it can be piped into the cut command to remove extraneous information. This example monitors the access log for requests, resulting in a 404 status code and then uses cut to display only the date/time and the page that was requested:

$ tail -f access.log | egrep --line-buffered 'HTTP/.*" 404' | cut -d' ' -f4-7

[29/Jul/2018:13:10:05 -0400] "GET /test
[29/Jul/2018:13:16:17 -0400] "GET /test.txt
[29/Jul/2018:13:17:37 -0400] "GET /favicon.ico

You can further clean the output by piping it into tr -d '[]"' to remove the square brackets and the orphan double quotation.

Note that we used the egrep command’s --line-buffered option. This forces egrep to output to stdout each time a line break occurs. Without this option, buffering occurs, and output is not piped into cut until a buffer is filled. We don’t want to wait that long. This option will have egrep write out each line as it finds it.

../ 
etc/passwd 
etc/shadow
cmd.exe 
/bin/sh
/bin/bash

tail -f /var/logs/apache2/access.log | egrep -i -f ioc.txt

tail -f /var/logs/apache2/access.log | egrep --line-buffered -i -f ioc.txt |
tee -a interesting.txt

Monitoring Windows Logs

As previously discussed, you need to use the wevtutil command to access Windows events. Although the command is versatile, it does not have functionality similar to tail that can be used to extract new entries as they occur. Thankfully, a simple bash script can provide similar functionality; see Example 8-2.

#!/bin/bash -
#
# Cybersecurity Ops with bash
# wintail.sh
#
# Description:
# Perform a tail-like function on a Windows log
#
# Usage: ./wintail.sh
#

WINLOG="Application"  

LASTLOG=$(wevtutil qe "$WINLOG" //c:1 //rd:true //f:text)  

while true
do
	CURRENTLOG=$(wevtutil qe "$WINLOG" //c:1 //rd:true //f:text)  
	if [[ "$CURRENTLOG" != "$LASTLOG" ]]
	then
		echo "$CURRENTLOG"
		echo "----------------------------------"
		LASTLOG="$CURRENTLOG"
	fi
done

This variable identifies the Windows log you want to monitor. You can use wevtutil el to obtain a list of logs currently available on the system.

This executes the wevtutil command to query the specified logfile. The c:1 parameter causes it to return only one log entry. The rd:true parameter causes the command to read the most recent log entry. Finally, f:text returns the result as plain text rather than XML, which makes it easy to read from the screen.

The next few lines execute the wevtutil command again and compare the latest log entry to the last one printed to the screen. If the two are different, meaning that a new entry was added to the log, it prints the entry to the screen. If they are the same, nothing happens, and it loops back and checks again.

Generating a Real-Time Histogram

A tail -f provides an ongoing stream of data. What if you want to count how many lines are added to a file during a time interval? You could observe that stream of data, start a timer, and begin counting until a specified time interval is up; then you can stop counting and report the results.

You might divide this work into two separate processes—two separate scripts—one to count the lines and another to watch the clock. The timekeeper will notify the line counter by means of a standard POSIX interprocess communication mechanism called a signal. A signal is a software interrupt, and there are different kinds. Some are fatal; they will cause the process to terminate (e.g., a floating-point exception). Most can be ignored or caught—and an action can be taken when the signal is caught. Many have a predefined purpose, used by the operating system. We’ll use one of the two signals available for users, SIGUSR1. (The other is SIGUSR2.)

Shell scripts can catch the catchable interrupts with the trap command, a shell built-in command. With trap, you specify a command to indicate what action you want taken and a list of signals that trigger the invocation of that command. For example:

trap warnmsg SIGINT

This causes the command warnmsg (our own script or function) to be called whenever the shell script receives a SIGINT signal, as when you press Ctrl-C to interrupt a running process.

Example 8-3 shows the script that performs the count.

#!/bin/bash -
#
# Cybersecurity Ops with bash
# looper.sh
#
# Description:
# Count the lines in a file being tailed -f
# Report the count interval on every SIGUSR1
#
# Usage: ./looper.sh [filename]
#   filename of file to be tailed, default: log.file
#

function interval ()					
{
    echo $(date '+%y%m%d %H%M%S') $cnt			
    cnt=0
}

declare -i cnt=0
trap interval SIGUSR1					

shopt -s lastpipe					

tail -f --pid=$$ ${1:-log.file} | while read aline	
do
    let cnt++
done

The function interval will be called on each signal. We define it here. It needs to be defined before we can call it, of course, but also before we can use it in our trap statement.

The date command is called to provide a timestamp for the count value that we print out. After we print the count, we reset its value to 0 to start the count for the next interval.

Now that interval is defined, we can tell bash to call the function whenever our process receives a SIGUSR1 signal.

This is a crucial step. Normally, when there is a pipeline of commands (such as ls -l | grep rwx | wc), those pieces of the pipeline (each command) are run in subshells, and each ends up with its own process ID. This would be a problem for this script, because the while loop would be in a subshell, with a different process ID. Whatever process started, the looper.sh script wouldn’t know the process ID of the while loop to send the signal to it. Moreover, changing the value of the cnt variable in the subshell doesn’t change the value of cnt in the main process, so a signal to the main process would result in a value of 0 every time. The solution is the shopt command that sets (-s) the shell option lastpipe. That option tells the shell not to create a subshell for the last command in a pipeline but to run that command in the same process as the script itself. In our case, that means that the tail will run in a subshell (i.e., a different process), but the while loop will be part of the main script process. Caution: This shell option is available only in bash 4.x and above, and is only for noninteractive shells (i.e., scripts).

Here is the tail -f command with one more option, the --pid option. We specify a process ID to tell tail to exit when that process dies. We are specifying $$, the current shell script’s process ID, as the one to watch. This is useful for cleanup so that we don’t get tail commands left running in the background (if, for example, this script is run in the background; see the next script, which does just that).

The script tailcount.sh starts and stops the counting—the script that has the “stopwatch” so to speak, and times these intervals. Example 8-4 shows this script.

#!/bin/bash -
#
# Cybersecurity Ops with bash
# tailcount.sh
#
# Description:
# Count lines every n seconds
#
# Usage: ./tailcount.sh [filename]
#   filename: passed to looper.sh
#

# cleanup - the other processes on exit
function cleanup ()
{
  [[ -n $LOPID ]] && kill $LOPID		
}

trap cleanup EXIT 				

bash looper.sh $1 &				
LOPID=$!					
# give it a chance to start up
sleep 3

while true
do
    kill -SIGUSR1 $LOPID
    sleep 5
done >&2					

Since this script will be starting other processes (other scripts), it should clean up after itself. If the process ID has been stored in LOPID, the variable will be non-empty, and therefore the function will send a signal via the kill command to that process. By not specifying a particular signal on the kill command, the default signal to be sent is SIGTERM.

Not a signal, EXIT is a special case for the trap statement to tell the shell to call this function (here, cleanup) when the shell that is running this script is about to exit.

Now the real work begins. The looper.sh script is called but is put in the “background”: it is detached from the keyboard to run on its own while this script continues (without waiting for looper.sh to finish).

This saves the process ID of the script that we just put in the background.

This redirection is just a precaution. By redirecting stdout into stderr, any and all output coming from the while loop or the kill or sleep statements (though we’re not expecting any) will be sent to stderr and not get mixed in with any output coming from looper.sh, which, though it is in the background, still writes to stdout.

In summary, looper.sh has been put in the background and its process ID saved in a shell variable. Every 5 seconds, this script (tailcount.sh) sends that process (which is running looper.sh) a SIGUSR1 signal that causes looper.sh to print out its current count and restart its counting. When tailcount.sh exits, it will clean up by sending a SIGTERM to the looper.sh function so that it, too, will be terminated.

With both a script to do the counting and a script to drive it with its “stopwatch,” you can use their output as input to a script that prints out a histogram-like bar to represent the count. It is invoked as follows:

bash tailcount.sh | bash livebar.sh

The livebar.sh script reads from stdin and prints its output to stdout, one line for each line of input; see Example 8-5.

#!/bin/bash -
#
# Cybersecurity Ops with bash
# livebar.sh
#
# Description:
# Creates a rolling horizontal bar chart of live data
#
# Usage:
# <output from other script or program> | bash livebar.sh
#

function pr_bar ()					
{
    local raw maxraw scaled
    raw=$1
    maxraw=$2
    ((scaled=(maxbar*raw)/maxraw))
    ((scaled == 0)) && scaled=1		# min size guarantee
    for((i=0; i<scaled; i++)) ; do printf '#' ; done
    printf '
'

} # pr_bar


maxbar=60   # largest no. of chars in a bar		
MAX=60
while read dayst timst qty
do
    if (( qty > MAX ))					
    then
	let MAX=$qty+$qty/4	# allow some room
	echo "              **** rescaling: MAX=$MAX"
    fi
    printf '%6.6s %6.6s %4d:' $dayst $timst $qty	
    pr_bar $qty $MAX
done

The pr_bar function prints the bar of hashtags scaled to the maximum size based on the parameters supplied. This function might look familiar. We’re using the same function we used in histogram.sh in the previous chapter.

This is the longest string of hashtags we will allow on a line (to avoid line wrap).

How large will the values be that need to be displayed? Not knowing beforehand (although it could be supplied as an argument to the script), the script will, instead, keep track of a maximum. If that maximum is exceeded, it will “rescale,” and the current and future lines will be scaled to the new maximum. The script adds 25% onto the maximum so that it doesn’t need to rescale if each new value goes up by just one or two each time.

The printf specifies a min and max width on the first two fields that are printed. They are date and time stamps and will be truncated if they exceed those widths. You wouldn’t want the count truncated, so we specify it to be four digits wide, but the entire value will be printed regardless. If it is smaller than four, it will be padded with blanks.

Since this script reads from stdin, you can run it by itself to see how it behaves. Here’s a sample:

$ bash livebar.sh
201010 1020 20
201010   1020   20:####################
201010 1020 70
              **** rescaling: MAX=87
201010   1020   70:################################################
201010 1020 75
201010   1020   75:###################################################
^C

In this example, the input is mixing with the output. You could also put the input into a file and redirect it into the script to see just the output:

$ bash livebar.sh < testdata.txt
bash livebar.sh < x.data
201010   1020   20:####################
              **** rescaling: MAX=87
201010   1020   70:################################################
201010   1020   75:###################################################
$

Summary

Logfiles can provide tremendous insight into the operation of a system, but they also come in large quantities, which makes them challenging to analyze. You can minimize this issue by creating a series of scripts to automate data formatting, aggregation, and alerting.

In the next chapter, we will look at how similar techniques can be leveraged to monitor networks for configuration changes.

Workshop

1. Add an -i option to livebar.sh to set the interval in seconds.

2. Add an -M option to livebar.sh to set an expected maximum for input values. Use the getopts built-in to parse your options.

3. How might you add an -f option to livebar.sh that filters data using grep? What challenges might you encounter? What approach(es) might you take to deal with those?

4. Modify wintail.sh to allow the user to specify the Windows log to be monitored by passing in a command-line argument.

5. Modify wintail.sh to add the capability for it to be a lightweight intrusion detection system using egrep and an IOC file.

6. Consider the statement made in “Command-Line Buffers”: “When the input is coming from a file, that usually happens quickly.” Why “usually”? Under what conditions might you see the need for the line-buffering option on grep even when reading from a file?

Visit the Cybersecurity Ops website for additional resources and the answers to these questions.