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!

Life as a Scientist

A great tool to analyze your blog: http://typealyzer.com/


(Found this tool referenced at Mark Little's blog: http://markclittle.blogspot.com/)

Stress Testing: Don't spend your life waiting for a moment that just don't come, Well, don't waste your time waiting...

I remember the situation distinctly, even though it happened over a decade ago. The product in question was a 2nd generation server. The 1st generation was successful, but like many 1.0 projects, parts of it were, well, let's just say "immature." As a result, the product was buggy and difficult (and expensive!) to maintain. The goals of the 2nd generation product were ambitious; to correct the product's design flaws, extend its feature set, and improve its overall performance and reliability.

After a long development cycle, testing started and we were dismayed to find that the re-architecting effort had completely destabilized the product. We immediately started finding memory leaks, random crashes, loss of data, and basic functions that we just plain broken. The early test results caused a large amount of angst, and also caused us to adopt a very defensive posture. We reorganized testing into discrete stages, and we determined to not advance from one stage to the next until we had established a consistent baseline of reliable product operation.

As the early stages of functional testing progressed, product instability continued, and large numbers of bugs were found, resolved, and verified. Eventually, the product's stability improved, but there serious bugs were still periodically found, so we held to our defensive posture and did not progress from functional to system-wide or stress/performance tests until functional testing was complete. When we finally determined that the product was stable enough for stress testing, the project schedule had been extended multiple times. When stress testing started, began finding still more bugs related to product's inability to function under a load over time or to handle high levels of traffic. Once again, the project schedule had to be extended as large numbers of bugs were found, resolved, and verified.

What went wrong on this project? Well, quite a bit. The planning was overly optimistic, the design was not properly reviewed or understood, unit testing was inadequate, at one point, we even discovered that if every port on the server was physically cabled and the system was not properly rack-mounted, it would tip over and fall on the floor. In addition, by being too conservative in our test planning, and too rigid in our first reaction to the system's initial poor performance, we may have delayed the discovery of some serious problems.

What should we have done differently? We should have started some stress testing as early as could find situations and product configurations that would support it. The first stress tests could have taken the form of low levels of traffic running over an extended period of time, and not necessarily a massive system load at the start. By finding tests that the product could support, we could have established a baseline of performance to measure against as the product's many bugs were resolved (and its code was changed). By waiting for "perfect" conditions that actually arrived very late in the product's development, we delayed tests that could have been run under "good" conditions.

There's a saying that, "if you see blue sky, go for it."[1] It can be like that in software testing too. If you wait for perfect conditions to run some tests, you may end up waiting for a long time, and that waiting may result in bugs being found at a late and probably inconvenient time. When should you try stress testing a product? As early as you can. Performance related problems can be difficult and time consuming to resolve. The sooner you find them, the better. So, if you see some blue sky among the bugs early in a project test cycle, go for it...

(Special thanks to Pavel!...and Mr. Springsteen...)

References:

[1] http://www.pbs.org/wgbh/amex/kennedys/filmmore/pt.html

Parameterized Testing? But wait, there's more! (Inversion of Control/Dependency Injection, that is)

When you spend most of your waking hours (and, truth be told, some of you sleeping hours too) involved in software engineering, you can find yourself speaking a language foreign to friends and relatives. In my own case, most of my friends and family have no experience in or with software design, development, or testing. They tend to see my software engineering experience as useful, but also something out of the ordinary.

This past Monday, for example, a good friend of mine, a lawyer by profession, telephoned me late at night, desparate to rescue his home computer from the malware that he had inadvertently downloaded. I managed to walk him through the steps necessary to get his computer working again. That is, I thought I had, until a couple of nights later, he called me again asking my advice in buying a new computer.

A few days later, I was reading a printed copy of Martin Fowler's paper "Inversion of Control Containers and the Dependency Injection pattern" [1] when a friend of mine commented, "inversion of control?" Dude, that's the story of my life. My kids rule the house."

The term "dependency injection" can at first be bit more intimidating than the reality of what it is and how it's used. The simplest explanation that I've ever seen for it is in James Shore's excellent blog "The Art of Agile" [2] when he states that:

'...dependency injection means giving an object its instance variables..'

OK. This is all interesting, but what does it have to do with software testing? Quite a bit, actually. In the blog entry from a few weeks ago titled "Parameterized Testing - Very Easy with TestNG's DataProvider" we talked about designing tests that accept parameters, so that the same test could be run against multiple sets of data. In this post, we'll revisit that test design pattern.

But first, let's take a deeper look at inversion of control and dependency injection.

To begin, let's disect the phrase "inversion of control." In this context, who wants control, and just how is this control inverted?

In an object oriented language such as Java, you solve programming problems by designing classes. The classes contain variables (to hold data) and methods (functions that manipulate the data). To actually perform the tasks that you want the programs to do, you create discrete instances of the objects. When you create an object instance, you work with instances of the variables.

Let's say that you've defined a Java class of type Car, and within the class you set a Manufacturer variable to, say, "Audi."

What have we just done in terms of control and dependencies?

* Who has control? The "Car" class has the control. In order to build a new car, it defines a variable of type "Manufacturer." Or more precisely it defines an instance variable of type "Manufacturer." In this case, the class only allows for a Manufacturer of "Audi."

* The "Car" class needs the "Manufacturer" variable to do its work. In other words, it depends on this variable. That's right, this instance variable is a "dependency."

However, there's a problem with the "Car" class. How can build a test for the class, and test multiple car manufacturers? To build a test for Toyota, for example, we will have to build another class that's almost identical to the "Car" class, except that it will create a different "Manufacturer" object.

The answer is easy, of course, we just add another constructor to the Car class:

  public Car(Manufacturer targetManufacturer) {
    carManufacturer = targetManufacturer;
  } 

So, now what have we just done in terms of control and dependencies?

* The value of the dependency, that is, the "carManufacturer" variable is not hardwired into the "Car" class. It is "injected" into the "Car" class through its new constructor.

* Who has control now? Not the "Car" class anymore. The class can now be used to create any type of car. Who controls the decision of the type of car to create? The program (or test program) that creates the instance of the "Car" class. That's the "inversion" of control.

One important use of this model is that it emables us to isolate the class being tested. For example, if we want to test the Car class with a mock or stub[3] version of the Manufacturer class, we can pass that stub or mock object to the Car class during the test. This will let the test concentrate on verifying the operation of the Car class, independent of the function (or lack of function) provided by the Manufacturer class.

When you couple this design pattern with ability to pass a parameter into a test, such as is supported in TestNG, this enables us to inject the dependecies into the classes being tested. This makes it possible for the tests to control not only the test data, but also the defined profile and characteristics of the classes under test. And to do it without hardcoding data into the tests or the classes under test. Now, that's control!

References:

[1] http://martinfowler.com/articles/injection.html

[2] http://jamesshore.com/Blog/Dependency-Injection-Demystified.html

[3] Next Generation Java Testing by Cedric Beust and Hani Suleiman, pages 95-96. http://testng.org/doc/book.html

And not a drop to drink - Leak and Soak Tests

Owning an old house has some advantages. You can enjoy its period architectural details and perhaps find some hidden treasures. When we did some house renovations, we found newspapers from 1923 in one wall of the house. It was quite a surprise to be able to read contemporary sports coverage of Babe Ruth[1]! Owning an old house also means that you are always performing maintenance. I remember late one cold January night when I woke up to the sound of water dripping. It wasn't the bathroom, it was a vintage cast-iron radiator drippig water through the ceiling. Nothing had changed in the water pressure, but the washers in the radiator had just been worn down by prolonged use. Another time, a massive rainstorm resulted in a leak in the roof. The roof had performed well for years of less severe rain storms or equally severe, but shorter downpours, but the extended high level of rain simply soaked through it.

In the first case, the problem wasn't that the level of water traffic had increased beyond what the radiator "system" could manage, it was the accumulated damage of a relatively low level of traffic over time. In the second case, the problem was that the roof "system" was overwhelmed by prolonged exposure to a high level of traffic.

OK - what do all these expensive home repairs have to do with software testing? Just this; when you go about designing stress tests for your product or application, you should include "leak" and "soak" tests* in your plan.

When some people approach stress test planning, they treat the tests as a blunt instrument with which they try to assault the system under test. This type of scorched earth approach to testing can result in system failures being encountered, but these failures can be difficult to diagnose and reproduce. A combination of disciplined leak and soak tests can help you better identify the root causes of stress related system failures.

How do leak and soak tests differ? The differences can be thought of in the terms of the radiator and roof failures that I mentioned above.

In a leak test, you tend to run the system under a manageable, and tracable level of traffic for an extended period, to determine of the accumulated weight of usage causes a system failure. The classic case is when you are looking for a memory leak. The taffic load should not be extreme.

It may be that each system action results in a very small memory leak, or in the premanent allocation of some other system resource. If you run this test once, the leak may occur, but in the context of a system with several GB of memory, and a process that is using several MB of memory, you might not notice that the memory or system resource is not freed up when the test completes. But, if you repeat the test, and observe the process under test a tool such as JBoss Profiler[2], and observe the system with utilities such as top, sar, or vmstat, then you may be able to spot a trend of when system resources are used and not released. A great way to begin a leak testing regimen, is by observing the memory and system resource use of the software under test in an idle state. Just start up the server or application product under test and then leave it alone for an extended period. You may find that it's use of system resources increases over time, just through its self-maintenance, even when it is not actively processing user or client requests.

So, in a leak test, the key variable in the test equation is time.

In contrast, a soak test, hits the system under test with a significant test load, and maintains that load over an extended period of time. A leak test may involve running traffic through the system under test on only one thread, but a soak test may involve stressing the system to its maximum number of concurrent threads. This is where you may start to see inter-thread contention issues or problems with database connection pools being exhausted. If you can establish a reliable baseline of system operation with a leak test that runs over an extended period of time, then you can move onto more aggressive tests such as soak tests. If, however, a leak test exposes system failures, then you would probably encounter the same types of failures with soak tests. But, the level of traffic used in a soak might make these failures harder to diagnose.

So, in a soak test, the key variables in the test equation are both time and a sustained high load level.

To sum it up, if a leak test is passive aggressive in nature, a soak test is just plain aggressive.

* Dzięki Jarek!

References:

[1] http://en.wikipedia.org/wiki/Curse_of_the_Bambino
[2] JBoss Profiler - http://www.jboss.org/community/docs/DOC-10728

Parameterized Testing - Very Easy with TestNG's DataProvider

I was starting work on some parameterized JUnit tests the other day, when a co-worker*, someone who has a uncanny knack of reducing my complicated questions to simple answers, suggested, "Why don't you try a TestNG DataProvider instead?"

I was already trying to write the tests in Groovy, a scripting language with which I had very little experience, so the prospect of also trying a new test framework was not exactly appealing. But, I decided to give it a try. After a couple of hours of trial and error and self-inflicted syntax errors, I came to the conclusion that a TestNG DataProvider was the way to go. DataProviders are easy to use, and the coding is very straightforward.

TestNG[1] was developed by Cedric Beust and Alexandru Popescu in response to limitations in JUnit3. Actually, "limitations" may be too strong a word. In their book "Next Generation Java Testing"[2], they take pains to say that they developed TestNG in response to "perceived limitations" in JUnit3. In some cases, these were not limitations, but rather, design goals in JUnit that were in conflict to some types of tests. For example, the manner in which each JUnit test case re-instantiates the test class for a "clean" starting point. In this regard, TestNG supports test models beyond unit tests, for example, tests that are inter-dependent.

TestNG provides a couple of ways to support passing parameters to test cases. The parameters can be passed to the test cases through properties defined in testng.xml, or with the DataProvider annotation. DataProviders support complex passing complex objects as parameters. Here's how it works:

You define a method associcated with the "@DataProvider" annotation that returns an array of object arrays to your test cases.

Hang on - an array of arrays? Why is that needed? Here's why - each array of objects is passed to the test cases. In this way, you can pass an array of multiple parameters, each of whatever object type you want to the test cases. It's like this, say you want to pass a String and an Integer[3] to a test case. The DataProvider method returns an object of this type:

Object [][]

So that with these values:

Groucho, 1890
Harpo, 1888
Chico, 1887

The DataProvider provides:

array of objects for call #1 to test method = [Groucho] [1890]
array of objects for call #2 to test method = [Harpo] [1888]
array of objects for call #3 to test method = [Chico] [1887]

Or: this array of arrays of objects = [array for call #1] [array for call #2] [array for call #3]

Simple, right? Once you get past the idea of an array of arrays. Here's the Groovy code.

package misc

import org.testng.annotations.*
import org.testng.TestNG
import org.testng.TestListenerAdapter
import static org.testng.AssertJUnit.*;

public class DataProviderExample {
 
 /* Test that consumes the data from the DataProvider */
 @Test(dataProvider = "theTestData")
 public void printData(String name, Integer dob) {
  println("name: " + name + " dob: " + dob)
 }
 
 /* Method that provides data to test methods that reference it */
 @DataProvider(name = "theTestData")
 public Object[][] createData ( ) {
  [ 
    [ "Groucho", new Integer(1890) ] , 
    [ "Harpo", new Integer(1888) ] , 
    [ "Chico", new Integer(1887) ] 
    ]  as Object[][]
 } 
 
}

When you run this with TestNG, the output looks like:

[Parser] Running:
  /workspace_groovy/BlogCode/temp-testng-customsuite.xml

name: Groucho dob: 1890
name: Harpo dob: 1888
name: Chico dob: 1887
PASSED: printData("Groucho", 1890)
PASSED: printData("Harpo", 1888)
PASSED: printData("Chico", 1887)

===============================================
    misc.DataProviderExample
    Tests run: 3, Failures: 0, Skips: 0
===============================================

I'll return to Groovy and TestNG in some future blog posts as they are very "groovy" test tools. Well, as Groucho would say, "hello, I must be going..."

References:

[1] http://testng.org/doc
[2] http://testng.org/doc/book.html
[3] This is a very slight variation on the sample shown here: http://testng.org/doc/documentation-main.html#parameters-dataproviders

* Děkujeme vám Jirka! ;-)