The majority of the libraries developers use in their projects these days are open source. So in case something crashes inside third party library or you just want to know how it works, it is possible to get the PDB files from Microsoft Symbols Servers and debug it. If for some reasons PDB cannot be found on the servers, you can always grab the source code from GitHub and add to your project manually. Unfortunately when you use commercial libraries, it is impossible to do any of the previous steps. Luckily with Resharper you are able to generate PDB files from assembly and use it later in Visual Studio to debug it.
Let’s assume we would like to generate PDB files for EntityFramework. First of all, we have to locate EntityFramework assembly in Assembly Explorer. Go to Solution Explorer, RMB click on assembly you are interested in and select View in Assembly Explorer.
In Assembly Explorer once again RMB click on EntityFramework and select “Generate Pdb…”
In the opened window, select the destination folder for the files.
Once you click “Generate“, Resharper will process the assembly and generate PDBs.
Once the files are generated we have to tell Visual Studio to use them. In order to do that, run the app and stop the execution with some breakpoint, then go to Debug->Windows-> Modules, locate EntityFramework.dll, click it with RMB, select “Load Symbols” and choose file(s) generated by Resharper.
A this point we have PDB files ready but we are not able to set any breakpoint as we don’t have source code of EntityFramework. Fortunately Resharper once again saves the day as it is able to navigate to decompiled sources. Just make sure that your settings (Resharper->Options->External Sources) are the same as in the picture below
and you can navigate to external libraries’ source code just like they were in your project. The very last step is to disable “Enable Just My Code” option in Tools->Options->Debugging->General
and from now on you can debug the external library
Debugging cake scripts
We’ve been using Cake in our project for quite some time and it has been working great. However for time to time lack of debugging support was really annoying for me. Fortunately it seems that these times are gone now. During NDC Oslo 2016 Gary Ewan Park showed that it is possible to attach debugger to the build process. Here are the steps to achieve that. Let’s assume that we have following simple cake script.
|
1 2 3 4 5 6 7 8 |
var target = Argument("target", "Default"); Task("Default") .Does(() => { MSBuild(Directory("../") + File("DebuggingCakeScript.sln")); }); RunTarget(target); |
In order to make the debugging possible it is necessary to add
|
1 |
#break |
preprocessor directive to the task we want the debugger to stop.
|
1 2 3 4 5 6 7 8 9 |
var target = Argument("target", "Default"); Task("Default") .Does(() => { #break MSBuild(Directory("../") + File("DebuggingCakeScript.sln")); }); RunTarget(target); |
This operation doesn’t affect the default build process, so if you run in console
|
1 |
.\build.ps1 -target Default |
the build will run as usual. In order to be able to attach the debugger we have to call Cake with
|
1 |
--debug |
flag. You can’t do it directly via
|
1 |
\build.ps1 |
script so assuming that you didn’t change directory structure created by bootstrapper, go to Tools/Cake folder and run from PowerShell
|
1 |
.\Cake.exe ..\..\build.cake -target=Default --debug |
where
|
1 |
..\..\build.cake |
is path to your cake script and
|
1 |
Default |
is task you want to start. Once you run the command, cake will wait for attaching the debugger
Now launch Visual Studio, go to Debug-> Attach to Process…, find process id listed in console
and click Attach. After couple of seconds Visual Studio will load your cake script and you will be able to debug it like normal application.
NLog – tracking flow of requests using MappedDiagnosticsLogicalContext
1. Problem
Everyone who has ever had to analyze logs from production environment knows, that quite often it is not an easy task. Usually application flow is deduced by log entries matched by thread id, which is problematic when you deal with multithreading scenarios. Say for example we have following piece of code
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 |
public class HomeController : Controller { private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); public async Task<ActionResult> Index() { await PreprocessRequest(nameof(Index)); return View(); } private static async Task PreprocessRequest(string actionName) { Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}"); await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler")) .ConfigureAwait(continueOnCapturedContext: false); Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}"); var thread = new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}")); thread.Start(); thread.Join(); } } |
Default log file usually looks like that
|
1 2 3 4 5 6 |
TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5 TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6 TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14 TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200 |
Having multiple simultaneous Index requests, makes it almost impossible to figure out which log entry is part of which call. Fortunately with NLog it is possible to solve this problem without too much of a hassle.
2. Proposed solution
The whole idea is to leverage MappedDiagnosticsLogicalContext “storage” to keep some unique identifier of request for entire call. Note, that this identifier will be accessible also from other threads created from within given call. In order to set unique request id (also known as correlation id) I will use custom HttpModule. The very first implementation looks like that
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 |
public class LoggingHttpModule : IHttpModule { private const string CorrelationIdKey = "correlationid"; private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); public void Init(HttpApplication context) { context.BeginRequest += HandleBeginRequest; context.EndRequest += HandleEndRequest; } public void Dispose() { } private void HandleBeginRequest(object sender, EventArgs e) { var value = Guid.NewGuid().ToString(); var httpApplication = (HttpApplication) sender; var httpContext = httpApplication.Context; MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value); Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request"); } private void HandleEndRequest(object sender, EventArgs e) { var httpApplication = (HttpApplication) sender; var httpContext = httpApplication.Context; Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} "); } } |
Once the HttpModule is ready it is necessary to register it in web.config.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
<!--rest of the code omitted --> <system.webServer> <modules> <!--rest of the code omitted --> <add name="LoggingHttpModule" type="AspNetMvcLoggingWithCorrelationId.HttpModules.LoggingHttpModule"/> </modules> </system.webServer> <!--rest of the code omitted --> <system.web> <!--rest of the code omitted --> <httpModules> <!--rest of the code omitted --> <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule,Microsoft.AI.Web"/> </httpModules> </system.web> |
From now on, every request goes through LogginHttpModule and proper correlationId is set in MappedDiagnosticsLogicalContext.
As we want to have correlationId included in log files it is necessary to modify Nlog.config. In my case it looks like that
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
<?xml version="1.0" encoding="utf-8" ?> <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd" autoReload="true" throwExceptions="false" internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log" > <variable name="myvar" value="myvalue"/> <targets> <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log" layout="TimeStamp=${longdate} CorrelationId=${mdlc:item=correlationid} Level=${uppercase:${level}} Message=${message}" /> </targets> <rules> <logger name="*" minlevel="Debug" writeTo="f" /> </rules> </nlog> |
Note that we can access our correlationId variable via ${mdlc:item=correlationid}
Log file after the changes looks like that
|
1 2 3 4 5 6 |
TimeStamp=2016-07-03 12:41:35.7292 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=About to start GET / request TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from thread=6 TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index, from thread 7 assigned by scheduler TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from async continuation, from thread 7 TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from explicitly created thread 9 TimeStamp=2016-07-03 12:41:38.4454 CorrelationId= Level=INFO Message=Request completed with status code: 200 |
This is almost perfect, however for some reasons correlationId is lost in EndRequest event handler. I am not sure if this is bug in NLog (I’ve posted question in Nlog’s github) or it is by design, however there is easy workaround for that. We can store our correlationId in HttpContext.Items collection and reassign it to MappedDiagnosticsLogicalContext in EndRequest event handler.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
private void HandleBeginRequest(object sender, EventArgs e) { var value = Guid.NewGuid().ToString(); var httpApplication = (HttpApplication) sender; var httpContext = httpApplication.Context; MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value); httpContext.Items[CorrelationIdKey] = value; Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request"); } private void HandleEndRequest(object sender, EventArgs e) { var httpApplication = (HttpApplication) sender; var httpContext = httpApplication.Context; var correlationId = httpContext.Items[CorrelationIdKey].ToString(); MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, correlationId); Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} "); } |
After these changes our log file finally looks OK
|
1 2 3 4 5 6 |
TimeStamp=2016-07-03 12:41:35.7292 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=About to start GET / request TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from thread=6 TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index, from thread 7 assigned by scheduler TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from async continuation, from thread 7 TimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from explicitly created thread 9 TimeStamp=2016-07-03 12:41:38.4454 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Request completed with status code: 200 |
Source code for this post can be found here
Console2 – multiple tabs on startup
I’ve been using Console2 for quite some time and as for now it is my favorite command line terminal. The one thing I like the most is availability to use multiple tabs you can easily switch between. By default Console2 starts with only one tab opened, which was a bit of a pain for me. Mainly because I work a lot with Git and I also like to have a Visual Studio command prompt opened. So basically every time I launched command line I had to open one or two additional tabs. Fortunately it is quite easy to launch multiple tabs on startup. All you have to do is to create a shortcut to the Console2 with proper flags. Say for example I have following tabs defined
I can start Console2 with all these tabs opened on startup using following command.
|
1 |
PATH_TO_CONSOLE\Console.exe -t Git -t Cmd -t Powershell |
Of course it is easier to define a shortcut to Console2 rather than remembering command above. My configuration looks like that
Mocking downstream services with Mountebank
1. Introduction
I’m a part of a team which creates large enterprise platform for the banking sector. Due to the fact that we operate in the financial area, our application consumes a high amount of downstream services. One of the major problems we are facing at the moment is the inaccessibility of those services on DEV and UAT environments. It often happens that one of those services is down for quite some time, so our development speed is impaired. The bigger problem, however, is the fact that our end-to-end tests are red. Having a red test on TeamCity for a long time is a really annoying thing because basically at this point, we just automatically assume that all of the failures are caused by issues with downstream systems. Fortunately, we finally decided to get rid of this problem and this is the solution we came up with.
2. Background
Before I go to the implementation details, take a look at a sample implementation of situation I described at the very beginning. Let’s assume that we have WCF service which contains business logic of our application and it is consumed by the UI side
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 |
public class BookingFacade : IBookingFacade { public Response<Price> Price(Models.GetPriceRequest request) { // in real life scenario Pricer should be injected var pricerService = new Pricer(); var response = new Response<Price>(); try { var tradingDates = pricerService.GetTradingDates(); var price = pricerService.GetPrice(new GetPriceRequest { IsAdvised = request.IsAdvised }); // rest of the code omitted for brevity response.Result = new Price { TradingDates = new TradingDates { MaturityDate = tradingDates.MaturityDate, SettlementDate = tradingDates.SettlementDate } }; // rest of the code omitted for brevity } catch (Exception ex) { // rest of the code omitted for brevity } return response; } } |
BookingFacade uses Pricer service which basically is just a wrapper for external/downstream service we have to use in order to retrieve some data (and we do not have an ownership of that service).
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
public class Pricer : IPricer { public TradingDates GetTradingDates() { using (var webClient = new WebClient()) { var result = webClient.DownloadString(ConfigurationManager.AppSettings["MockingDownstreamServices.Externals.Pricer.GetTradingDates"]); return JsonConvert.DeserializeObject<TradingDates>(result); } public Price GetPrice(GetPriceRequest request) { using (var webClient = new WebClient()) { var result = webClient.UploadString(ConfigurationManager.AppSettings["MockingDownstreamServices.Externals.Pricer.GetPrice"], JsonConvert.SerializeObject(request)); return JsonConvert.DeserializeObject<Price>(result); } } } |
Very simple end-to-end test for BookingFacade can look like that
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
[TestFixture] public class BookingFacadeTests { [Test] public void CanSuccessfullyPriceTest() { var response = this.Price(new GetPriceRequest()); Assert.IsNotNull(response); Assert.IsNotNull(response.Result); Assert.IsFalse(string.IsNullOrWhiteSpace(response.Result.Id)); CollectionAssert.IsEmpty(response.Messages.Where(val => val.StatusCode == StatusCodes.Error)); } } |
As I mentioned before, everything is fine as long as all of the downstream systems are working. The moment one of them is down, our tests start failing.
3. Implementation
General idea to fix this problem is to use fake downstream systems during end-to-end testing. In order to do that we use combination of custom compilation profile, app.config transformations and mountebank test doubles.
3.1 Setting up transformations
First of all we will create a custom compilation profile called test.integration which will be used for running tests with mocked downstream systems (we want to preserve the normal use of downstreams for Debug and Release mode). In order to do that, go to ConfigurationManager
and follow the steps presented in the pictures below
Now it is time to prepare our app.config for transformations. We can do it manually but for sake of simplicity I will use SlowCheetah extension. Go to Tools->Extensions and Updates and install
SlowCheetah – XML Transforms. Once extension is installed you will see a Add Transform item in a config files’ context menu.
Clicking Add Transform will create three files: App.Debug.config, App.Release.config and App.Test.Integration.config. What is more, some additional changes will be added to your csproj file, which will be responsible for applying transformations during a build process. These three additional files hold information about config transformations. The default App.config file looks like that
|
1 2 3 4 5 6 |
<?xml version="1.0" encoding="utf-8" ?> <configuration> <appSettings file=""> <add key="commonKey" value="commonValue"/> </appSettings> </configuration> |
Nothing special in here but note the empty file attribute in appSettings node. The value of this attribute will be replaced with proper filename during transformation process. In order to do that let’s implement tramsforms for every of three config files we use
App.Debug.config
|
1 2 3 4 5 6 7 |
<?xml version="1.0" encoding="utf-8" ?> <!-- For more information on using transformations see the web.config examples at http://go.microsoft.com/fwlink/?LinkId=214134. --> <configuration xmlns:xdt="http://schemas.microsoft.com/XML-Document-Transform"> <appSettings file="app.settings.debug" xdt:Transform="SetAttributes"> </appSettings> </configuration> |
App.Release.config
|
1 2 3 4 5 6 7 |
<?xml version="1.0" encoding="utf-8" ?> <!-- For more information on using transformations see the web.config examples at http://go.microsoft.com/fwlink/?LinkId=214134. --> <configuration xmlns:xdt="http://schemas.microsoft.com/XML-Document-Transform"> <appSettings file="app.settings.release" xdt:Transform="SetAttributes"> </appSettings> </configuration> |
App.Test.Integration.config
|
1 2 3 4 5 6 7 |
<?xml version="1.0" encoding="utf-8" ?> <!-- For more information on using transformations see the web.config examples at http://go.microsoft.com/fwlink/?LinkId=214134. --> <configuration xmlns:xdt="http://schemas.microsoft.com/XML-Document-Transform"> <appSettings file="app.settings.tests.integration" xdt:Transform="SetAttributes"> </appSettings> </configuration> |
As you can see I apply SetAttributes transform for appSettings node, which means that the transformation will replace appSettings node attributes from app.config file with appSettings node attributes from transform file. You can preview results of transformation by clicking Preview Transform context menu option available for every of our transform files
As you’ve probably already figured it out app.settings.debug and app.settings.release fileses contain real downstream endpoints and app.settings.tests.integration contains addresses of fake endpoints. Of course you have to create those files and copy them to output directory during the build (for instance by using Copy to Output directory option).
3.2. Creating fake downstreams with mountebank
Setting up fake downstream systems completely from scratch would be a very painful and time consuming process. Fortunately there are tools which can make this task easier. The tool I use is called mountebank – you can easily install it via npm
|
1 |
npm install -g mountebank |
Having mountebank on board it is time to configure it, so that it acts as fake Pricer service. It can be done in couple of ways but I will go with file based configuration. You can run the tool using following command
|
1 |
mb --configfile impostors.ejs --allowInjection |
Where impostors.ejs is a configuration file with following structure
|
1 2 3 4 5 |
{ "imposters": [ <% include pricer.json %> ] } |
<% include pricer.json %> is EJS syntax which (in this case) allows you to split configuration into multiple files. As you’ve probably already figured it out, Pricer.json contains the actual mock configuration for Pricer service. The initial mock object consists of couple of properties which setup the name, port and protocol for given mock.
|
1 2 3 4 5 6 |
{ "port": 4545, "protocol": "http", "name": "pricer stub", "stubs": [] } |
Note that we do not specify the address of mock but just a port. Mountebank by default runs on http://localhost:2525 and mocks listen on http://localhost:{port}. The actual magic happens in stubs property.
Here is an example of stub/mock for GetTradingDates method.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
{ "responses": [ { "is": { "body": { "MaturityDate": "2016-02-17", "SettlementDate": "2012-02-23" } } } ], "predicates": [ { "equals": { "path": "/GetTradingDates", "method": "GET" }, } ] } |
As you can see stub object consists of two properties
- responses
- predicates
responses property is an array of objects mountebank will be using to create a response. If you insert multiple items into array, they will be utilized using round robin algorithm. Note that you don’t have to create a full response (with all the headers etc.) just use “is” property which will fill the default values for you. More about that topic can be found here but in most of the cases setting value for “body” property will be enough for you.
predicates property is an array of predicates which will be used during matching process. Predicate object can be quite complex, it supports lots of different matching techniques. In this case, for simple GET method I just use equals operator to match HTTP verb and HTTP method.
The same technique can be used for stubbing POST methods. However, in this case, you can also perform matching against the body of the request. The one thing you have to remember is that body property is not an object but string. So in my case, if I want to make a stub for GetPrice which takes as params following request object
|
1 2 3 4 |
public class GetPriceRequest { public bool IsAdvised { get; set; } } |
I can write for instance this stub
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
{ "responses": [ { "is": { "body": { "Id": "1", "Strike": "1" } } } ], "predicates": [ { "equals": { "path": "/GetPrice", "method": "POST", "body": "{\"IsAdvised\":false}" } } ] } |
Of course for more complex request it is pointless to write every possible combination of params. Fortunately you can create fallback/default stub which will match everything
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
{ "responses": [ { "is": { "body": { "Id": "default", "Strike": "1" } } } ], "predicates": [ { "equals": { "path": "/GetPrice", "method": "POST" } } ] } |
If you put this at the very end of stubs array it will not interfere with other stubs.
This is of course just a tip of the iceberg when it comes to predicate matching. Explanation of all possible matching options can be found here
4. Results
From now on running tests against test.integration compilation profile and having mountebank working in the background, our tests will be green.
Source code for this post can be found here