Filtering Errors in Log Files

The following blog post was originally posted to the SAP Community Network on 21 May 2012.

When it comes to SAP Visualization Solutions by Nakisa (VSN), the log file is king. It is the source of information about all the transactions and activities carried out. In my first few weeks working with SAP VSN products I was quickly made aware of just how significant the CDS (Corporate Directory Services) log is and it is the foundation to solving at least a good 90% of issues encountered when configuring VSN applications.

The logs I found myself dealing with each day ranged in size from tens of lines to tens of thousands of lines. This to my mind made tracking down errors a rather tedious process and given that some of the errors were expected it made it all the more frustrating.

It was actually when I came across the first log that was tens of thousands of lines long that I decided I would make time to find a better (Quicker way to get the information from the file. In fact the method I describe here can be useful in a number of ways so even if you don’t deal with cds.log files every day you may still find the tools and ideas presented here useful.

The Idea

I’ve held a variety of positions in my career and fortunately this wasn’t the first time I’ve encountered an issue which required the manipulation and filtering of a large flat file of data. Whilst on occasion I’ve had to code an application to do the required work, the gurus of Unix past have saved my sanity a number of times and this is yet another where a useful tool known as SED comes into play.

SED (Stream Editor) is a command line utility that can carry out operations on a text file on a line by line basis. The instructions are based upon SED? own scripting language but typically (but not always) incorporate regular expressions. Such regular expressions allow you to define a pattern of characters that SED will use to determine if and how to carry out an operation on the line. One final thing worth mentioning is that it is super quick!

So the approach is to use SED and a specially crafted (but simple) script to do the heavy lifting for us.

The Non-Problem

But I use Windows, not Unix…

Whilst SED is originally a Unix utility and exists on pretty much every *nix based operating system, it has been also ported to non-*nix based operating systems including Windows. Of course you could install a Unix based emulator (e.g. CygWin, GOW) or even a virtual machine, but there are a number of reasons you might opt to just use the ported version of SED.

  • It doesn’t take up much disk space (unlike something as fully featured as CygWin).
  • You’re more likely to get permission to put it on the server.
  • It’s overkill to use the other options if all you’ll ever need is the functionality of SED. Keep it simple!

One other useful thing to consider is that you may not always have access to the command line on a server. Sometimes you may use FTP/SFTP to access the server and so not be able to run the SED script. In these instances however you can download the log file (hopefully your FTP/SFTP client supports on the fly ZIP-ing for your file if it’s hundreds of thousands of lines long!) and process it with SED locally. I’m sure I’m not alone in having a Windows based PC for my work, so

So where do you get SED for Windows from? Well it’s open source, so the answer’s SourceForge of course.

As you might have guessed from the reading this section I’m going to take using SED on Windows as my base line for showing you how to script it and work with the log file. If your’e on Linux chances are you know how to shell script and quite probably use SED, so feel free to read on but I’m probably not going to tell you much that you don’t already know.

The Approach

So what do we want to script SED to do? The approach I adopted was split into two main parts.

The first part was to take the log and strip out any line that isn’t an error. This would give me a nice condensed log with each of the errors in place and since every line is time stamped should I find the issue and want to check any information or warning lines (assuming the logging level in the application was set to include them) I can quickly get the time stamp and search the original log for it.

The second part relates to something you may recall from the start of this post. I said that some of the errors in the log were expected, I know you were wondering about that at the time, so let me explain….

One of the typical occasions you might refer to the cds.log file (including the one that inspired me to look at this) is when an issue occurs during the process to populate a staging database with data from SAP to be used by the VSN application. The configuration of the job to do this population includes SQL statements to drop tables, create indexes and lots of other operations you might expect. The job does runs the processing from scratch (mostly at least) and so there are times when it attempts to drop/remove tables or create an index that already exists from a previous run. These result in errors, but they don’t mean that the job has failed. These sorts of things are my expected errors.

So as a result I want to remove these errors from the log to just leave me with those unexpected errors.

The Script

For this example I’m just going to use DOS commands in a batch file to process the log file. For the sake of keeping things simple (and to hopefully not confuse matters) I’m going to state some assumptions/points of order for what follows.

  1. The SED executable is in the same directory as the log.
  2. The log file is named cds.log (older cds.log files get renamed when the new day’s log is created).
  3. The batch file to process the log file is called runme.bat and is in the same directory as the other two files.
  4. No other files are in the directory, just the three mentioned above.
  5. The batch file will be run from the directory it is in - i.e. it will be the working directory.
  6. You can create a batch file using a text editor (How to write a batch file).

So how do we strip out the non-error lines? Well we’ll re-frame it into something a little better. Let’s read through the log file and output every line that is an error into a new file.

@echo off
sed -n "/ERROR/p" "cds.log" > "cds1.txt"

So let’s break this down and look at what is going on…

Line Code What it Does
1 @echo off Tells the script not to output the command it is running to the screen. This is a fairly standard way to start a batch file.
2 sed Call the SED utility.
-n Tells SED to run silently and not follow its normal behaviour of outputting every line it reads. Instead it will only output when explicitly told to (using the "p" command for print).
"/ERROR/p" This is the command for SED to run. It tells SED to match any line containing the word ERROR and the "p" then tells SED to print it out to the standard output.
"cds.log" This is the name of the file for SED to carry out the processing on.
> Take all the output from SED (written to the standard output) and write it to a file.
"cds1.txt" Write the output to a file called cds1.txt in the local directory.

If we run the batch file this will produce a new (fourth) file in the directory which will contain only error lines.

We can now take this file and work on removing lines that are very specific error messages. I’ll use a couple of examples to show how this works.

First off I’m going to look at one that often occurs relating to employee images not being available. The error message in the log looks like this:

01 May 2012 12:34:56 ERROR com.nakisa.Logger  - executeFunctionDirect : FunctionRunner.executeFunctionDirect: HRWPC_RFC_EP_READ_PHOTO_URI threw an Exception of type AbapException, took: 163ms, Message = INTERNAL_ERROR

The script now becomes…

@echo off  
sed -n "/ERROR/p" "cds.log" > "cds1.txt"  
sed -e "/HRWPC_RFC_EP_READ_PHOTO_URI threw an Exception of type AbapException/d" "cds1.txt" > "cds2.txt"
Line Code What it Does
3 sed Call the SED utility.
-e Tells SED to run silently and not follow its normal behaviour of outputting every line it reads. Instead it will only output when explicitly told to (using the "p" command for print).
"/HRWPC\_RFC\_EP\_READ\_PHOTO\_URI threw an Exception of type AbapException/d" This is the command for SED to run. It tells SED to match any line containing the string we selected earlier and the "d" then tells SED to delete it - i.e. not print it to the standard output.
"cds1.txt" This is the name of the file for SED to carry out the processing on. It is the file created by the previous operation (not the original log file).
> Take all the output from SED (written to the standard output) and write it to a file.
"cds2.txt" Write the output to a file called cds2.txt in the local directory.

The cds2.txt file has now filtered out the photo error lines and we’re beginning to filter our error file down to a more manageable size. You can more or less just keep adding these text snippets and outputting to another new file. The process is just the same. Well more or less.

SED does use some characters for things other than their simple “textual” meaning. For example you’re probably noticed some forward slashes creeping in.

One of the characters that SED makes special use of is an open square bracket. SED uses the open square bracket (along with a close square bracket) to define a list. You might for example want to use it to define a list of vowels “[aeiou]”?

Remember I mentioned dropping tables that don’t exist? Well take a look at a typical drop table error message.

01 May 2012 12:34:56 ERROR com.nakisa.Logger  -  : org.springframework.jdbc.BadSqlGrammarException: StatementCallback; bad SQL grammar [DROP TABLE EMAILPHONETEMP]; nested exception is Cannot drop the table 'EMAILPHONETEMP', because it does not exist or you do not have permission.

Notice the use of square brackets. That complicates things a little. We can’t afford to just use the word “drop” as our exclusion match as it is possible that this could come up in a non-SQL context in another error.

Note also that this error indicates that the issue could arise because the user account does not have the correct level of permission. So before applying this filter you may wish to consider if it is a wise choice. Personally I use this. At each stage of filtering the resulting file is left in place so if I don’t see anything in my final file I can work backwards and review things such as permissions.

So how do we get SED to realise that when we use a square bracket we mean as text. The answer is to use an “escape character” An escape character is a special character which tells SED to treat the next character as a literal (text based) string rather than giving it the SED special character treatment. The character used to do this is the backslash. So to tell SED here’s an open square bracket we pass it “[”” If we needed to tell SED to use a backslash we’ll pass it “\

So the script now becomes:

@echo off  
sed -n "/ERROR/p" "cds.log" > "cds1.txt"  
sed -e "/HRWPC_RFC_EP_READ_PHOTO_URI threw an Exception of type AbapException/d" "cds1.txt" > "cds2.txt"  
sed -e "/ bad SQL grammar \[DROP/d" "cds2.txt" > "cds3.txt"

Now to make it a little easier when I was adding a new filter operation I decided to use some variables in the file naming. So here’s the same script but without me having to worry about the numbering of the files.

@echo off  
set intIN=-1  
set intOUT=0  

set /a intIN+=1  
set /a intOUT+=1  
sed -n "/ERROR/p" "cds.log" > "cds%intOUT%.txt"  

set /a intIN+=1  
set /a intOUT+=1  
sed -e "/HRWPC_RFC_EP_READ_PHOTO_URI threw an Exception of type AbapException/d" "cds%intIN%.txt" > "cds%intOUT%.txt"  

set /a intIN+=1  
set /a intOUT+=1  
sed -e "/ bad SQL grammar \[DROP/d" "cds%intIN%.txt" > "cds%intOUT%.txt"

Hopefully you can see how you can now get a repeatable block for any of the second stage operations.

The End?

Well that’s the general principle of how I tackled the taming of the huge cds.log and the end of my post … almost.

Since creating the first script I’ve gone through quite a few iterations of improvements and refinements. So if you fancy the challenge of making life with the cds.log (or any other log) even easier here are some things you might like to consider doing with the script.

Modify the script to give you the option to remove all of the files the script generated except for the last one.

Modify the script to open up the last file generated.

Modify the script to reference the install location of SED (if it isn’t in your path) and change it so that the first stage can take in a file of any name (remember cds.log files get renamed when the new day’s log is started). You could then add it to the send-to option in your context menu. Modify the script to read in a separate file that defines the strings for the second phase that you want to remove. You’ll probably want to select something other than DOS batch files to use to do this one.

Modify the script to include some (script) error handling logic.

Modify the script to give you some technical information.

How many lines it has processed at each stage and in total.

  • Hint: What would the following SED instruction do?
  • sed -n "$=" "cds.log"

How long did it take to process each file?

How many lines per second did it process?

Modify the script to use substitution based pattern matching to allow you to be more precise in your filtering. This can allow you to get around occasions where you want to filter similar error messages in and out.

Further Reading

For anyone wanting to take things a little further or who maybe needs a primer on some of the non-SED stuff touched upon here are some links I think you’ll find useful.

Author: Stephen Millard
Tags: | sap | shell | vsn |

Buy me a coffeeBuy me a coffee

Related posts that you may also like to read