Chapter 8.2 - Logging (Part 2)

[OneTimeSetUp]
public void BeforeAll()
{
    FW.CreateTestResultsDirectory();
}

[SetUp]
public void BeforeEach()
{
    FW.SetLogger();
    Driver.Init();
    Pages.Init();
    Driver.Goto("https://statsroyale.com");
}

# Adding Log Info and Steps in Our Pages

Then let's add some simple logging to a couple of our classes.

We'll start with the Driver.cs class.

In the Init method, we will say — `FW.Log.Info(“Browser: Chrome”).
We'll then go to our GoTo method and instead of Debug.WriteLine(url), we're going to change this to be FW.Info(url) with the URL we're going to.
Let's scroll down to our Quit method and do `FW.Log.Info(“Close Browser”).

public static void Quit()
{
    FW.Log.Info("Close Browser");
    Current.Quit();
}

Now let's go to our DeckBuilderPage.

I'll do the same thing in here, but instead of Info we’re going to use the Step one.

In our GoTo method we’ll say — FW.Log.Step(“Click Deck Builder link”).
Scroll down to our AddCardsManually method and we'll do the same thing in here — FW.Log.Step(“Click Add Cards Manually link”).
And one more in our CopySuggestedDeck method — FW.Log.Step(“Click Copy Deck Icon”).

public DeckBuilderPage Goto()
{
    FW.Log.Step("Click Deck Builder link");
    HeaderNav.Map.DeckBuilderLink.Click();
    Driver.Wait.Until(drvr => Map.AddCardsManuallyLink.Displayed);
    return this;
}

public void AddCardsManually()
{
    Driver.Wait.Until(drvr => Map.AddCardsManuallyLink.Displayed);
    FW.Log.Step("Click Add Cards Manually link");
    Map.AddCardsManuallyLink.Click();
    Driver.Wait.Until(drvr => Map.CopyDeckIcon.Displayed);
}

public void CopySuggestedDeck()
{
    FW.Log.Step("Click Copy Deck Icon");
    Map.CopyDeckIcon.Click();
}

Open up a terminal and run your tests for the CopyDeck suite.

dotnet test --filter testcategory=copydeck

And then once it's done, if we go in here, we'll actually see that there's a TestResults directory.

Inside of here are the 3 tests that we wrote and each one of them will have their own log file.

If you open one of them up, we'll see the actual contents of everything that we logged.

So that means we now have a TestResults directory for each one of our test runs.

And each test will have its own directory and log file as well.

# Solving Race Conditions

But before we call it a day, did you try running our parallel tests?

Our tests are executing in parallel as expected, but there is only 1 test folder in our TestResults.

So, what happened?

Well, our test is technically a single test method with a single name, so if we are creating our test folders based on the name of the test, then each test case has the same name.

That means that each new test case is overriding the test folder and test log of the previous test case. This is an example of a race condition.

So, what is a race condition?

One definition is that it is an “anomalous behavior due to unexpected critical dependence on the relative timing of events”.

It's a vague way of saying basically that a race condition happens when 2 or more things — threads, processes, requests or whatever — try to work with the same data at the same time.

In our case, we have 3 tests running at the same time and trying to write to a single log file. They're in a race to write to it.

Another good example is having multiple processes trying to set data in a database. One test may be setting the data as another test is trying to read it.

A more lightweight of talking about it is this joke of knock-knock race condition before the person is able to ask “who's there”.

In other words, the joke gets all mixed up because of the timing.

In a more real sense, let's say we had this database here in the middle and we had multiple people trying to add 1 to the database and another person trying to subtract 2 from the database.

If at the same time of all these additions and subtractions happening, I wanted to see what number it actually was, what would the number actually be?

Hence the race condition — because if I get it right after the first person is done, the number is 2.

But what if the negative 2 happened right after the first plus 1, but before the last plus 1. That's when I asked for the data.

You can see how things could get more complicated and bugs in race conditions are pretty hard to find.

We're going to solve this by forcing the workers to wait in a line when creating the directories and log files, but we'll also be giving each test case its own test folder and log by using a unique ID.

We're going to create a “lock”.

A Lock is a mechanism that forces the workers to wait in line until the current worker exits the Lock.

Very much like a prize room where 1 person can enter at a time, grab their prize and once they leave the next person could enter the room to pick their prize.

We'll start by creating that “room” in our FW.cs file.

It’s going to be a new object called “_setLoggerLock”.

private static object _setLoggerLock = new object();

And now we'll use the room and put everything inside of it.

We can grab all of this [from our SetLogger method].

Now we're going to “lock” on our _setLoggerLock and paste everything inside.

Let me grab these and format them.

public static void SetLogger()
{
    lock(_setLoggerLock)
    {
        var testResultsDirectory = WORKSPACE_DIRECTORY + "TestResults";
        var testName = TestContext.CurrentContext.Test.Name;
        var fullPath = $"{testResultsDirectory}/{testName}";

        CurrentTestDirectory = Directory.CreateDirectory(fullPath);
        _logger = new Logger(testName, CurrentTestDirectory.FullName + "/log.txt");
    }
}
private static object _setLoggerLock = new object();

Next, we'll check to see if the test folder already exists.

If it does, that means this is a test method with multiple test cases. We will still use the test name, but we'll also include the unique ID of the test case and append that to the name.

Let's add our if statement first for when the directory exists. Let's grab this and paste it in.

So, if it exists that we know that it's a test case method so let's add an ID here. We're going to use the TestContext.CurrentContext.

And then the test has its own ID already, so we're going to leverage that.

if (Directory.Exists(fullPath))
{
    CurrentTestDirectory = Directory.CreateDirectory(testPath + TestContext.CurrentContext.Test.ID);
}

And now our else condition.

Current directory is just going to be a regular directory, so directory dot create directory with just the full path.

else
{
    CurrentTestDirectory = Directory.CreateDirectory(fullPath);
}

Now let's go to our test suite Royal.Tests.

We already did it for the CopyDeckTest.cs.

Let's go to our CardTests.cs.

And in here we need to include that [OneTimeSetUp] and this was FW.CreateTestResultsDirectory.

And then inside of here [our [SetUp] method] we add FW.SetLogger.

Open up a terminal, run those tests.

We want to do the test category of “cards” and use NUnit to set the number of test workers — have it be like 2 or 3, or something.

dotnet test --filter testcategory=cards –Nunit.NumberOfTestWorkers=3

Run the tests again and we'll see what we get inside of the test results directory.

Hey, what I'm talking about, it looks like we got everything we were expecting.

So, you'll see that all of these look like they have the same name.

They do end with the ID that we used, but otherwise each one has their own log file as well.

You see the timestamps are a little bit different than each of them.

Awesome, we did it.

So that's what I'm talking about. Login away concurrently. Thread safe.

Good job!

Resources

Git Repo: Chapter 8 - Logging

Add AI to your existing test scripts in minutes!