Monday, May 9, 2022

Latest Azure PaaS Sitecore Logs using a single line of PowerShell

If you’re anything like me, you probably don’t have a passion for manually digging through the series of hundreds of randomly dated folders that look like this in search of the latest Sitecore logs:

Hello darkness, my old friend

Although several tools and approaches are available (including this nifty tool credited to fellow Sitecore MVP Kiran Patil - as well as some of my own previous posts from 2018 and 2019 covering this topic), I've recently adopted a different strategy that's proved to be successful across several Sitecore PaaS clients for quickly obtaining the latest physical Sitecore log for a given server. 

The post-worthy kicker?  It's one line of PowerShell:

$kuduHost = ""; Write-Output "`n[ LATEST SITECORE LOGS ]`n"; $array = @(); Get-ChildItem "C:\home\site\wwwroot\app_data\logs" -File -Recurse | Where-Object { $_.FullName -match "azure.*.txt" -and $_.LastWriteTime -gt (Get-Date).AddHours(-12) } | ForEach-Object { $path = $_.FullName.replace("C:\home\site\wwwroot\app_data\logs\", "$kuduHost/api/vfs/site/wwwroot/App_Data/logs/"); $array += "`n[$($_.LastWriteTime)]`n$path`n"}; $array | Sort-Object $_.LastWriteTime | Select-Object -Last 3


Okay, it's...kind of a long one-liner...but one line nevertheless 

The above example outputs direct links to the latest three physical Sitecore log files, which match the pattern 'azure.*.

In practice, the desired file can be highlighted from the console and at which point you can copy the URL or open it in a new tab.

Let's break it down

The first line defines a variable for the KUDU host you're using:

$kuduHost = ""

The second line outputs a (wholly arbitrary and unnecessary) title:

Write-Output "`n`[ LATEST SITECORE LOGS ]`n"

The third line represents an array variable aptly named `$array` (because I'm clever):

$array = @();

This is where it gets exciting. This Get-ChildItem cmdlet gets all files recursively under the site's `\App_Data\logs` location:

Get-ChildItem "C:\home\site\wwwroot\app_data\logs" -File -Recurse

We can pipe in a Where-Object cmdlet to filter only file names that match 'azure.*.txt' (or if you want all log types - Publishing, Crawling, Dianoga, SPE, etc. - *.txt) and provide a 12-hour threshold against the `LastWriteTime` property:

Get-ChildItem "C:\home\site\wwwroot\app_data\logs" -File -Recurse |
Where-Object {$_.FullName -match "azure.*.txt" -and $_.LastWriteTime -gt (Get-Date).AddHours(-12)}

We can then pipe in a ForEach-Object cmdlet to iterate through each file:

Get-ChildItem "C:\home\site\wwwroot\app_data\logs" -File -Recurse | Where-Object { $_.FullName -match "azure.*.txt" -and $_.LastWriteTime -gt (Get-Date).AddHours(-12) } | ForEach-Object { $path = $_.FullName.replace("C:\home\site\wwwroot\app_data\logs\", "$kuduHost/api/vfs/site/wwwroot/App_Data/logs/"); $array += "[$($_.LastWriteTime)]`n$path`n"}

Notice that in the ForEach-Object cmdlet, we create a variable called `$path` and set it to a string that takes the file's FullName and replaces the 'system path' portion, and replace it with our `$kuduHost` variable concatenated to `/api/vfs/site/wwwroot/App_Data/logs/`.

$path = $_.FullName.replace("C:\home\site\wwwroot\app_data\logs\", "$kuduHost/api/vfs/site/wwwroot/App_Data/logs/")

Without this string replacement, we'd only get the system path for the files in the dataset, which would still require navigating to the file manually:

Also, within the ForEach-Object cmdlet, a formatted string containing the LastWriteTime and the `$path` variable is added to the `$array` variable:

$array += "[$($_.LastWriteTime)]`n$path`n"

The `n used above allows for line breaks.

After the files have been processed, the `$array` variable is called and sorted by LastWriteTime.

A Select-Object cmdlet is piped in to limit the number of results to 3:

$array | Sort-Object $_.LastWriteTime | Select-Object -Last 3

By combining these together, eliminating spaces, and adding semi-colons to separate commands, we've got our one-liner! 🕺

Bonus: IIS HTTP Request Logs

Using the same approach with a few modifications, the application's raw IIS HTTP Request Logs can also be obtained (differences bolded below):

$kuduHost = ""; Write-Output "`n[ LATEST IIS LOGS ]`n"; $array = @(); Get-ChildItem "C:\home\LogFiles\http\RawLogs" -Recurse | Where-Object { $_.FullName -match ".log" -and $_.LastWriteTime -gt (Get-Date).AddHours(-12) } | Sort-Object $_.LastWriteTime | ForEach-Object { $path = $_.FullName.replace("C:\home\LogFiles\http\RawLogs\", "$kuduHost/api/vfs/LogFiles/http/RawLogs/"); $array += "[$($_.LastWriteTime)]`n$path`n"}; $array | Sort-Object $_.LastWriteTime | Select-Object -Last 3

Final Thoughts

You can generate variations of this one-liner by changing the various variables, which can be shared with the rest of your development/troubleshooting team and readily ready to copy from an internal Wiki:

Feel free to use and modify the script as you see fit. 🚀

Friday, April 1, 2022

'Tracker.Current.Session.Interaction should not be null' CountryCondition

Uh oh. 

The following errors are heavily present on my client's content delivery servers:

ERROR Evaluation of condition failed. Rule item ID:
Unknown, condition item ID: {9A4BEB4B-4B0F-4392-A798-124CEC8AADA4}

Exception: Sitecore.Framework.Conditions.PostconditionException

Message: Postcondition 'Tracker.Current.Session.Interaction should not be null' failed.

Source: Sitecore.Framework.Conditions
at Sitecore.Framework.Conditions.EnsuresValidator`1.ThrowExceptionCore(String condition, String additionalMessage, ConstraintViolationType type)
at Sitecore.Framework.Conditions.Throw.ValueShouldNotBeNull[T](ConditionValidator`1 validator, String conditionDescription)
at Sitecore.Framework.Conditions.ValidatorExtensions.IsNotNull[T](ConditionValidator`1 validator)
at Sitecore.ContentTesting.Rules.Conditions.CountryCondition`1.Execute(T ruleContext)
at Sitecore.Rules.Conditions.WhenCondition`1.Evaluate(T ruleContext, RuleStack stack)
at Sitecore.Rules.Conditions.OrCondition`1.Evaluate(T ruleContext, RuleStack stack)
at Sitecore.Rules.Conditions.WhenRule`1.Execute(T ruleContext)
at Sitecore.Rules.Conditions.WhenCondition`1.Evaluate(T ruleContext, RuleStack stack)
at Sitecore.Rules.RuleList`1.Run(T ruleContext, Boolean stopOnFirstMatching, Int32& executedRulesCount)

We're talking thousands upon thousands of these errors. 

The error references a GUID we can use to determine the context of this:
Moreover, the error's message hints are what ultimately causes the error to trigger: 
Tracker.Current.Session.Interaction should not be null
For context, the GUID refers to the following out-of-the-box Sitecore item:
/sitecore/system/Settings/Rules/Definitions/Elements/Predefined Rules/Predefined Rule
Nothing to see here...

After digging in, I found that the client had configured personalization on a Controller Rendering for their site's homepage component rendering so that depending on the user’s country, unique content is presented. They've implemented the following Predefined rules on the rendering:

- visitor is located in the Asia Pacific region
- visitor is located in the UK
    - or where visitor is equal to the United Kingdom
- where visitor is located in Continental Europe

These are custom rules they've added that categorize a list of countries into a region they want to target.

For example, the `visitor is located in the Asia Pacific region` looks like this:
where the country is equal to Australia
or where the country is equal to Brunei Darussalam
or where the country is equal to China
or where the country is equal to Hong Kong
or where the country is equal to Singapore
or where the country is equal to Taiwan
or where the country is equal to Thailand
or where the country is equal to New Zealand
or where the country is equal to Qatar
or where the country is equal to Turkey
or where the country is equal to Malaysia
or where the country is equal to Russian Federation
or where the country is equal to India
or where the country is equal to Indonesia
or where the country is equal to United Arab Emirates
or where the country is equal to Philippines
or where the country is equal to Israel
or where the country is equal to Pakistan
or where the country is equal to Saudi Arabia
or where the country is equal to Vietnam
or where the country is equal to Japan

Each country has been defined using the out-of-the-box `GeoIP` > `where the country compares to specific countries` condition template.

This line in the error denotes that the `CountryCondition` is the culprit in regards to the recurring error:
at Sitecore.ContentTesting.Rules.Conditions.CountryCondition`1.Execute(T ruleContext)
According to a reflection of the `Sitecore.ContentTesting.Rules.Conditions` namespace in Sitecore.ContentTesting.dll for v10.0.0, this series of checks in the first few lines of the `CountryCondition<T> : VisitCondition<T> where T : RuleContext` class's Execute() method:


My hunch was that the last check was causing the failure, and instead of failing silently, it throws an error - specifically often in cases where bot-like traffic is involved. 
Condition.Ensures<CurrentInteraction>(Tracker.Current.Session.Interaction, "Tracker.Current.Session.Interaction").IsNotNull<CurrentInteraction>();

To quell the flood of errors initially, I applied a new stand-alone rule preceding each existing visitor is rule located in {REGION_NAME} region called `visitor is human` (also out-of-the-box) to attempt to deflect bots and spam where a country code or identifiable contact/interaction is unlikely to yield a country (which would result in an error):

After applying these changes and publishing them, we see those errors disappear entirely from the error logs.  However, the introduction of the `visitor is human` rule proceeding the rest had an unintended effect: first-time visitors always failed this first condition, causing them to only see the personalized rendering after reloading the page. Removing the rule enabled users to receive the personalized rendering on the first load but reintroduced the flood of errors.

It seemed that instances where `Tracker.Current.Session.Interaction` is null may be caused by bot traffic according to:

Given that this is version 10.0.0, this particular bug should have been resolved in all versions above 8.1.

Upon decompiling and comparing the GetTracker : CreateTrackerProcessor > Process() override in Sitecore.Support.424667.81.dll for v8.1+ to the 10.0.0 Sitecore.Analytics.dll's GetTracker : CreateTrackerProcessor > Process method, there's one notable difference:



It was unclear if we need a similar patch to implement `args.set_Tracker(new DefaultTracker());` in the Process() method.

I raised the question with Sitecore Support to explore one of two resolutions:

1) A patch for suppressing errors in Sitecore.ContentTesting.Rules.Conditions.CountryCondition's Execute() method, when the `Condition.Ensures<CurrentInteraction>(Tracker.Current.Session.Interaction, "Tracker.Current.Session.Interaction").IsNotNull<CurrentInteraction>();` is not satisfied (perhaps by returning false).


2) An override patch for the tracker creation similar to the hotfix.

Sitecore Support was able to reproduce the reported behavior in a clean local instance of Sitecore 10.0.0 (Initial Release) without involving any of our specific customizations. They registered the issue as a bug in their bug tracking system (future reference number 456739).

Sitecore's official statement regarding the bug: 
The reported behavior occurs because Sitecore.Rules.Conditions.WhenRule class inherits CanEvaluate() method from Sitecore.Rules.Conditions.RuleCondition class which always returns true. That is why the rule is not skipped so the evaluation continues and leads to the exception. 
In order to workaround the issue, please try to avoid the usage of Conditional renderings rules.
Please assign conditions to your renderings directly without wrapping them into conditional renderings rule.
In this case, Sitecore will trigger CanEvaluate method related to the specific condition, so the condition will be skipped.

I ended up pursuing the following approach myself:

  1. Decompiled the `Sitecore.ContentTesting.dll` and copied the Sitecore.ContentTesting.Rules.Conditions.CountryCondition class into our solution called `CountryConditionOverride`.  I used Telerik JustDecompile for this. 

  2. Commented the offending line (48) and replaced it with a simple null check that returns false.

  3. Enabled the custom override class by updating the `Type` field on the following default Sitecore item and published it:
Field: Script (section) > Type 
Old value:  `Sitecore.ContentTesting.Rules.Conditions.CountryCondition,Sitecore.ContentTesting`
New value: `Foundation.Overrides.Rules.Conditions.CountryConditionOverride, Foundation.Overrides`

The final override class:

This resolves the issue with erroneous error log entries while retaining the expected Country condition functionality when the `Tracker.Current.Session.Interaction` happens to not be null.

I've shared my resolution with Sitecore Support and will keep an eye on an official hotfix (reference 456739), which I will share once it's available. 

Hopefully, in the meantime, this helps someone out there in a similar scenario!