One of my colleagues at work was struggling with a peculiar problem on his machine. Whenever he tried to access the address of his test project: http://my.project:8080 he was getting connection refused error (my.project points to 127.0.0.1 in the hosts file). The same error appeared when we opened the http://127.0.0.1:8080 address:
Recently, the idea of protected variables in TFS struck my attention and pushed me to do some more research on how exactly those variables are stored. I hope I will write a separate post on that subject, but today I would like to share with you a small trick I use whenever I need to work with managed application traces (and TFS is one of them).
On Windows, when I want to know how things work internally, I usually start with procmon. Seeing which paths and registry keys are accessed, combined with TCP/IP connections is often enough to get an idea where to put breakpoints in further analysis. My TFS investigation was no exception to this rule. I collected a trace while saving a protected build variable – this is how such a variable looks like (in case you are interested :)):
Process Monitor (or procmon) is a very powerful diagnostics tool for Windows. I remember when I first run it, a few years ago, I was overwhelmed by the number of events happening on my system each and every second. Thankfully, procmon has features to help you deal with this bulk of data, including filters, highlighters, and bookmarks. But sometimes even a filtered log is not enough to find the root cause of a problem. On such occasions, other log sources may contain the missing bits of information. We only need to correlate them with our procmon trace. And today, I would like to show you how I do that.
Application Insights is a performance monitoring service, created by Microsoft and available on Azure. It gives you space to store the performance metrics and logs of your application (1GB for free!), as well as functionalities to search and manage them. In this post I am not going to present you the whole platform – Microsoft already did it in the Azure documentation, but rather focus on an element of the log collection, named dependency calls tracking. I did some analysis on the Application Insights libraries, and decided to publish my findings, in the hope that the results might interest some of you too.
Dependency calls are requests, which your application makes to the external services (such as databases or REST services). When this telemetry type is enabled, all the dependent actions form a timeline within the scope of the parent action. Using this timeline we may easily verify whether the delay in our application is caused by an external service, or the application itself. Let’s analyze in detail how this data is collected.
In today’s short post I would like to present you a new tool in my diagnostics toolkit: wtrace, and an update to procgov (or Process Governor). Let’s start with wtrace.
On Linux, when I need to check what a given process is doing, I usually use strace. I was always missing such a tool for Windows. We have procmon (which is great), but it does not run in a console, and thus can’t be used in the command line scripts, or on a Nano server. This might change soon, as in one of the latest episodes of the Defrag Tools show, Mark Russinovich shared the plan of releasing the procmon version for Nano. Till then though we don’t have much choice when it comes to real-time tracing. You may think of xperf or wpr, but those tools only record ETW events for further analysis. However, we may use the same ETW events in a realtime session, and print information they provide to the console output. This is how the idea for wtrace was born in my head. Few weeks ago Sasha Goldshtein released another tool for ETW processing named etrace, which basically does something very similar and has many interesting options. I decided to publish wtrace nonetheless, as my point was to create a tool with an extremely simple interface. Wtrace is collecting only a small subset of events (FileIO, TcpIp, Process/Thread Start) from the kernel provider. It may either start a process, or trace one that is already running. At the end of the trace it also shows some statistics (unless you use the –nosummary switch). Trace session will end either when you press Ctrl+C, or when the traced process terminates. Events are printed in the console window. An example session might look as follows:
This is how the story begins. On our build server we are using a JetBrains Resharper CLT to generate a code analysis report. In one of the projects build we started getting the following exception log:
Executing the powershell script: C:\install\TFS \1.0.691\resharp.ps1
JetBrains Inspect Code 2016.1.2
Running in 64-bit mode, .NET runtime 4.0.30319.42000 under Microsoft Windows NT 6.2.9200.0
'AutoMapper' already has a dependency defined for 'Microsoft.CSharp'.
--- EXCEPTION #1/2 [InvalidOperationException]
Message = "'AutoMapper' already has a dependency defined for 'Microsoft.CSharp'."
ExceptionPath = Root.InnerException
ClassName = System.InvalidOperationException
HResult = COR_E_INVALIDOPERATION=80131509
Source = NuGet.Core
StackTraceString = "
at NuGet.Manifest.ValidateDependencySets(IPackageMetadata metadata)
at NuGet.Manifest.ReadFrom(Stream stream, IPropertyProvider propertyProvider, Boolean validateSchema)
at NuGet.LocalPackage.ReadManifest(Stream manifestStream)
at NuGet.SharedPackageRepository.OpenPackage(String path)
at NuGet.LocalPackageRepository.GetPackage(Func`2 openPackage, String path)
at NuGet.LocalPackageRepository.<>c__DisplayClass13.<FindPackage>b__f(String path)
at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
at NuGet.LocalPackageRepository.FindPackage(Func`2 openPackage, String packageId, SemanticVersion version)
at NuGet.SharedPackageRepository.FindPackage(String packageId, SemanticVersion version)
at JetBrains.ProjectModel.Packages.SharedPackageRepositoryInTemp.FindPackage(String packageId, SemanticVersion version)
at NuGet.PackageRepositoryExtensions.FindPackage(IPackageRepository repository, String packageId, SemanticVersion version, IPackageConstraintProvider constraintProvider, Boolean allowPrereleaseVersions, Boolean allowUnlisted)
at NuGet.PackageReferenceRepository.GetPackage(PackageReference reference)
at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
at JetBrains.Util.ILoggerEx.Catch[TValue](ILogger th?s, Func`1 F, ExceptionOrigin origin, LoggingLevel loggingLevel)
When we work with binary data we often use the dt command to group the bytes into meaningful fields, eg.
0:000> dt ntdll!_PEB @$peb
+0x000 InheritedAddressSpace : 0 ''
+0x001 ReadImageFileExecOptions : 0 ''
+0x002 BeingDebugged : 0x1 ''
+0x003 BitField : 0x8 ''
+0x003 ImageUsesLargePages : 0y0
+0x003 IsProtectedProcess : 0y0
+0x003 IsLegacyProcess : 0y0
+0x003 IsImageDynamicallyRelocated : 0y1
+0x003 SkipPatchingUser32Forwarders : 0y0
The problem arises when the library owner does not provide type information in the symbol files. We are usually left with a manual decomposition of the bytes in a binary editor (010 Editor has a nice template system). Wouldn’t it be great if we had some template system available also in the debugger? I have some good news for you: with the latest release of WinDbg we received a very powerful feature: .natvis files. There were even two Defrag Tools episodes dedicated to this functionality: Defrag Tools #138 and Defrag Tools #139. Let’s first analyze how the .natvis files are built, to later use them in our binary data analysis.
In the last post I presented you my first WinDbg extension with a !injectdll command. Theoretically everything was correct, but after some more testing I noticed that the command is not always working as expected. Andrey Bazhan was pretty quick in pointing this out and advised me to use a remote thread, which, as you will see, is a much better approach. But let’s first have a look at the problems in lld 1.0.
Today I have a pleasure to present you my first WinDbg extension lld 🙂 For now it contains only one command: !injectdll, which allows you to inject a DLL into the process being debugged. There is a similar command in the sdbgext extension, but it works only for 32-bit processes. The usage is extremly simple – just remember to load the extension in the correct bitness (32-bit version for 32-bit processes). Example session may look as follows:
0:000> .load lld
0:000> !injectdll c:\temp\Test.exe
ModLoad: 00000001`3f820000 00000001`3f924000 c:\temp\Test.exe
ModLoad: 000007fe`fd960000 000007fe`fd98e000 C:\Windows\system32\IMM32.DLL
ModLoad: 000007fe`ff410000 000007fe`ff519000 C:\Windows\system32\MSCTF.dll
(bac.5a0): Break instruction exception - code 80000003 (first chance)
00000000`778c7800 cc int 3
The binaries can be found under the release tab of the source code repository.
For some time I have been working on a monitoring solution for developers. Today I have a pleasure to announce its first official release. It is a set of tools which should help you better diagnose your applications. As there are many monitoring solutions on the market you may be using one of them (and that’s great). However, I’ve observed that it’s still uncommon for developers to collect application logs in one place. Therefore OPS monitor IIS logs and developers are checking application-specific targets. This is not the best approach as you can’t see at first sight if something is going wrong with your application. Few years ago I had an idea of an application board which will show statuses of applications on all the servers. This is one of the central part of the Diagnostics Kit and I named it the Diagnostics Castle. A sample board might look as follows: