José F. Romaniello

Las aventuras y desventuras de un codificador.

I will show you in this post two tricks you can do to enhance and add value to your nhibernate logs.

Format Sql

This is widely know trick, you can add a configuration setting to your hibernate.cfg.xml, app.config or web.config as follow:

<property name="hibernate.format_sql" value="true" />

or you can simply do it in code:

config.DataBaseIntegration(db => db.LogFormatedSql = true)

with this trick you will get nicely formated sql in your logs files.

Logging the session identifier

All nice, we have a bunch of sql logs, but we don’t know which queries belongs to which sessions. This might be useful when you are debugging an application with multiples threads or requests.

I found this trick inside NHibernate, the easy way I found so far is to add a log4net appender like this one:

<appender name="NHibernateAppender" type="log4net.Appender.RollingFileAppender">
  <appendToFile value="true"/>
  <datePattern value="yyyyMMdd"/>
  <file value="./logs/NHibernate.log"/>
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date Session id: %property{sessionId} - %message%newline"/>
  </layout>
  <rollingStyle value="Date"/>
</appender>

See the %property{sessionId} in the conversion pattern?

Well, in order to log something there you need to do two steps.

Add a class like this one:

public class SessionIdCapturer
{
    public override string ToString()
    {
        return SessionIdLoggingContext.SessionId.ToString();
    }
}

Add the following code in some place at the application initialization:

ThreadContext.Properties["sessionId"] = new SessionIdCapturer();

That is all! I found this code inside a nhibernate test.. it is something not very known.

After doing so, your logs will look like:

2011-05-05 18:35:59,899 Session id: 5e172068-5064-44b6-bf96-99362ca05c46 - 
    SELECT
        myFoo0_.AccountId as AccountId3_0_,
        myFoo0_.Name as Name3_0_,
        myFoo0_.Version as Version3_0_ 
    FROM
        MyFoo myFoo0_
    WHERE
        myFoo0_.AccountId=@p0;
    @p0 = 1 [Type: Int32 (0)]

Another way to have this information (and much more) is to use the nhprof tool.

| More

If you follow my tweets for sure you had read one of these:

2011-05-04_1343

2011-05-04_1343_001

2011-05-04_1345

This is one of the things I most enjoy of working for Tellago. The Tellago Technology Dojo is a webinar that we have once a week to talk about new technologies. Which is a high quality webinar from qualified developers.

Today Tellago announced a series of webinars named “Tellago Technology Updates”, from Jesús Rodriguez blog:

Today, we are really pleased to announce the Tellago Technology Updates series. This program is a periodic series of webinar that will explore in detail debate some of the emerging technologies in the software industry as well as some of our implementation experiences. These Technology Updates are targeted to both IT executives trying to adopt these new technologies as well as developers and architects trying to implement them.

You can follow the Technology Updates series at http://tellago.com/what_we_says/tellago-technology-updates

BOTTOM LINE, WHETHER YOU ARE AN IT EXECUTIVE, ARCHITECT OR DEVELOPER INTERESTED ON UNDERSTANDING SOME OF THESE TECHNOLOGIES, YOU SHOULD NOT MISS THE TELLAGO TECHNOLOGY UPDATES SERIES!!!!!

The first two webinars announced are:

  • NOSQL DATABASES FOR THE .NET DEVELOPER: WHAT’S THE FUSS ALL ABOUT?
  • I LIKE IPHONE AND ANDROID BUT I AM A .NET DEVELOPER: DEVELOPING .NET APPLICATIONS FOR IPHONE AND ANDROID
You can read more about these webinars in our brand new website!
Those webinars are completely free and open to anyone.
If you missed, you will be able to watch the recording offline.

We hope to see you there!

| More

I have created a new package that add support for writing NHibernate logs with NLog.
The package is not a dll but only one class.

In order to use this package, simply install with nuget:

2011-05-04_0838

This is an example app.config file:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>
  <appSettings>
    <add key="nhibernate-logger" value="YourNamespace.NLogFactory, YourAssemblyName"/>
  </appSettings>

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <targets>
      <target name="ds" xsi:type="Console"/>
    </targets>
    <rules>
      <logger name="NHibernate.SQL" minlevel="Debug" writeTo="ds" />
    </rules>
  </nlog>
</configuration>

Remember to change “YourNamespace” and “YourAssemblyName”. That is all.
You don’t need to run Configure or some initialization code as in log4net.

There is an alternative approach here but it is a little bit more complicated.

| More

In this post I will show how to enhance your REST services by providing cache headers in the responses. I am going to show a simple but scalable implementation in the new Wcf Web API; however the intention of this article is purely theoretically.

Introduction

As I am not good explaining things in English and most of the things are already explained, I will simply copy and paste the w3.org explanation for Http Cache:

HTTP is typically used for distributed information systems, where performance can be improved by the use of response caches. The HTTP/1.1 protocol includes a number of elements intended to make caching work as well as possible…

Caching would be useless if it did not significantly improve performance. The goal of caching in HTTP/1.1 is to eliminate the need to send requests in many cases, and to eliminate the need to send full responses in many other cases. The former reduces the number of network round-trips required for many operations; we use an "expiration" mechanism for this purpose (see section 13.2). The latter reduces network bandwidth requirements; we use a "validation" mechanism for this purpose

As the last quote say; the two more important things from HTTP cache is “expiration” and “validation”.
Remember; Http is everywhere and we can take tremendous advantage of the HTTP infrastructure.

Implementation

Lets say that I have a resource like this:

[ServiceContract, WithUriPrefix("order")]
public class OrderResourceHandler
{
    private readonly IRepository<Order> orderRepository;
    
    public OrderResourceHandler(
        IRepository<Order> orderRepository)
    {
        this.orderRepository = orderRepository
    }

    [WebGet(UriTemplate = "{orderId}")]
    public HttpResponseMessage Get(int orderId)
    {
        var order = orderRepository.GetById(orderId);
        if(order == null) return Response.NotFound();
        return Response.WithContent(new OrderRepresentation(order));
    }
}

In this example, every request will hit the handler, the repository, the database and so on. We can take advantage of the Web infrastructure by adding cache instructions to our response

A better implementation with cache headers will be something like this:

[ServiceContract, WithUriPrefix("order")]
public class OrderResourceHandler
{
    private readonly IRepository<Order> orderRepository;
    private readonly ETagCache etagCache;

    public OrderResourceHandler(
        IRepository<Order> orderRepository,
        ETagCache etagCache)
    {
        this.orderRepository = orderRepository
        this.etagCache = etagCache;
    }

    [WebGet(UriTemplate = "{orderId}")]
    public HttpResponseMessage Get(int orderId)
    {
        var order = orderRepository.GetById(orderId);
        if(order == null) return Response.NotFound();

        var response = Response.WithContent(new OrderRepresentation(order));
        AddCacheHeaders(response, order.Id, order.Version);
        return response;
    }

    private void AddCacheHeaders(HttpResponseMessage responseMessage, long orderId, int version)
    {
        //Get the link for the resource: http://mysuperapp.com/order/123
        var link = linker.GetUri<OrderResourceHandler>(orh => orh.Get(0), new { orderId });

        //Get or Add the Etag to the cache.
        var etag = etagCache.GetOrAdd(link, version);

        //Set the 'expiration' and 'validation' (maxage and etag)
        responseMessage.WithCacheControlHeader(c =>
                                {
                                    c.Public = true;
                                    c.MaxAge = TimeSpan.FromSeconds(10);
                                })
                       .WithETagHeader(etag);
    }

}

I choose using “Max-Age” for “expiration” and “ETag” for “validation”. But you can use other mechanism as “Expires” (for expiration) and “Last-Modified” (for validation) or any combination in the middle.

A quick overview to the method:

  • I introduced an ETagCache, this is a cache for the ETags.. The thing is that during conditional get (or validations get) I would like to respond as fast as possible. Even without going to the database. The cache consist of an uri as key and a version number (the actual etag value).
  • I am using as ETag a Version property. This version property is managed by my ORM for concurrency. Each update we do in the entity version increases by one.
  • As max-age I am using 10 seconds. This is only for experimental purposes.

This code add the cache headers to the response.

How we can handle conditional-gets (get for validations)?

Suppose that as an http client we receive a response as follows:

2011-04-27_1559

We, as an intelligent http client now that we can use this representation of the resource for 10 seconds. After those ten seconds, if we need again the representation we might send a conditional request, as follows:

2011-04-27_1605

And when we do such thing we know that two things might happen:

  • The resource has changed in those 10 seconds. So we will probably get a 200-OK response with the new representation of the resource.
  • The resource hasn’t changed, so we get a 302-Not Modified without any content. This means that we can keep using the previous representation that we hold.

I used an specific extension point from the last release of the WCF Web API to handle this, a DelegatingChannel:

public class EntityTagCheckerDelegateChannel : DelegatingChannel
{
    private readonly ETagCache etagCache;

    public EntityTagCheckerDelegateChannel(HttpMessageChannel innerChannel, ETagCache etagCache)
        : base(innerChannel)
    {
        this.etagCache = etagCache;
    }
    
    protected override Task<HttpResponseMessage> SendAsync(
        HttpRequestMessage request, CancellationToken cancellationToken)
    {
        
        if(request.Method == HttpMethod.Get && request.Headers.IfNoneMatch.Any())
        {
            var etag = request.Headers.IfNoneMatch.First().ToString();
            var cached = etagCache.Get(request.RequestUri.ToString());
            return etag == cached ? Task.Factory.StartNew(() => CreateANotModifiedResponse(), 
                                                                cancellationToken)
                                : base.SendAsync(request, cancellationToken);
        }
        return base.SendAsync(request, cancellationToken);
    }

    private static HttpResponseMessage CreateANotModifiedResponse()
    {
        return new HttpResponseMessage(HttpStatusCode.NotModified, "NotModified")
                   {
                       Headers = {CacheControl = new CacheControlHeaderValue
                                                     {
                                                         MaxAge = TimeSpan.FromSeconds(10),
                                                         Public = true
                                                     }}
                   };
    }
}

If the request is a GET, and it contains an IfNoneMatch tag, we compare this with the one in our etagCache. If the tags match, we return a task that returns a NotModified with the same cache headers. If not, we proceed with the invocation to our handler.

When resources change

When the resource change we need to tell to our EtagCache the new value of the ETag. I did this within an extension point of my ORM (because my resource is something stored in a database):

public class OnOrderUpdateInsert : IPostInsertEventListener, IPostUpdateEventListener
{
    private readonly ETagCache etagCache;
    private readonly string baseAddress;
    
    public OnOrderUpdateInsert(EntityTagManager entityTagManager)
        : this(entityTagManager, ConfigurationManager.AppSettings["BaseUri"])
    {
    }

    public OnOrderUpdateInsert(ETagCache etagCache, string baseAddress)
    {
        this.etagCache = etagCache;
        this.baseAddress = baseAddress;
    }

    public void OnPostInsert(PostInsertEvent @event)
    {
        Handle(@event);
    }

    public void OnPostUpdate(PostUpdateEvent @event)
    {
        Handle(@event);
    }

    private void Handle(IPostDatabaseOperationEventArgs @event)
    {
        var entity = @event.Entity as Order;
        if (entity == null) return;
        var link = string.Format("{0}order/{1}", 
                            baseAddress, entity.Id);
        etagCache.Add(link, entity.Version);
    }
}

The ETagCache

The ETagCache is:

public class ETagCache
{
    private readonly ConcurrentDictionary<string, string> cache =
        new ConcurrentDictionary<string, string>();
    
    public void Add(string link, int version)
    {
        cache.AddOrUpdate(link, 
                ToETag(version), 
                (l, prev) => ToETag(version));
    }
    
    public string GetOrAdd(string link, int version)
    {
        return cache.GetOrAdd(link, ToETag(version));
    }

    private static string ToETag(int version)
    {
        return string.Format("\"{0}\"", version);
    }

    public string Get(string link)
    {
        string etag;
        return cache.TryGetValue(link, out etag) ? 
                etag : string.Empty;
    }
}

For now, it is implemented with only a ConcurrentDictionary.
This means that I am assuming that the database is not changed by anyone else than the rest service. Which is quite good for this example, but as soon as you need to change the orders outside this application you will be better of with other kind of ETag cache, with other expiration policy or so.

See the system working

I am using fiddler to test my service. A simple GET request:

#REQUEST

GET http://localhost:13509/order/294912 HTTP/1.1
User-Agent: Fiddler
Accept: text/xml
Host: localhost:13509


#RESPONSE

HTTP/1.1 200 OK
Server: ASP.NET Development Server/10.0.0.0
Date: Wed, 27 Apr 2011 22:36:42 GMT
X-AspNet-Version: 4.0.30319
Content-Length: 844
Cache-Control: public, max-age=10
ETag: "1"
Content-Type: text/xml; charset=utf-8
Connection: Close

<?xml version="1.0" encoding="utf-8"?><order xmlns="....

now that we now the ETag, we can try a conditional get as follows:

#REQUEST

GET http://localhost:13509/order/294912 HTTP/1.1
User-Agent: Fiddler
Accept: text/xml
Host: localhost:13509
If-None-Match: "1"

#RESPONSE

HTTP/1.1 304 Not Modified
Server: ASP.NET Development Server/10.0.0.0
Date: Wed, 27 Apr 2011 22:39:40 GMT
X-AspNet-Version: 4.0.30319
Cache-Control: public, max-age=36000
Connection: Close

Urray! conditional gets work like a charm!

So, now we know that our http clients can validate caches with conditional requests.

Simulating a real world scenario

You can simulate a real world scenario (and potentially scale your application) by using a reverse-proxy (or application proxy), from wikipedia:

In computer networks, a reverse proxy is a type of proxy server that retrieves resources on behalf of a client from one or more servers. These resources are then returned to the client as though it originated from the reverse proxy itself.[1] While a forward proxy is usually situated between the client application (such as a web browser) and the server(s) hosting the desired resources, a reverse proxy is usually situated closer to the server(s) and will only return a configured set of resources.

To simulate a simple scenario, I am using the powerfull squid-cache. If you want to run in your own follow these steps:

  • download the windows version from one of the links..
  • copy etc\mime.conf.default to etc\mime.conf
  • copy squid.conf.default to squid.conf
  • delete all the content of squid.conf.default and add the following:
access_log C:\squid\var\logs\access_log.txt
http_port 3128 accel defaultsite=mysite.com
cache_peer localhost parent 13509 0 no-query originserver name=myAccel

#Recommended minimum configuration:
acl all src all
acl manager proto cache_object
acl localhost src 127.0.0.1/32
acl to_localhost dst 127.0.0.0/8 0.0.0.0/32


acl our_sites dstdomain mysite.com
http_access allow our_sites
cache_peer_access myAccel allow our_sites
cache_peer_access myAccel deny all
  • change the second line with your ip (or leave localhost) and the port you are using to test. This is the address of your application.
  • You can optionally change the 3128 port.
  • run from command line sbin\squid –z . This will create the cache structure on disk.
  • run squid.

Testing against Squid

Now, if you invoke a request on the same uri (but using the squid port), several times from Fiddler as follows:

#REQUEST

GET http://localhost:3128/order/294912 HTTP/1.1
User-Agent: Fiddler
Accept: text/xml
Host: localhost:3128

The application server is not touched for all request to the reverse proxy. Only after 10 seconds we receive a conditional get and most of the time we will answer that request very quickly, i.e. without going to the database. You can put a breakpoint in the delegate channel and you will see no activity.

Then if you go to the access_log.txt of squid, you will see this:

1303947187.453    720 127.0.0.1 TCP_REFRESH_MISS/200 1197 GET http://mysite.com:3128/order/294912 - FIRST_UP_PARENT/myAccel text/xml
1303947189.907      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947190.501      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947191.031      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947191.251      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947191.451      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947191.641      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947191.977      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947192.037      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947216.296   1901 127.0.0.1 TCP_REFRESH_MISS/200 1197 GET http://mysite.com:3128/order/294912 - FIRST_UP_PARENT/myAccel text/xml
1303947219.461      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml
1303947220.997      0 127.0.0.1 TCP_MEM_HIT/200 1204 GET http://mysite.com:3128/order/294912 - NONE/- text/xml

where TCP_MEM_HIT means "A valid copy of the object was in the memory cache", while "TCP_REFRESH_MISS" means the requested object wasn't in the cache.

Final notes

This is the way the web scale. Now a client can be polling and our application without bother our application.

If you want to learn more about caches, http and rest; I strongly recommend you the book Rest In Practice.
This is part of a major example application I am doing in Tellago. The sample application will be Open Source and released soon.

I hope you find this useful, or at least… informative.

| More

I wrote an approach to make -resource linking- easier with the new Web Api in this post. This is an alternative approach and I think it is much better.

This time I wrote the Uri template in only one place;

[ServiceContract, WithUriPrefix("products")]
public class ProductsResourceHandler
{
    [WebGet(UriTemplate = "")]
    public Product[]  Get()
    {
        //handle 
    }
    
    [WebGet(UriTemplate = "{productId}")]
    public Product GetProductById(int productId)
    {
        //handle 
    }
}

Now, if I with my uri template there; I can register all routes as follows:

public static class RouteTableConfigurator
{
    public static void Configure(IHttpHostConfigurationBuilder builder)
    {
        var routeInfo = typeof (RouteTableConfigurator)
            .Assembly.GetTypes()
            .Where(t => Attribute.IsDefined(t, typeof (ServiceContractAttribute))
                        && Attribute.IsDefined(t, typeof (WithUriPrefix)))
            .Select(t => new{ ServiceType = t, UriPrefix = GetPrefix(t)});

        var routes = routeInfo
            .Select(rinfo => new ServiceRoute(rinfo.UriPrefix, 
                                              new HttpConfigurableServiceHostFactory
                                                    {
                                                        Builder = builder
                                                    }, 
                                              rinfo.ServiceType));


        foreach (var route in routes)
        {
            RouteTable.Routes.Add(route);
        }
    }

    private static string GetPrefix(Type t)
    {
        return t.GetCustomAttributes(typeof(WithUriPrefix), true)
                .OfType<WithUriPrefix>()
                .First().Uri;
    }
}

This only works if you can register everything with the same configuration, otherwise you will must to define other set of conventions. But for this example it works

Then my IResourceLinker interface is:

public interface IResourceLinker
{
    string GetUri<T>(Expression<Action<T>> method, object uriArgs = null);
}

How the implementation should work?

[TestFixture]
public class LocationsSpecifications
{
    
    protected IResourceLinker resourceLinker 
        = new ResourceLinker("http://foo.bar");
    
    [Test]
    public void TheUriOfProductsIsOk()
    {
        resourceLinker.GetUri<ProductsResourceHandler>(pr => pr.Get())
            .Should().Be.EqualTo("http://foo.bar/products");
    }

    [Test]
    public void TheUriToGetAProductIsOk()
    {
        resourceLinker.GetUri<ProductsResourceHandler>(pr => pr.GetProductById(0), 
                                                       new{productId = 123})
            .Should().Be.EqualTo("http://foo.bar/products/123");
    }
}

And the implementation is:

public class ResourceLinker : IResourceLinker
{
    private readonly Uri baseUri;

    public ResourceLinker(string baseUri)
    {
        this.baseUri = new Uri(baseUri, UriKind.Absolute);
    }

    public string GetUri<T>(Expression<Action<T>> method, object uriArgs = null)
    {
        string prefix = GetServicePrefix<T>();

        var methodInfo = ((MethodCallExpression)method.Body).Method;
        var methodTemplate = GetUriTemplateForMethod(methodInfo);
    
        var newBaseUri = new Uri(baseUri, prefix);
        var uriTemplate = new UriTemplate(methodTemplate, true);

        return uriTemplate.BindByName(newBaseUri, ToDictionary(uriArgs ?? new{})).ToString();
    }

    public static IDictionary<string, string> ToDictionary(object anonymousInstance)
    {
        var dictionary = anonymousInstance as IDictionary<string, string>;
        if (dictionary != null) return dictionary;

        return TypeDescriptor.GetProperties(anonymousInstance)
            .OfType<PropertyDescriptor>()
            .ToDictionary(p => p.Name, p => p.GetValue(anonymousInstance).ToString());
    }

    private static string GetServicePrefix<T>()
    {
        var withUriPrefixAttribute = typeof (T)
                            .GetCustomAttributes(typeof (WithUriPrefix), true)
                            .OfType<WithUriPrefix>()
                            .FirstOrDefault();

        if(withUriPrefixAttribute == null )
        {
            var message = string.Format("Can't find the WithUriPrefix in {0}", typeof(T).Name);
            throw new InvalidOperationException(message);
        }
        return withUriPrefixAttribute.Uri;
    }

    private static string GetUriTemplateForMethod(MethodInfo method)
    {
        var webGet = method.GetCustomAttributes(true)
                            .OfType<WebGetAttribute>()
                            .FirstOrDefault();
        if (webGet != null) return webGet.UriTemplate ?? method.Name;

        var webInvoke = method.GetCustomAttributes(true)
                            .OfType<WebInvokeAttribute>()
                            .FirstOrDefault();
        if (webInvoke != null) return webInvoke.UriTemplate ?? method.Name;

        var message = string.Format("The method {0} is not a web method.", method.Name);
        throw new InvalidOperationException(message);
    }
}

I am still not happy with this, but it is nicer and less invasive than the first aproach.

| More