ASP .NET and Cookies

Recently I found out something rather cool about Request and Response cookies in ASP .NET. The basics of cookie management in ASP .Net are that the cookie gets read in the Request.Cookies collection and written in the Response.Cookies collection. However, did you know that as soon as you as you write a cookie out in the response, it is automatically available in the request? I didn’t, and when I worked it out I thought it was rather cool, and thought I would share.

Using log4net: some observations when logging is under load

So, here is the first of what I hope will be many posts coming out of my new project. As with most .NET developers, I use log4net to log to text files and to a database. It is one of the more flexible logging frameworks and is relatively easy to set up. However, recently I have found what I think is a bug in log4net, which I will explain how to generate it and also how to overcome it.

Firstly, some basic configuration details. Below is my basic configuration for log4net.
<log4net> <appender name="LogFileAppender" type="log4net.Appender.FileAppender"> <file value="logs\web.log"> <appendtofile value="true"> <lockingmodel type="log4net.Appender.FileAppender+MinimalLock"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%date [%thread] %-5level %logger - %message %exception%newline"> </conversionpattern></layout> </lockingmodel></appendtofile></file></appender> <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender"> <buffersize value="1"> <connectiontype value="System.Data.SqlClient.SqlConnection, System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"> <connectionstring value="data source=&lt;server&gt;;initial catalog=&lt;database&gt;;integrated security=true;persist security info=True"> <commandtext value="INSERT INTO CodeLog ([Date],[Thread],[Level],[Logger],[Message],[Exception]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception)"> <parameter> <parametername value="@log_date"> <dbtype value="DateTime"> <layout type="log4net.Layout.RawTimeStampLayout"> </layout></dbtype></parametername></parameter> <parameter> <parametername value="@thread"> <dbtype value="String"> <size value="255"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%thread"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@log_level"> <dbtype value="String"> <size value="50"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%level"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@logger"> <dbtype value="String"> <size value="255"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%logger"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@message"> <dbtype value="String"> <size value="4000"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%message"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@exception"> <dbtype value="String"> <size value="2000"> <layout type="log4net.Layout.ExceptionLayout"> </layout></size></dbtype></parametername></parameter> </commandtext></connectionstring></connectiontype></buffersize></appender> <root> <level value="ALL"> <appender-ref ref="LogFileAppender"> <appender-ref ref="AdoNetAppender"> </appender-ref></appender-ref></level></root> </log4net> Basicly, I have set up log4net to log to a text file and also to a database.

Now, as far as I am aware there is nothing specifically wrong about this configuration. It does indeed log to both a database and also a text file. However, under load some curious things happen. First of all, you can get an I/O race condition appearing regularly in the logs. This is because the load can cause 2 threads to want to write to the text file at the same time, causing the I/O race condition to occur. To fix this, remove the text file log appender updating the root node as below:
<root> <level value="ALL"> <!-- <appender-ref ref="LogFileAppender" /> --> <appender-ref ref="AdoNetAppender"> </appender-ref></level></root> This then leaves the database logger configured. So far so good. Lets say that for production you want to turn off logging entirly, the following configuration will work:
<root> <level value="OFF"> <!-- <appender-ref ref="LogFileAppender" /> --> <appender-ref ref="AdoNetAppender"> </appender-ref></level></root> Note that we have now turned all logging OFF. If your like me, you would think that this would be the end of it. You have turned off logging, end of story. But this is actually where things can get interesting. Lets say your site or web service gets under heavy load and requires data access out side of the logging framework (even to a different database). Over time, your web site stops working, all queries to the database fail. Yes, you can restart IIS and everything will go back to working again. But this is not an actual solution, it is something you would do when you had nothing else to try and you need to get the site back up and running as soon as possible.

So, what caused the issue? From what I can tell if you have a ADO appender as in the example above, you can't just turn off logging. From what I have experienced this will still connect to the database AND WONT RELEASE THE CONNECTION TIL THE CONNECTION EXPIRES. And that is the key thing here. If your database connections time out after 2 minutes, you can see how the connection pool can get clogged with these open logging connections that do nothing. What you need to do is remove or comment out the ADO appender from the list of appenders as below:
<root> <level value="OFF"> <!-- <appender-ref ref="LogFileAppender" /> --> <!-- <appender-ref ref="AdoNetAppender" /> --> </level></root> From what I have noticed, if logging is turned on, then the issue does not arise. It is only when the logging is off and there is an ADO appender there that this is an issue. I ran some tests against a web service, and with logging turned off and the ADO appender commented out, I could get 516k requests though a web service over the course of an hour with no adverse affects. As soon as I uncommented the ADO appender, the test ran for 5 minutes then started experiencing major issues, with all database connectivity stopping soon after.

Side note:
If you want to use the above to configure to a database, below is the SQL that you need to create the table. Just make sure your connection string is correct and that the user that is running the website has access to the databse the table is in.
CREATE TABLE [dbo].[CodeLog]( [Id] [int] IDENTITY(1,1) NOT NULL, [Date] [datetime] NOT NULL, [Thread] [varchar](255) NOT NULL, [Level] [varchar](50) NOT NULL, [Logger] [varchar](255) NOT NULL, [Message] [varchar](4000) NOT NULL, [Exception] [varchar](2000) NULL ) ON [PRIMARY]

A New Challenge

It has been a while since my last post, having been really busy at work getting some projects completed.  However, as its the start of a new year, I'm thinking I should get back to blogging.

So, I'm going to start work on a new self learning project, like the Java OData and the SQL audit tools I wrote previously. While I'm not going to share what the project is, I will try share what I learn while doing the project.  What's the point of working on a project? Well, I like having a purpose for doing something. I like to have a goal and try to meet that goal. Also, I am working on my project from the beginning, to see thoughts turn into requirements into functionality. But when it comes down to it, I just like a challenge.

Now the basic frameworks/languages/processes will be MVC 4, C#, Razor, agile, HTML5, CSS3, WCF and MS SQL 2012.

I already have some ideas for some future posts, so watch this space.

nHibernate, Lazy Loading and AutoMapper

I know its been a while since I have last posted, and unfortunately this post is going to be short, but I have just gotten something working and thought that I would share it with you all.

Here is the senario: you have nHibernate (in my case fluent nHibernate) and you have some collections (and properties) to be lazy loaded.  You also have your entities mapped to a DTO entity for sending over the wire.  Now, my problem was that the lazy loading was not working, when I monitored the SQL trace I could see every member and every collection being loaded regardless of what I had configured in nHibernate.  This was causing around 400 SQL statements to be executed to the database, and I could not work out why.

Now, the answer seems simple now that I know what it is, but needless to say it took a few hrs to work out what the issue was, and then another few hrs to actually get a solution that I was happy with. But, I think I have a solution I can be happy, especially now that I have gotten the 400 or so SQL statements down to about 50 for the first load, and 5 (I am hoping I can get that down to 3) for every other load in the nHibernate session.

So, I hear you ask, what was causing this blow out?  It was the AutoMapper checking the value of the entity that was triggering the lazy loading of the collections and properties, which then resulted in every member in the object being loaded, then every member in every child entity, and so on until the entire entity tree was being loaded.  Now, I am sure that I might have a configuration setting not set up properly, or I might have something wrong with my entity definition, but from what I have found this is pretty standard behaviour.

Now for the fix.  It is really neat, and is done in the AutoMapper configuration when you create your maps between your entity and DTO object.  I had basic mappings set up (my DTO’s are closely aligned with my entities), so a sample mapping would be:

Mapper.CreateMap<Entity, EntityDto>();

Now, that is fine, but to stop the Lazy loading being triggered I needed to add a bit to the mapping definition when mapping the entity to the DTO (I don’t care about the mapping from the DTO to the entity, no data access there).  So my mapping from about became:

Mapper.CreateMap<Entity, EntityDto>()
 .ForMember(dest => dest.Collection, 
    opt => opt.Conditional(dest => NHibernateUtil.IsInitalized(dest.Collection));

As you can see, this simple change is nice and neat, and stops the AutoMapper triggering the Lazy Loading of the entities.  And, as we stop the lazy loading, we stop the extra unwanted and un-needed calls to the database.


Anyway, just thought I would mention it and hopefully help someone else having the same fun as I was.  Let me know your thoughts.