grep - In living Color

In my last blog post, I mentioned that in performing software testing you tend to look in log files for clues as to the root cause of bugs. grep is a great tool for doing this, but it does have one drawback. If the lines of text in a log file that you are grep'ing through are very long, you can end up with output that looks like this:

grep here-is-the-bad.jar server.log

22:05:01,485 DEBUG [ServerInfo] class.path: /opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxws.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxrpc.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-saaj.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/serializer.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xercesImpl.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/jaxb-api.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xalan.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/resources.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/rt.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jsse.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jce.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/charsets.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/classes:/usr/lib/here-is-the-bad.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxws.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxrpc.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-saaj.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/serializer.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xercesImpl.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/jaxb-api.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xalan.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/resources.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/rt.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jsse.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jce.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/charsets.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/classes

Oh. Of course. There's the problem. What? You can't see it? ;-)

Let's try that grep command again. But this time, let's use grep's color option*. This will highlight what we're looking for:

grep --color=auto here-is-the-bad.jar server.log

22:05:01,485 DEBUG [ServerInfo] class.path: /opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxws.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxrpc.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-saaj.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/serializer.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xercesImpl.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/jaxb-api.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xalan.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/resources.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/rt.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jsse.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jce.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/charsets.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/classes:/usr/lib/

here-is-the-bad.jar

:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxws.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-jaxrpc.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/server-saaj.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/serializer.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xercesImpl.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/jaxb-api.jar:/opt/local/system000001_test_1234/server-sample-p.1.2.4/server-as/lib/endorsed/xalan.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/resources.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/rt.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jsse.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/jce.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/lib/charsets.jar:/usr/lib/jvm/java-1.6.0-sun-1.6.0.7/jre/classes

Now, that's more like it! ;-)


* Special thanks to Ralph for pointing me at grep's color option!

Watching Things...with Linux's "watch"

When you test software, you tend to spend a lot of your waking hours (and some sleeping hours too) debugging problems. This involves looking around the system undertest for clues as to the root causes of failures.

One trick that I constantly use is to execute the "tail -f" command on system or server or process log files while I'm running tests. The tail command displays the last (10) lines of the file. Adding the -f option results in the file contents to be displayed as they are written to the log file. The result is that I can watch the log file as a real-time window into what's happening on the system under test.

I recently learned[1] about another useful tool; the "watch"[1] command. What watch does is to execute the shell command that you specify at the interval that you specify. What makes watch useful, though. is that is displays its output full-screen, and refreshes the full screen display, so you can don't have to scroll the display for the latest results.

For example, if you wanted to keep an eye on system memory use, you could execute this command to have watch display memory usage information and update the display every 5 seconds:

watch -n 5 cat /proc/meminfo

And see something like this:

Every 5.0s: cat /proc/meminfo                           Fri May  8 22:43:53 2009

MemTotal:      2049932 kB
MemFree:        948244 kB
Buffers:         77540 kB
Cached:         535776 kB
SwapCached:          0 kB
Active:         460124 kB
Inactive:       476236 kB
HighTotal:     1153728 kB
HighFree:       314396 kB
LowTotal:       896204 kB
LowFree:        633848 kB
SwapTotal:     2621432 kB
SwapFree:      2621432 kB
Dirty:              88 kB
Writeback:           0 kB
AnonPages:      323000 kB
Mapped:          67700 kB
Slab:            53548 kB
PageTables:       5064 kB
NFS_Unstable:        0 kB
Bounce:              0 kB
CommitLimit:   3646396 kB
Committed_AS:   904128 kB
VmallocTotal:   114680 kB
VmallocUsed:      7748 kB
VmallocChunk:   106612 kB
HugePages_Total:     0
HugePages_Free:      0
HugePages_Rsvd:      0
Hugepagesize:     4096 kB

Or, if you wanted to only watch the amount of free memory, you could execute this variation on that same command:

watch -n 5 'cat /proc/meminfo | grep MemFree'

And see something like this:

Every 5.0s: cat /proc/meminfo | grep MemFree            Fri May  8 22:47:10 2009

MemFree:        932252 kB

As I said, when you're debugging a test, or a potential bug uncovered by a test, you have to watch multiple source of information on the system you're testing. The watch command can be a very useful tool to help you see specific pieces of information in the flood of information that you may have to search through.

References:

[1] http://linux.about.com/library/cmd/blcmdl1_watch.htm

* Special thanks to Ralph for pointing me at watch!