Monday, 13 October 2014

Date and time plugin for Visual Studio Web Test

A Visual Studio web performance test required the current date and time to be written to a context parameter for inserting into a request. Writing the current date and time to a string is straightforward and it is simple to write a string into a content parameter within the web test plugin.

using Microsoft.VisualStudio.TestTools.WebTesting;

namespace Plugins
{
    [System.ComponentModel.DisplayName(
        "Save current date time to context parameter")]
    [System.ComponentModel.Description(
        "Saves date time of call to a context parameter")]
    public class DateTimeToContext : WebTestRequestPlugin
    {
        [System.ComponentModel.DisplayName("Parameter name")]
        [System.ComponentModel.Description("Name of context parameter.")]
        public string ParameterName { get; set; }

        [System.ComponentModel.DisplayName("Date-time format")]
        [System.ComponentModel.DefaultValue("yyyy-MM-dd HH:mm:ss.fff")]
        public string DateTimeFormat { get; set; }

        public override void PreRequest(object sender, PreRequestEventArgs e)
        {
            string now 
                = string.IsNullOrWhiteSpace(DateTimeFormat) 
                ? System.DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")
                : System.DateTime.Now.ToString(DateTimeFormat);

            e.WebTest.AddCommentToResult(string.Format(
                "Setting context parameter '{0}' to '{1}'", ParameterName, now));
            e.WebTest.Context[ParameterName] = now;
        }
    }
} 
I like to add calls of e.WebTest.AddCommentToResult(...) at significant places in plugins, particularly when developing a plugin or a web test. In this case it simply reports the values that are set into the web test log.

Friday, 11 April 2014

Logging web test details to a text file

My next approach to logging was to by writing direct to text files. This worked fine and I was able to write large number of lines without obvious problems. I was concerned that opening and closing the files within each test case would be too much load, so I arranged to open the text file once per agent computer. A C# lock on the output file synchronises the multiple writers coming from the many test cases.

The code is written to have only one instance, so its contructor is private. The main class data items are the lock, the actual instance of the class and the output stream.

    public class SingletonWriter
    {
        private static object myLock = new object();
        private static SingletonWriter mySingleton = null;

        StreamWriter outStream;


The constructor generates the file name and creates the corresponding output stream.

        private SingletonWriter(string AgentId)
        {
            string streamName

                = "TestStatusAsComment."
                + System.DateTime.Now.ToString("yyyy-MM-dd.HHmm.")
                + AgentId + ".log";

            outStream = new StreamWriter(streamName, true);

                // true means append to an existing file.
            outStream.WriteLine("Start of output");
            outStream.Flush();
        }


Writeline is the main interface. It needs to access some parts of the web test details, it writes a simple string. After each write the stream is flushed.

        public static void WriteLine(PostWebTestEventArgs e,
                                     string line)
        {
            lock ( myLock ) {
                if ( mySingleton == null ) {
                    string AgentId =

                       ContextReader.GetContextField(
                           e, "$AgentId", "00");
                    mySingleton = new SingletonWriter(AgentId);
                }

                mySingleton.outStream.WriteLine(line);
                mySingleton.outStream.Flush();
            }
        }

Closing the stream allows one test run to generate multiple output files, if the created filenames are different. The stream creation above will append to an existing file rather than overwrite it.

        public static void Close()
        {
            lock ( myLock ) {
                if ( mySingleton != null ) {
                    mySingleton.outStream.WriteLine(

                       "End of output");
                    mySingleton.outStream.Close();
                    mySingleton = null;
                }
            }
        }
    }



Having got a write line routine it is a simple matter to use it in a plugin. The code below writes some details of the test case and the date, plus the contents of one context variable. An extra property is added to allow output from all test cases, or just those that are not passing at the time of the call.

public class WriteTestStatusAsComment : WebTestPlugin
{
    [System.ComponentModel.DisplayName("Write status for all tests")]
    [System.ComponentModel.Description("Only write for failing tests when false.")]
    [System.ComponentModel.DefaultValue("false")]
    public bool WriteStatusForAllTests { get; set; }

    [System.ComponentModel.Category("Additional data")]
    [System.ComponentModel.Description("Include value of this context variable, if any")]
    public string Context1 { get; set; }

    private StringBuilder sb;

    public override void PostWebTest(object sender, PostWebTestEventArgs e)
    {
        if ( WriteStatusForAllTests || e.WebTest.Outcome != Outcome.Pass ) {
            sb = new StringBuilder();

            sb.Append(System.DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff "));
            sb.Append(e.WebTest.Outcome.ToString());
            sb.Append(" Iter: ");
            sb.Append(ContextReader.GetContextField(e, "$WebTestIteration"));
            sb.Append(" UserId: ");
            sb.Append(ContextReader.GetContextField(e, "$WebTestUserId"));
            sb.Append(' ');
            sb.Append(e.WebTest.Name);

            AddContext(e, Context1);

            string message = sb.ToString();
            e.WebTest.AddCommentToResult(message);

            SingletonWriter.WriteLine(e, message);
        }
    }
}


Wednesday, 18 September 2013

Unable to add comments to web performance logs

Continuing the topic of logging data from Visual Studio load tests. Previously I wrote about trying to extract all the web performance test logs from a load test. For this to be useful the logs needed to include more data about the test.

Both web performance tests and load tests support plugins. These allow user written code to be called at various points in the execution of a test. One of the routines that web test plugins can call is AddCommentToResult, so all we need to do is gather some data, format it into a string and write it out as a comment at the end of the web test. Unfortunately that did not work as expected. Comments are successfully written when the web performance test is run, but when run as part of a load test the comments are not written. See this MSDN forum topic for more details of the issue. This was found with Microsoft Visual Studio Ultimate 2012,  Version 11.0.60315.01 Update 2 with Microsoft .NET Framework Version 4.5.50709

Wednesday, 28 August 2013

Collecting error reports from Visual Studio load tests

Generally Visual Studio load tests that call web performance tests are written to follow a happy path through the application. The goal is to have tests that are expected to pass so any errors are due to faults in the system under test. When the tests are data driven the data should be screened to exclude any values that always cause failures. Unfortunately that cannot always be achieved. On a recent project the data could not be screened before use. We had many discussions about attempting database resets between test executions but in the end we had to accept that some data records might be invalid.

Given that some tests might fail the project manager wanted the test results to include details of which tests failed, at what time, with what values from the data source, and with what error code. At first sight that data is readily available because a load test keeps logs for up to 200 (the default number) failing tests. These 200 logs could be studied to extract the details, but there is no easy way. Each log file must be opened by clicking on a link and then clicking through the various parts of the web test log to find the information. To analyze all 200 logs would require opening 200 log files, exploring 200 files and closing 200 files. That is much too much mouse clicking and mouse waving. It involves too much manual activity making it very error prone.

Trying to extract the log file details by program appears possible. The log files are stored in the SQL table 'LoadTestTestLog' within the load test results database. Using SQL the results can be exported to a CSV file where one field of each record contains a hexadecimal dump of the log file. Converting the hex to bytes is easy and viewing the results in a simple text editor shows encoded data with lots of embedded ASCII text. Some of that text appears to be parts of the log file. Using a "strings" command leaves the useful text hidden by a mass of other text.

The record appears to be a serialized class. My attempts to deserialize the data have been unsuccessful. The initial error is that the DLL required to decode the file cannot be found. So this approach does not work. Of course, even if it did work this approach would only show details of the first 200 failing tests. The number of saved logs could be increased but as each log file record is large that might mean filling up the database if several test runs were wanted.

Another approach is wanted and that will be the subject of another blog entry.

Wednesday, 7 August 2013

Small Steps in Software

Small Steps in Software gives me an opportunity to write a few words from time to time about the software I am working on. This first post is a bit of self congratulation about success in software related examination rather than about actual software. Today I sat and passed the Microsoft 70-498 Delivering Continuous Value with Visual Studio 2012 Application Lifecycle Management. One of my work colleagues took the same exam today and passed. So it was a good day for our employer who paid the fees and gave us some time to study.