Debugging blank SSRS report caused by SecurityException

I was testing reports for SQL Server Reporting Services on a new computer, but the results were blank and no relevant error messages were logged by SSRS.

 

Investigated by using procdump to log exception messages from the IIS worker process with:

procdump.exe -f "" -l -e 1 ReportingServicesService.exe

Part of the result was:

[13:22:13] Exception: E0434F4D.System.Security.SecurityException ("Request for the permission of type 'System.Net.WebPermission, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089' failed.")
[13:22:13] Exception: E0434F4D.System.Security.SecurityException ("Request for the permission of type 'System.Security.Permissions.SecurityPermission, mscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089' failed.")

 

I knew that the reports performed HTTP/web service calls from VB code, so I had to modify rssrvpolicy.config to allow this.

It can be done by:

1. Appending a named permission set with both execution and web permission like:

<PermissionSet class="NamedPermissionSet"
version="1"
Name="ExecutionAndWebPermission"
Description="A special permission set that grants execution and web permission for specific site(s).">
  <IPermission class="SecurityPermission" version="1" Flags="Execution" />
  <IPermission class="WebPermission" version="1">
    <ConnectAccess>
      <URI uri="http://localhost/Test/ReportingUtilityService.svc"/>
    </ConnectAccess>
  </IPermission>
</PermissionSet>

 

2. Modifying the CodeGroup with Name=”Report_Expressions_Default_Permissions”

From:

PermissionSetName="Execution"

To:

PermissionSetName="ExecutionAndWebPermission"

 

3. Restarting Reporting Services.

 

I decided to verify that this was the issue before performing the changes.

Therefore I attached WinDbg (x64) to ReportingServicesService.exe and configured event filters to break on CLR exceptions.

 

Refreshed the report again and the first exception was thrown.

Checked the exception with:

!PrintException

 

The result was a very detailed (and useful) message, that confirmed the suspected issue:

Exception object: 0000000460198410
Exception type: System.Security.SecurityException
Message: Request for the permission of type 'System.Net.WebPermission, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089' failed.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 8013150a
SecurityException Message:
The action that failed was:
Demand
The type of the first permission that failed was:
System.Net.WebPermission
The first permission that failed was:
<IPermission class="System.Net.WebPermission, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
version="1">
<ConnectAccess>
<URI uri="http://localhost/Test/ReportingUtilityService\.svc"/>
</ConnectAccess>
</IPermission>

The demand was for:
<IPermission class="System.Net.WebPermission, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
version="1">
<ConnectAccess>
<URI uri="http://localhost/Test/ReportingUtilityService\.svc"/>
</ConnectAccess>
</IPermission>

The granted set of the failing assembly was:
<PermissionSet class="System.Security.PermissionSet"
version="1">
<IPermission class="System.Security.Permissions.SecurityPermission, mscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
version="1"
Flags="Execution"/>
<IPermission class="System.Security.Permissions.StrongNameIdentityPermission, mscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
version="1"
PublicKeyBlob="..."
Name="expression_host_..."
AssemblyVersion="1.0.0.0"/>
<IPermission class="System.Security.Permissions.ZoneIdentityPermission, mscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
version="1"
Zone="MyComputer"/>
</PermissionSet>

The assembly or AppDomain that failed was:
expression_host_..., Version=12.2.6020.0, Culture=neutral, PublicKeyToken=null
The method that caused the failure was:
System.Object CallWebService(System.String, System.String)
The Zone of the assembly that failed was:
MyComputer

 

After modifying rssrvpolicy.config and restarting Reporting Services the issue was resolved.

Debugging endless loop caused by missing SignalR performance counters

I recently experienced a problem with an IIS website:

After changing and building code, the site would hang indefinitely at startup.

It seemed like an endless loop, because CPU activity was high.

 

One workaround was to reset IIS with:

iisreset

Then the site became functional until the next change + build.

 

However I decided to find the cause of the problem and a real solution.

 

I checked the process activity for w3wp.exe with Process Monitor:

These parts of the registry were continually accessed:

process_monitor_w3wp_registry_signalr_performance

HKLM
HKLM\SYSTEM\CurrentControlSet\Services\SignalR\Performance
HKLM\System\CurrentControlSet\Services\SignalR\Performance

 

At this point I should have checked if the system actually had SignalR performance counters installed…

 

However I decided to examine the situation further by attaching WinDbg (x64) to the w3wp.exe process.

 

Because I was suspecting an endless loop I decided to check the thread CPU activity with:

!runaway

Part of the result was:

User Mode Time
Thread       Time
6:26cc      0 days 0:05:39.750
15:2e00      0 days 0:00:11.187
13:27b0      0 days 0:00:06.718

 

Thread 6 was definitely the one with the most activity, so I switched to that with:

~6s

 

Then checked the .NET call stack with:

!clrstack

Part of the result was:

OS Thread Id: 0x26cc (6)
Child SP               IP Call Site
000000f1a0c6b158 00007ff98b60b1a6 [HelperMethodFrame: 000000f1a0c6b158] System.Security.SecurityRuntime.GetSecurityObjectForFrame(System.Threading.StackCrawlMark ByRef, Boolean)
000000f1a0c6b260 00007ff98a4b584c System.Security.SecurityRuntime.RevertAssert(System.Threading.StackCrawlMark ByRef)
000000f1a0c6b290 00007ff98a4b9e3d System.Security.PermissionSet.RevertAssert()
000000f1a0c6b2c0 00007ff989cd5e6d System.Diagnostics.PerformanceCounterLib.FindCustomCategory(System.String, System.Diagnostics.PerformanceCounterCategoryType ByRef)
000000f1a0c6b310 00007ff989cd5db8 System.Diagnostics.PerformanceCounterLib.FindCustomCategory(System.String, System.Diagnostics.PerformanceCounterCategoryType ByRef)
000000f1a0c6b380 00007ff989cd735c System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String, System.String)
000000f1a0c6b3e0 00007ff989cdd1af System.Diagnostics.PerformanceCounter.InitializeImpl()
000000f1a0c6b450 00007ff989cdc35f System.Diagnostics.PerformanceCounter..ctor(System.String, System.String, System.String, Boolean)
000000f1a0c6b4a0 00007ff92f81b7b5 Microsoft.AspNet.SignalR.Infrastructure.PerformanceCounterManager.LoadCounter(System.String, System.String, System.String, Boolean)
000000f1a0c6b550 00007ff92f81b606 Microsoft.AspNet.SignalR.Infrastructure.PerformanceCounterManager.SetCounterProperties()
000000f1a0c6b5c0 00007ff92f81b2d7 Microsoft.AspNet.SignalR.Infrastructure.PerformanceCounterManager.Initialize(System.String, System.Threading.CancellationToken)
000000f1a0c6b640 00007ff92f81a23b Microsoft.AspNet.SignalR.Hosting.HostDependencyResolverExtensions.InitializeHost(Microsoft.AspNet.SignalR.IDependencyResolver, System.String, System.Threading.CancellationToken)
000000f1a0c6b680 00007ff92f81859b Owin.OwinExtensions.UseSignalRMiddleware[[System.__Canon, mscorlib]](Owin.IAppBuilder, System.Object[])
000000f1a0c6b770 00007ff92f818147 Owin.OwinExtensions+c__DisplayClass1.b__0(Owin.IAppBuilder)
000000f1a0c6b7b0 00007ff92f816c22 Owin.MapExtensions.Map(Owin.IAppBuilder, Microsoft.Owin.PathString, System.Action`1)
000000f1a0c6b800 00007ff92f816993 Owin.MapExtensions.Map(Owin.IAppBuilder, System.String, System.Action`1)
000000f1a0c6b850 00007ff92f816814 Owin.OwinExtensions.MapSignalR(Owin.IAppBuilder)

 

After continuing and breaking execution a few times I was seeing similar call stacks.

I needed to identify the endless loop.

 

Experimented by setting breakpoints from the above call stack.

 

Set a single breakpoint at:

00007ff989cd735c System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String, System.String)

With:

bc *
bp 00007ff989cd735c

Result: Breakpoint was continually hit.

 

Set a single breakpoint at:

00007ff989cdd1af System.Diagnostics.PerformanceCounter.InitializeImpl()

With:

bc *
bp 00007ff989cdd1af

Result: breakpoint was not hit within 1 minute.

 

This indicated that the endless loop was in:

System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String, System.String)

 

I used ILSpy to decompile the method and noticed this loop:

for (CultureInfo cultureInfo = CultureInfo.CurrentCulture; cultureInfo != CultureInfo.InvariantCulture; cultureInfo = cultureInfo.Parent)
{
    performanceCounterLib = PerformanceCounterLib.GetPerformanceCounterLib(machine, cultureInfo);
    if (performanceCounterLib.IsCustomCategory(category))
    {
        return true;
    }
}

 

I noted that the loop condition likely continued to be true.

And that performanceCounterLib.IsCustomCategory(category) most likely continued to be false.

This was likely the endless loop I was looking for.

 

I set an additional breakpoint with:

!bpmd   System.dll   System.Diagnostics.PerformanceCounterLib.IsCustomCategory

Messages from WinDbg:

Found 2 methods in module 00007ff989421000...
MethodDesc = 00007ff989524020
MethodDesc = 00007ff989524040
Setting breakpoint: bp 00007FF989CD73EB [System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String)]
Setting breakpoint: bp 00007FF989CD727A [System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String, System.String)]
Adding pending breakpoints...

 

However when continuing only breakpoint 0 was hit, further indicating that the endless loop occured inside PerformanceCounterLib.IsCustomCategory(…).

 

Decided to look for the CultureInfo object in the loop.

 

Checked the call stack including locals and parameters with:

clrstack -a

Top part of the call stack was:

OS Thread Id: 0x26cc (6)
Child SP               IP Call Site
000000f1a0c6b380 00007ff989cd735c System.Diagnostics.PerformanceCounterLib.IsCustomCategory(System.String, System.String)
PARAMETERS:
machine (<CLR reg>) = 0x000000f4a155df18
category (<CLR reg>) = 0x000000f4a1584228
LOCALS:
<CLR reg> = 0x000000f1a158f130

 

Examined the local reference with:

!DumpObj /d 000000f1a158f130

Part of the result was:

Name:        System.Globalization.CultureInfo
MethodTable: 00007ff98a701420
EEClass:     00007ff98a111e48
Size:        128(0x80) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT    Field   Offset                 Type VT     Attr            Value Name
00007ff98a6ed6f8  4001208       74       System.Boolean  1 instance                1 m_isReadOnly
00007ff98a6e0698  4001209        8 ...ation.CompareInfo  0 instance 000000f1a1593b40 compareInfo
...
...
00007ff98a6ed6f8  4001212       75       System.Boolean  1 instance                0 m_isInherited
00007ff98a6ed6f8  4001213       76       System.Boolean  1 instance                1 m_isSafeCrossDomain
00007ff98a7003d0  4001214       70         System.Int32  1 instance                2 m_createdDomainID
00007ff98a701420  4001215       40 ...ation.CultureInfo  0 instance 0000000000000000 m_consoleFallbackCulture
00007ff98a6fda88  4001216       48        System.String  0 instance 000000f1a1551420 m_name
00007ff98a6fda88  4001217       50        System.String  0 instance 000000f1a1551420 m_nonSortName
00007ff98a6fda88  4001218       58        System.String  0 instance 000000f1a1551420 m_sortName
00007ff98a701420  4001223       60 ...ation.CultureInfo  0 instance 000000f1a158f130 m_parent
...
...

 

Noticed that m_parent pointed to itself.

 

Cleared all breakpoints with:

bc *

Set another breakpoint with:

!bpmd   System.dll   System.Diagnostics.PerformanceCounterLib.FindCustomCategory

 

This breakpoint was continually hit as expected.

 

Then checked the PerformanceCounterLib.FindCustomCategory(…) method with ILSpy.

Noticed that the method accessed the registry and that the return value depended on what was found.

 

Searched online for: HKLM\System\CurrentControlSet\Services\SignalR\Performance

And found this article: http://www.asp.net/signalr/overview/performance/signalr-performance

 

Based on the article I decided to install SignalR performance counters by:

1. Installing the NuGet package: signalr.utils

2. Then installing the SignalR performance counters with:

SignalR.exe ipc

 

This was the solution!

After continuing execution, the loop ended and site initialization continued normally.

(The issue occured with version 2.2.1 of SignalR and version 4.6.1 of .NET, but targeting version 4.5)

Conclusion

A site using SignalR can hang with an endless loop when initializing, if the SignalR performance counters are not installed.

A combination of tools like Process Monitor, ILSpy and WinDbg can be used to discover the cause of an endless loop in 3rd party or framework code.

Debugging #Error in SSRS report caused by missing function overload

While testing a modified SSRS report I noticed that certain values were not shown, only the message:

#Error

 

Neither the ReportServerService__*.log or ExecutionLog* database views contained any clues about the cause.

 

I used procdump to log exception messages from ReportingServicesService.exe with:

procdump.exe -f "" -l -e 1 ReportingServicesService.exe

Part of the result was:

[13:46:39] Exception: E0434F4D.System.InvalidOperationException ("Nullable object must have a value.")
[13:46:39] Exception: E0434F4D.System.FormatException ("Input string was not in a correct format.")
[13:46:39] Exception: E0434F4D.System.FormatException ("Input string was not in a correct format.")
[13:46:39] Exception: E0434F4D.System.InvalidCastException ("Conversion from string "Nullable object must have a valu" to type 'Decimal' is not valid.")

 

These exceptions were unexpected and puzzling. Additional examination was required.

 

I attached WinDbg (x64) to ReportingServicesService.exe and configured event filters to break on CLR exceptions.

 

Refreshed the report again and the first exception was thrown.

Verified the exception with:

!PrintException

The result was:

Exception object: 000000030d4c2f90
Exception type: System.InvalidOperationException
Message: Nullable object must have a value.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131509

 

Checked the .NET call stack with:

!clrstack

Part of the result was:

Child-SP         RetAddr          Call Site
0000000016d1b150 00007ff98347a650 System.ThrowHelper.ThrowInvalidOperationException(System.ExceptionResource)
0000000016d1b190 00007ff9271033ef System.Nullable`1[[System.Double, mscorlib]].op_Explicit(System.Nullable`1<Double>)
0000000016d1b1c0 00007ff927103310 ReportExprHostImpl+CustomCodeProxy.UnitConvertSlim(Double, System.String, System.String, System.String, System.Nullable`1<Double>, System.Nullable`1<Double>)
0000000016d1b290 00007ff92622c452 ReportExprHostImpl+Textbox9_TextBoxExprHost+Paragraph00_ParagraphExprHost+TextRun00_TextRunExprHost.get_ValueExpr()
0000000016d1b360 00007ff92622bedf Microsoft.ReportingServices.RdlExpressions.ReportRuntime.EvaluateTextRunValueExpression(Microsoft.ReportingServices.ReportIntermediateFormat.TextRun)

 

Also checked the .NET call stack including parameters and locals with:

!clrstack -a

However the majority of these were optimized away, only showing: <no data>

 

It’s relevant to mention that the report code in question contains multiple UnitConvert(…) functions with different parameter overloads.

 

At this point I made a mistake by reading UnitConvertSlim as UnitConvert. I mistakenly thought that the right UnitConvert(…) function was called.

 

I wanted to set a breakpoint to inspect the status before the exception occured, but this was complicated by the fact that ReportExprHostImpl+CustomCodeProxy is generated code.

(Managed to set breakpoints, but they were not hit, most likely because they were on previous versions of the generated code)

 

Being challenged by this, I decided to do something else.

I compared the old and new version of the report and realised that UnitConvertSlim(…) was another function than expected.

 

Therefore I decided to run the VB code in a simple, separate VB application, to enable normal debugging.

This required simulating certain SSRS classes and properties, in this case Report.Parameters(…).

 

By debugging the separate VB application I realized that the expected UnitConvert(…) function did not exist!

Instead another UnitConvert(…) function was found and called. Some parameters were converted to other types and this was the root cause of the problem…

 

I implemented the missing UnitConvert(…) function and this solved the problem, both in the separate VB application and in SSRS.

Conclusion

SSRS VB code may fail in unexpected ways, if a required function overload does not exist.

If debugging VB code in SSRS is problematic, try debugging it outside of SSRS in a separate program.

Debugging blank SSRS report caused by invalid XML characters

I was testing a modified report for SQL Server Reporting Services, but the results were blank and no relevant error messages were logged by SSRS.

Only messages like these that didn’t reveal the root cause:

ERROR: Throwing Microsoft.ReportingServices.Diagnostics.Utilities.ReportServerHttpRuntimeInternalException: RsWorkerRequest::FlushResponse., Microsoft.ReportingServices.Diagnostics.Utilities.ReportServerHttpRuntimeInternalException: An internal or system error occurred in the HTTP Runtime object for application domain ReportServer_MSSQLSERVER_0-1-131184109058523378.  ---> System.Runtime.InteropServices.COMException (0x800703E3): The I/O operation has been aborted because of either a thread exit or an application request. (Exception from HRESULT: 0x800703E3)

 

Started troubleshooting by comparing the modified report with the original version, but I could see no obvious problems in either version.

 

When testing the report through the Report Viewer component resulted in this exception:

[XmlException: '♫', hexadecimal value 0x0E, is an invalid character. Line 1, position 6512.]
   System.Xml.XmlTextReaderImpl.Throw(Exception e) +88
   System.Xml.XmlTextReaderImpl.ParseNumericCharRefInline(Int32 startPos, Boolean expand, StringBuilder internalSubsetBuilder, Int32& charCount, EntityType& entityType) +817
   System.Xml.XmlTextReaderImpl.ParseCharRefInline(Int32 startPos, Int32& charCount, EntityType& entityType) +98
   System.Xml.XmlTextReaderImpl.ParseText(Int32& startPos, Int32& endPos, Int32& outOrChars) +816
   System.Xml.XmlTextReaderImpl.ParseText() +126
   System.Xml.XmlTextReaderImpl.ParseElementContent() +438
   System.Xml.XmlReader.ReadElementString() +84
   Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderServerReportSoapProxy.Read5_ValidValue(Boolean isNullable, Boolean checkType) +489

 

I wanted to verify that it was the same problem in pure SSRS, so I used ProcDump to log exception messages with:

procdump.exe -f "" -l -e 1 ReportingServicesService.exe

 

The result was:

[17:47:58] Exception: E0434F4D.System.Xml.XmlException ("'♫', hexadecimal value 0x0E, is an invalid character. Line 1, position 6508.")
[17:47:58] Exception: E0434F4D.System.InvalidOperationException ("There is an error in XML document (1, 6508).")
[17:47:58] Exception: E0434F4D.MissingEndpointException ("The attempt to connect to the report server failed. Check your connection information and that the report server is a compatible version.")
[17:47:58] Exception: E0434F4D.System.Runtime.InteropServices.COMException ("The I/O operation has been aborted because of either a thread exit or an application request. (Exception from HRESULT: 0x800703E3)")
[17:47:58] Exception: E0434F4D.System.Runtime.InteropServices.COMException ("The I/O operation has been aborted because of either a thread exit or an application request. (Exception from HRESULT: 0x800703E3)")
[17:47:58] Exception: E0434F4D.Microsoft.ReportingServices.Diagnostics.Utilities.ReportServerHttpRuntimeInternalException ("An internal or system error occurred in the HTTP Runtime object for application domain ReportServer_MSSQLSERVER_0-1-131184109058523378. ")

 

That confirmed that the problem was caused by invalid XML characters somewhere.

 

I wanted to see the XML that contained the invalid characters, so I attached WinDbg to ReportingServicesService.exe and enabled the CLR Exception event filter.

 

Refreshed the report to reproduce the problem.

Tried looking at the .NET call stack including parameters and locals with:

!clrstack -a

First part of the stack was:

OS Thread Id: 0x1d84 (26)
        Child SP               IP Call Site
00000011d267d1d8 00007ffef2638a5c [HelperMethodFrame: 00000011d267d1d8] 
00000011d267d2c0 00007ffedc73e488 System.Xml.XmlTextReaderImpl.Throw(System.Exception)
    PARAMETERS:
        this = <no data>
        e = <no data>
    LOCALS:
        <no data>

00000011d267d300 00007ffedc3cfd11 System.Xml.XmlTextReaderImpl.ParseNumericCharRefInline(Int32, Boolean, System.Text.StringBuilder, Int32 ByRef, EntityType ByRef)
    PARAMETERS:
        this (0x00000011d267d380) = 0x0000000fae5d0c00
        startPos = <no data>
        expand (0x00000011d267d390) = 0x0000000000000001
        internalSubsetBuilder (0x00000011d267d398) = 0x0000000000000000
        charCount (0x00000011d267d3a0) = 0x00000011d267d3f0
        entityType = <no data>
    LOCALS:
        <no data>
        0x00000011d267d340 = 0x0000000000000a6b
        0x00000011d267d330 = 0x0000000fae5d1328
        <no data>
        <no data>
        <no data>
        <no data>
        <no data>
        <CLR reg> = 0x000000000000000e
        <no data>
        <no data>

 

I examined the local object 0x0000000fae5d1328 with:

!DumpObj /d 0000000fae5d1328

Which seemed to be used as a buffer for XML data:

Name:        System.Char[]
MethodTable: 00007ffee08debd0
EEClass:     00007ffee02f10d0
Size:        8218(0x201a) bytes
Array:       Rank 1, Number of elements 4097, Type Char (Print Array)
Content:     MultiValue>true</MultiValue><QueryParameter>true</QueryParameter><Prompt>Device Type</Prompt><PromptUser>true</PromptUser><Depen
Fields:
None

 

I decided to find the adresses involved by dumping the array with:

!DumpArray /d 0000000fae5d1328

Part of the result was:

Name:        System.Char[]
MethodTable: 00007ffee08debd0
EEClass:     00007ffee02f10d0
Size:        8218(0x201a) bytes
Array:       Rank 1, Number of elements 4097, Type Char
Element Methodtable: 00007ffee08dec38
[0] 0000000fae5d1338
[1] 0000000fae5d133a
...
...
[4095] 0000000fae5d3336
[4096] 0000000fae5d3338

 

Now knowing the address range the unicode characters in the buffer could be read with:

du 0000000fae5d1338 0000000fae5d3338

Part of the result was:

0000000f`ae5d1338  "MultiValue>true</MultiValue><Que"
0000000f`ae5d1378  "ryParameter>true</QueryParameter"
...
...
0000000f`ae5d27b8  "/Value></ValidValue><ValidValue>"
0000000f`ae5d27f8  "<Label>♫♫113897</Label><"
0000000f`ae5d2838  "Value>52b3bc3a-32a8-49fc-a658-66"
0000000f`ae5d2878  "c67d3b29f6</Value></ValidValue><"
...
...

 

Checked the XML for invalid characters and eventually found some.

In a more readable form:

<ValidValue>
  <Label>♫♫113897</Label>
  <Value>52b3bc3a-32a8-49fc-a658-66c67d3b29f6</Value>
</ValidValue>

 

I thought it would be interesting to see the last query before the exception occured, so I started a trace with SQL Server Profiler and found:

SELECT cast(cast(0 as binary) as uniqueidentifier) AS Id, 'UNKNOWN' AS Username
UNION
SELECT Id, Username FROM Users order by 2

 

Tried running the query in SQL Server Management Studio and part of the result was:

query_result_usernames_with_invalid_xml_characters

 

Certain usernames actually contained characters that are invalid in XML.

This was the underlying cause behind the problem.

Conclusion

When SSRS reports fail without a clear indication of the cause, I recommend using a variety of tools and techniques to debug the problem similar to the described approach.

WinDbg: Problems attaching to process

Sometimes various problems prevent WinDbg from attaching to a process.

I experienced some recently, that I have described here.

 

Trying to attach 32-bit WinDbg (x86) to a 64-bit process

WinDbg_Could_not_attach_to_process_NTSTATUS_0xC00000BB

Could not attach to process 11576, NTSTATUS 0xC00000BB

The request is not supported.

 

If you get this error message, please check if the process is 32-bit or 64-bit.

Then try attaching again with the right version of WinDbg.

 

Attaching 64-bit WinDbg (x64) to a 32-bit process

Attaching 64-bit WinDbg (x64) to a 32-bit process is possible, but it’s usually not very useful. That’s because it shows a WOW64 view of the process, which limits the debugging options.

 

Trying to attach to process with insufficient user permissions

WinDbg_Could_not_attach_to_process_error_0n5

Could not attach to process 4160, Win32 error 0n5

Access is denied.

 

This error may occur if WinDbg has insufficient permissions.

Try running WinDbg “As Administrator” and try attaching to the process again.

 

Trying to attach to process when it is already being debugged

WinDbg_Could_not_attach_to_process_NTSTATUS_0xC0000048

Could not attach to process 6128, NTSTATUS 0xC0000048

An attempt to set a process's DebugPort or ExceptionPort was made, but a port already exists in the process or an attempt to set a file's CompletionPort made, but a port was already set in the file or an attempt to set an ALPC port's associated completion port was made, but it is already set.

 

This problem usually occurs if the process is already being debugged. The other debugger could be Visual Studio, ProcDump or another tool.

Check if other debuggers are attached, detach them and then try attaching to the process again with WinDbg.

Debugging Reporting Services with WinDbg

I recently needed to use classes and methods from MSXML6.dll in Reporting Services reports (to make web service calls).

Tried to instantiate XMLHTTP and DOMDocument from MSXML6.dll with late binding like this:

Request = CreateObject("MSXML2.XMLHTTP.6.0")
Doc = CreateObject("MSXML2.DOMDocument.6.0")

However it failed with a SecurityException, but the exact cause was unknown.

 

I decided to identify the cause by attaching WinDbg (x86) to RsReportHost.exe

 

On each report refresh I noticed a number of exceptions like:

(2a54.34d4): CLR exception - code e0434352 (first chance)
(2a54.34d4): CLR exception - code e0434352 (first chance)
(2a54.34d4): C++ EH exception - code e06d7363 (first chance)
(2a54.34d4): C++ EH exception - code e06d7363 (first chance)

 

I configured WinDbg to break on first chance exceptions under: Debug -> Event Filters…

Debug_Event_Filters

 

And loaded the SOS extension with:

.loadby sos clr

 

Typical (top part) of the call stack was:

0:007> !clrstack
OS Thread Id: 0x55f4 (7)
Child SP       IP Call Site
00bbb28c 7652dae8 [HelperMethodFrame: 00bbb28c]
00bbb33c 72f25d5a System.Security.CodeAccessSecurityEngine.ThrowSecurityException(...)
00bbb36c 72f25cad System.Security.CodeAccessSecurityEngine.ThrowSecurityException(...)
00bbb394 72f2136c System.Security.CodeAccessSecurityEngine.CheckSetHelper(...)
00bbb3e4 73581acf System.Security.CodeAccessSecurityEngine.CheckSetHelper(...)
00bbb50c 73e41376 [GCFrame: 00bbb50c]
00bbbd08 73e41376 [GCFrame: 00bbbd08]
00bbbdc0 73e41376 [GCFrame: 00bbbdc0]
00bbbf58 73e41376 [DebuggerSecurityCodeMarkFrame: 00bbbf58]
00bbbee4 73e41376 [HelperMethodFrame: 00bbbee4]
00bbbf7c 09a16859 Microsoft.VisualBasic.Interaction.CreateObject(System.String, System.String)
00bbbfa4 09a180ba ReportExprHostImpl+CustomCodeProxy.CallServiceTest2()
00bbbfcc 09a1807b ReportExprHostImpl+Description_TextBoxExprHost+Paragraph00_ParagraphExprHost+TextRun00_TextRunExprHost.get_ValueExpr()

(parameters trimmed for readability)

 

I checked the mscorlib.dll code for System.Security.CodeAccessSecurityEngine.CheckSetHelper(…) in ILSpy.

Noticed something interesting: The local variable permThatFailed could show which permission was missing.

This was also used when calling System.Security.SecurityException.MakeSecurityException, so that was an ideal place to set a breakpoint.

 

Set a breakpoint with !bpmd:

0:015> !bpmd mscorlib.dll System.Security.SecurityException.MakeSecurityException
Found 1 methods in module 72bf1000...
MethodDesc = 72c88e84
Setting breakpoint: bp 72F33813 [System.Security.SecurityException.MakeSecurityException(System.Reflection.AssemblyName, System.Security.Policy.Evidence, System.Security.PermissionSet, System.Security.PermissionSet, System.RuntimeMethodHandleInternal, System.Security.Permissions.SecurityAction, System.Object, System.Security.IPermission)]
Adding pending breakpoints...

 

Continued execution, refreshed the report and then checked the call stack with parameters:

0:014> !clrstack -p
OS Thread Id: 0x54c0 (14)
Child SP       IP Call Site
0103bd88 72f33813 System.Security.SecurityException.MakeSecurityException(System.Reflection.AssemblyName, System.Security.Policy.Evidence, System.Security.PermissionSet, System.Security.PermissionSet, System.RuntimeMethodHandleInternal, System.Security.Permissions.SecurityAction, System.Object, System.Security.IPermission)
PARAMETERS:
asmName (<CLR reg>) = 0x036c4bd0
asmEvidence (<CLR reg>) = 0x036c5b64
granted (0x0103bda0) = 0x00000000
refused (0x0103bd9c) = 0x036c4bd0
rmh (0x0103bd98) = 0x036c5b64
action (0x0103bd94) = 0x00000000
demand (0x0103bd90) = 0x00000000
permThatFailed (0x0103bd8c) = 0x00000002

 

The permThatFailed parameter consistently had the value 2.

I looked up the values for the SecurityPermissionFlag enumeration in ILSpy:

And found this:

/// <summary>Ability to call unmanaged code.</summary>
UnmanagedCode = 2,

 

Conclusion

The SecurityException occured because permission to execute unmanaged code was missing.

Examine WHEA_UNCORRECTABLE_ERROR (124) BSOD with WinDbg

One of my computers recently crashed with a BSOD.

This occurs very rarely so I decided to identify the cause.

Troubleshooting

I checked the system event log for a bugcheck and found this:

Log Name:      System
Source:        Microsoft-Windows-WER-SystemErrorReporting
...
Description:
The computer has rebooted from a bugcheck.  The bugcheck was: 0x00000124 (0x0000000000000000, 0xfffffa800d91b038, 0x00000000b2004000, 0x0000000029000175). A dump was saved in: C:\Windows\MEMORY.DMP. Report Id: 040116-21216-01.

 

I decided to examine the C:\Windows\MEMORY.DMP crash dump with WinDbg. (In this case the x64 version of WinDbg)

WinDbg’s !analyze command usually reveals relevant information about a BSOD, so that’s what I checked first:

Run: !analyze -v

0: kd> !analyze -v

...
WHEA_UNCORRECTABLE_ERROR (124)
A fatal hardware error has occurred. Parameter 1 identifies the type of error
source that reported the error. Parameter 2 holds the address of the
WHEA_ERROR_RECORD structure that describes the error conditon.
Arguments:
Arg1: 0000000000000000, Machine Check Exception
Arg2: fffffa800d91b038, Address of the WHEA_ERROR_RECORD structure.
Arg3: 00000000b2004000, High order 32-bits of the MCi_STATUS value.
Arg4: 0000000029000175, Low order 32-bits of the MCi_STATUS value.

...

PRIMARY_PROBLEM_CLASS:  X64_0x124_AuthenticAMD_PROCESSOR_CACHE

 

It seemed to be a hardware error related to the processor cache.

For more details I looked at the WHEA_ERROR_RECORD information:

(Only section 2 with the actual error shown)

0: kd> !errrec fffffa800d91b038
===============================================================================
Common Platform Error Record @ fffffa800d91b038
-------------------------------------------------------------------------------
Record Id     : 01d17af4b6b560a4
Severity      : Fatal (1)
Length        : 928
Creator       : Microsoft
Notify Type   : Machine Check Exception
Timestamp     : 4/1/2016 18:19:44 (UTC)
Flags         : 0x00000000

...

===============================================================================
Section 2     : x86/x64 MCA
-------------------------------------------------------------------------------
Descriptor    @ fffffa800d91b148
Section       @ fffffa800d91b2d0
Offset        : 664
Length        : 264
Flags         : 0x00000000
Severity      : Fatal

Error         : DCACHEL1_EVICT_ERR (Proc 0 Bank 0)
Status      : 0xb200400029000175

 

Apparently a hardware error releated to the level 1 data cache caused the system crash.

 

The computer in question has an AMD Athlon II X2 280 CPU.

Using CPU-Z I noticed that the core voltage seemed a little low for this CPU.

I remembered that I had undervolted the CPU to save power.

(Did not have reliability problems with it for years until now)

 

I checked the BIOS settings and discovered that the CPU was undervolted by -0,15 volts.

I decided to change it to -0,1 volts.

If any other reliability problems occur, I will change it back to standard voltage.

Conclusion

If hardware is running out of specifications and system crashes occur, then adjust settings closer to specifications.

(Examples of running out of spec: Undervolting, overvolting and overclocking)

Get .NET call stack when files are written with WinDbg

I was interested in learning how Neuron ESB performed logging internally.

(To see if it would be relevant to use the same classes and methods for logging in custom C# process steps and possibly other situations)

 

At first I used Process Monitor.

I found a WriteFile event, where a log file was updated.

Neuron_ESB_WriteFile_Process_Monitor_Event

I checked the stack under event properties.

Neuron_ESB_WriteFile_Process_Monitor_Event_Properties_Stack

The native stack trace didn’t tell me which .NET classes or methods that were in use, but it did give me an idea:

Perhaps I could use WinDbg to get the .NET call stack for each call to WriteFile in kernel32.dll

 

Indeed this was possible by:

1. Starting WinDbg (x64) as Administrator.

2. Attaching to the ESBService.exe process.

3. Loading the SOS extension with:

.loadby sos clr

4. Setting a breakpoint with a command to show the .NET call stack and continue execution with:

bp kernel32!WriteFile "!clrstack; g"

5. Continuing execution with:

g

 

This showed the .NET call stack every time files were written.

Most WriteFile calls were for logging (as expected).

An example:

OS Thread Id: 0x2354 (35)
Child SP               IP Call Site
000000001836e028 00000000775a1fa0 [InlinedCallFrame: 000000001836e028] Microsoft.Win32.Win32Native.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836e028 000007feea284cf4 [InlinedCallFrame: 000000001836e028] Microsoft.Win32.Win32Native.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836dff0 000007feea284cf4 DomainNeutralILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836e0d0 000007feea265984 System.IO.FileStream.WriteFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, System.Threading.NativeOverlapped*, Int32 ByRef)
000000001836e130 000007feea2658d2 System.IO.FileStream.WriteCore(Byte[], Int32, Int32)
000000001836e1a0 000007feea265847 System.IO.FileStream.FlushInternalBuffer()
000000001836e1e0 000007feea2657d4 System.IO.FileStream.Flush(Boolean)
000000001836e220 000007feea27128c System.IO.StreamWriter.Flush(Boolean, Boolean)
000000001836e280 000007fec064f2f7 Microsoft.VisualBasic.Logging.FileLogTraceListener+ReferencedStream.Flush()
000000001836e2d0 000007fec064e065 Microsoft.VisualBasic.Logging.FileLogTraceListener.Flush()
000000001836e300 000007fee92e0859 System.Diagnostics.TraceInternal.WriteLine(System.String)
000000001836e370 000007fe8bcc780d Neuron.Esb.ESBMasterService.Trace(System.Diagnostics.TraceListener, System.String)
000000001836e3c0 000007fe8bcc7bec Neuron.Esb.ESBMasterService.TraceInfo(System.Diagnostics.TraceSwitch, System.String, System.Diagnostics.TraceListener)
000000001836e420 000007fe8bfa72a9 Neuron.Esb.ESBMasterService.TraceInfo(System.Diagnostics.TraceSwitch, System.String)
000000001836e460 000007fe8c1c831e Neuron.Esb.EsbService.AmqpService.Trace(System.String, System.Object[])
000000001836e4a0 000007fe8cbbbc2e Neuron.Esb.EsbService.AmqpService.UpdateServiceStatus(Neuron.Esb.EsbService.ServiceState, Newtonsoft.Json.Linq.JToken)
000000001836e530 000007fe8c8baa0b Neuron.Esb.EsbService.AmqpService.UpdateExchangeStatus(System.Object, System.Timers.ElapsedEventArgs)
000000001836e5d0 000007fee9802586 System.Timers.Timer.MyTimerCallback(System.Object)
000000001836e650 000007feea1c2490 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001836e720 000007feea1c2327 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001836e750 000007feea1f0b9b System.Threading.TimerQueueTimer.CallCallback()
000000001836e7b0 000007feea1f0998 System.Threading.TimerQueueTimer.Fire()
000000001836e800 000007feea281a9f System.Threading.TimerQueue.FireNextTimers()
000000001836ed08 000007feeb303753 [DebuggerU2MCatchHandlerFrame: 000000001836ed08]
000000001836ee98 000007feeb303753 [ContextTransitionFrame: 000000001836ee98]
000000001836f0b8 000007feeb303753 [DebuggerU2MCatchHandlerFrame: 000000001836f0b8]

 

Having years of experience with log4net, I decided to use and recommend that.

Neuron ESB service may hang due to RabbitMQ service

I recently experienced a situation where the Neuron ESB service would hang when restarting.

ESBService.exe was stuck at Stopping and didn’t finish within 5 minutes, so it seemed to be permanently stuck.

Troubleshooting

Resource Monitor’s “Analyze Wait Chain” feature showed that 3 threads were waiting to finish network I/O.

ESBService_Analyze_Wait_Chain_waiting_to_finish_network_IO

 

I took 5 memory dumps using procdump:

procdump -ma EsbService.exe

 

WinDbg showed similar call stacks for the waiting threads:

0:060> !clrstack
OS Thread Id: 0x4e58 (60)
Child SP IP Call Site
000000001cd6dd88 000000007757d3fa [InlinedCallFrame: 000000001cd6dd88] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6dd88 000007fee9217e61 [InlinedCallFrame: 000000001cd6dd88] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6dd60 000007fee9217e61 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6de10 000007fee919c501 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
000000001cd6de90 000007fee919c3b8 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags)
000000001cd6def0 000007fee919c132 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
000000001cd6df50 000007feea1479bf System.IO.BufferedStream.ReadByte()
000000001cd6df90 000007feea13444f System.IO.BinaryReader.ReadByte()
000000001cd6dfc0 000007fe8c0ad406 RabbitMQ.Client.Impl.Frame.ReadFrom(RabbitMQ.Util.NetworkBinaryReader)
000000001cd6e020 000007fe8c0ad374 RabbitMQ.Client.Impl.SocketFrameHandler_0_9.ReadFrame()
000000001cd6e070 000007fe8c0ad27c RabbitMQ.Client.Impl.ConnectionBase.MainLoopIteration()
000000001cd6e0b0 000007fe8c0acfe2 RabbitMQ.Client.Impl.ConnectionBase.MainLoop()
000000001cd6e110 000007feea0c2490 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001cd6e1e0 000007feea0c2327 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001cd6e210 000007feea0c22e2 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000001cd6e260 000007feea162362 System.Threading.ThreadHelper.ThreadStart()
000000001cd6e548 000007feeb203753 [GCFrame: 000000001cd6e548]
000000001cd6e898 000007feeb203753 [DebuggerU2MCatchHandlerFrame: 000000001cd6e898]
000000001cd6ea28 000007feeb203753 [ContextTransitionFrame: 000000001cd6ea28]
000000001cd6ec48 000007feeb203753 [DebuggerU2MCatchHandlerFrame: 000000001cd6ec48]

 

The call stacks indicated that the problem was related to RabbitMQ.

 

I decided to forcefully stop the ESBService.exe process.

 

When starting ESBService.exe it was still trying to communicate with RabbitMQ and hanging.

I noticed this error in the Neuron ESB Event Log:

Event Info: An error occurred trying to update the status for RabbitMQ exchange "DEFAULT.Enterprise.FileContent": This request operation sent to net.tcp://localhost:50004/MasterControl/ did not receive a reply within the configured timeout (00:01:00). The time allotted to this operation may have been a portion of a longer timeout. This may be because the service is still processing the operation or because the service was unable to send a reply message. Please consider increasing the operation timeout (by casting the channel/proxy to IContextChannel and setting the OperationTimeout property) and ensure that the service is able to connect to the client.. Attempted to Query 'localhost' on port '15672'.

 

I decided to restart the RabbitMQ service, which solved the problem.

After this the Neuron ESBService.exe was able to start and work normally.

 

If the problem occurs again, I will take and examine memory dumps of the RabbitMQ service, in an attempt to learn the cause of the problem.

This occured with Neuron ESB version 3.5.3.411 and RabbitMQ version 3.2.2 (bundled with Neuron ESB).

 

I notice that the latest RabbitMQ version is currently 3.6.1:

https://www.rabbitmq.com/changelog.html

It seems relevant to update RabbitMQ, but compatibility with the current Neuron ESB version is currently unknown.