SoapUI: Using FileAppender for Logging

In writing SoapUI test scripts, you may come across a situation where you need some additional logging functionality; for example, writing information to a file aside from the default SoapUI log for review after running a script via testrunner.  You could explicitly create and manage your own text file, but you may find it simpler to leverage the existing Logger object (via the log variable) to send logged messages to another file using the FileAppender class.

A FileAppender can forward messages sent to the log to a separate file, using formatting options to label messages with dates, logging levels, etc.  Here's an example setup script demonstrating how to set up a FileAppender to write to a simple text file (you can download a starter project containing all this code here):

import org.apache.log4j.FileAppender
import org.apache.log4j.PatternLayout

//Define the layout to use
def pLayout = new PatternLayout("%d{DATE} : %m%n")
//Create FileAppender in context using layout we just defined
context.customLogger = new FileAppender(pLayout,"C:\\Temp\\CustomLog\\CustomLog.txt", false)
//Add the appender to the existing log
log.addAppender(context.customLogger)

Remember, there's no need to add any additional jars to SoapUI's ext folder in this case; we're using the log4j package that's already part of its libraries.  However, we do need to import the FileAppender and PatternLayout classes at the top of our script.

After the import statements, a new PatternLayout is created for use with the FileAppender:

def pLayout = new PatternLayout("%d{DATE} : %m%n")

The string that's passed into the PatternLayout constructor ("%d{DATE} : %m%n") is used to describe how we'd like information formatted in the log file.  For a detailed list of the special formatting indicators (generally demarcated by the % character), see the javadoc for the log4j PatternLayout class.  In the meantime, here's a table showing some example patterns and how the line log.info("Simple Test Message One") is rendered in a custom log (starting with the pattern used in our script):

PatternOutputNotes
%d{DATE} : %m%n
14 Sep 2015 21:51:21,223 : Simple Test Message One
- %d indicates a date, with {DATE} specifying a log4j pre-canned date format
- %m indicates where the actual message content will be shown
- %n indicates a new line character
%-15d{ABSOLUTE}%p : %m%n
16:25:33,000   INFO : Simple Test Message One
- {ABSOLUTE} is used with %d to specify another log4j pre-canned date format-- this one prints only the time component of the {DATE} default format used in the first example.
- The -15 at the beginning of the date pads the expression, reserving 15 characters for the date and right-padding with spaces if the date is less than 15 characters long.
- %p indicates the priority level of the message (e.g., INFO, DEBUG, etc.).
%26d{ISO8601} : %m%n
   2015-09-19 16:50:08,095 : Simple Test Message One
- {ISO8601} is the last of the log4j pre-canned date formats, printing the date portion with numeric year, month, and day. ISO8601 is also the default format used if none is specified.
- The 26 at the beginning of the date format expression pads the date expression like -15 in the previous example, but the positive value pads the left instead of the right (note the leading spaces in the output).
%d{MM-dd-yyyy HH:mm:ss.SSS} : %.10m%n
09-19-2015 17:31:10.976 : essage One
- In this case we're using a custom format for the date; this one prints the date with numeric month, then day, then year, then prints the time using a decimal point as the divider between seconds and nanoseconds. You can find out more about the date and time pattern characters to use for a custom date format here. According to the log4j javadocs, using a custom format like this could result in a performance hit; they encourage you to use the pre-canned formats instead.
- The .10 before the message specifier is another spacing indicator; this one specifies that if the message is longer than 10 characters, it should be truncated from the front (which is why you only see the last 10 characters in the output).

Once we have our PatternLayout created, we can create our FileAppender, using the PatternLayout as an argument in its constructor.  We put it in context to manage disposing its resources later on in the tear down script:

context.customlogger = new FileAppender(pLayout, "C:\\Temp\\CustomLog\\CustomLog.txt", false)

The first two arguments should be self-explanatory: the first is the layout we want the FileAppender to use and the second is a string giving the path and name of the text file where we want the FileAppender to forward messages-- feel free to change this path as you see fit.  Remember that "\" has a special meaning in string in Java; that's why we have to use the escape sequence "\\" here instead.  The final argument specifies whether we want the messages appended to the text file.  When set to true, any content in the text file generated in previous runs is preserved and information from this run is added to the end of the file.  In this example we're setting the argument to false, so each time we run our suite a new log is created.

The final line in the setup script registers the appender with the default SoapUI log.

log.addAppender(context.customLogger)

Once everything is configured and the appender is registered with the log object, there's nothing special you have to do to send messages to this custom log file-- anything sent to the log within your script is sent to the FileAppender's underlying stream.

As indicated in the table above, the line log.info("Simple Test Message One") in our script results in this output in the custom log file:

14 Sep 2015 21:51:21,223 : Simple Test Message One

Within our tear down script (or whenever we're done with the appender), we have to release the resources being used by the appender, closing the underlying file and the appender itself:

context.customLogger.closeFile()
context.customLogger.close()

I encourage you to play around with the provided starter project to see what can be done with a file appender.  In particular, try making changes to the pattern layout string to see how it controls formatting and affects the custom log's output. 

Jenkins: An Example Project

In this post I'll provide a more detailed example of setting up a project in Jenkins, albeit on a smaller scale than what you would expect to encounter in a real-world situation.  I'm also not going into the specifics of some of the steps (for example, I'm not providing detailed explanations of the batch commands to run MSBuild or NUnit); my primary objective is to give you some idea of the general workflow of a Jenkins project and how its different components can fit together.

The particular scenario covered here involves a small solution consisting of a C# .NET application that's a basic calculator with several methods for basic mathematical operations, along with a library of NUnit tests that check those methods.  The code is maintained in a local Subversion repository.  In my walk-through I'll create a Jenkins job to handle building, testing, and reporting test results whenever there's a change to the SVN repository.

Clicking "New Item" brings up the page below.  In this case, I'm creating a Freestyle Project named "Silly Calc Project".


After clicking OK I'm presented with the main configuration screen for the project.  The page is broken up into a few sections by default.  For this example, the first section where I'll make changes is the Source Code Management section, where I can specify information to integrate a version control system with the project.  CVS and SVN repositories are supported by default; for other version control systems like git, search available Jenkins plug-ins using appropriate keywords.  Here I'm specifying that my repository is an SVN repository and providing its path.  This example uses the svn protocol, but Jenkins supports other protocols including http and https (see this page for more info about supported URL formats).


The Build Triggers section of the configuration page allows me to specify when Jenkins will start processing a build-- or really any job, since a project does not necessarily require a build step.  Default (included with Jenkins "out of the box") build triggers allow me to use other projects as a cue for when to start building this one, kick off the build on a regular scheduled basis, or build when a change is detected in the version control system.  Settings for the third option are illustrated here.


The Build Periodically and Poll SCM options use a syntax based on cron to specify how frequently a build/process is triggered (Build Periodically) or the version control system is polled for changes (Poll SCM).  Jenkins provides some inline help on this syntax (accessed via the help icon next to the text box where the cron expression is entered) or you can Google "cron" to find other explanations online-- Jenkins itself has a link to this Wikipedia entry.  Expressions consists of five parts, corresponding to (from left to right) minutes in an hour, hours in a day based on a 24-hour clock, days in a month, months, and days of the week.  The particular expression above instructs Jenkins to poll SVN from Monday through Friday (corresponding to "1-5" specified for days of the week) in five minute intervals ("H/5" specified for the minutes portion of the expression-- see the suggested cron explanations for details on the meaning of "H" in this case), with no additional restrictions based on hour, day of the month, or month in the year (specified by the "*" wild card character for those parts of the expression).

Now that I've specified when I want my job to start, I have to specify exactly what I want Jenkins to do in the Build configuration section.  When I click on the "Add build step" button, I see build options for Ant and Maven (Java-based build utilities) along with the ability to add shell or Windows batch commands.  This provides a lot of flexibility with Jenkins-- almost any task you can run via a batch command can be performed as part of a project.  Since my sample project was built using C# .NET I need to use a batch command to compile using MSBuild.


It's possible to add more than one batch command, and in this example I still need to add a command to run my NUnit tests once the build is complete.


Note how the paths to the solution (in the MSBuild command-- SillyCalc.sln) and the test library (in the NUnit command-- SillyCalcTest\bin\debug\SillyCalcTest.dll) are not fully qualified.  Each Jenkins project has an associated workspace folder.  Many commands and settings-- like the paths in these Windows batch commands-- are evaluated relative to this workspace folder (Jenkins Help will clearly specify when this is the case).

Finally, I want to publish the results of my tests, a Post-build Action.  Unfortunately, if I click on the "Add post-build action" button with a new Jenkins installation, I see that it's possible to publish JUnit reports, but there's no option available for NUnit reports.  This is one of those cases where the huge library of plug-ins pays off.  A quick search on "NUnit" in the Available tab of the Plugin Manager finds the NUnit plugin.  Once installation of the plug-in is finished, "Publish NUnit test result report" magically appears as an available Post-build Action in the project configuration page.


As with the batch commands above, the path to the NUnit report is relative to the workspace folder.  Given my settings, the report is generated in the workspace folder itself, so I only have to specify the file name.

So now that my Jenkins project is set up, it should detect any errors (as determined by my NUnit tests) that might be introduced in my code.  As an example, say I inadvertently change my calculator's add() method, replacing a + operator with a * operator, and check in the "bad" change to my SVN repository.  After a few minutes Jenkins will 1) poll SVN and recognize that a change was checked in, 2) check out the code in the repository, 3) run MSBuild on the solution, 4) run my NUnit tests on the newly generated build, and 5) publish test results so they're visible within Jenkins:


Again, this is a simple example; in truth this type of error probably would have been caught quickly enough with manual unit testing for a small application of this size.  But extrapolate this scenario out to a large project with many moving parts and interdependencies and many developers or even teams of developers, and you may see the potential benefits of using Jenkins for automation.

Jenkins: An Introduction

I've mentioned Jenkins in passing in a few recent posts, so I thought I'd provide a little more detail about what it is and what it can do for you.  Among other things, Jenkins provides a centralized platform for building and testing software.  It's specifically targeted for use in continuous integration, an iterative approach to development intended to provide rapid feedback to changes in an application, minimizing the time between the introduction of a bug and its detection.  In a typical continuous integration setup after a developer checks in a code change Jenkins would detect it and kick off a build of the software, run tests against the new build, and publish the results of the test-- and do all of this automatically.  Each of the tasks comprising a Jenkins job can be added and configured independently, so, for example, you can choose to run tests independent of the build process and run them on demand, on a schedule, etc.  You can also set up "slave" machines to distribute processing of Jenkins jobs.

You can download a Jenkins installation from http://www.jenkins-ci.org; available packages include a Java WAR (web application archive) or packages covering most major desktop platforms.  Once installed, the Jenkins dashboard is available as a web page on its host machine (on port 8080 by default); here's a screenshot of a typical dashboard with a project already added:


The columns in the projects list should be pretty straightforward for the most part (Name, Last Success, Last Failure, etc.), but extra explanation of the icon-based columns may be helpful.  The first column (simply labelled "S") indicates the status of the last run of this project/job.  The indicator can be blue (indicating no problems), yellow (mixed results: typically, the build step might have completed successfully, but tests failed), or red (severe failure: e.g., the build step failed).  The second column ("W" for "Weather Report") indicates status trends over the last few runs of the project/job-- the weather icon gets "stormier" as more jobs fail and "sunnier" as results improve.  The last column is simply a run button to kick off a job on demand.

Creating a basic Jenkins job involves configuring build options, build tasks, and post-build tasks:

- Build options include setting up code sources and build trigger(s), specifying build dependencies, etc.  Build trigger options allow you to start a new build (and any subsequent tasks including tests) based on changes to code in a source control system, on a scheduled basis, both, neither, etc.

- In addition to actually performing a build of a project's code, build tasks can also include running tests or just about anything else that can be done through the command line (in Windows) or shell.

- Post-build tasks involve processing the results of your build tasks; typical post-build tasks include sending email notifications of build and test results to stakeholders, publishing results, kicking off another project, etc.

Again, Jenkins was created with continuous integration in mind, so configuration settings are very "build-centric"-- but even performing a build is optional; Jenkins can be useful even if you're not involved in continuous integration.  For example, you could use it to monitor the health of a web service, running a set of tests against the service on a scheduled basis, or as a centralized "control center" for web service tests, allowing authorized users to kick them off remotely and review published results.

With its core capabilities alone Jenkins is pretty versatile, but it's also amazingly extensible.  There are hundreds of plug-ins available that can be installed through the Plugin Manager of the Jenkins dashboard itself, many without any disruption to Jenkins (no need to re-start the service):


That's it for an intro to Jenkins; in my next post I'll dig into some of the nuts and bolts of adding a project.

Updated PDF Posts Collection

I hope everybody's been having a happy new year.  This is just a brief post letting everybody know the PDF file on the downloads page should be updated now to include the last two tutorials covering generating xls reports and using the testrunner.  The link on the downloads page now includes the date of the last update as well, which should give you some indication of how up-to-date the file is at any given time.  The example project for the xls report tutorial has also been added to the downloads page.