'HttpModule is being initialized' mystery - mitikov/KeepSitecoreSimple GitHub Wiki

Weird log entries

You might have seen following log entries in Sitecore logs:

2244 15:00:46 INFO HttpModule is being initialized

13236 15:00:46 INFO HttpModule is being initialized

Let's try to figure out where are they coming from, and why could they be useful.

Boring part

ASP.NET theory

HTTP module is called on every request that is made to your application.

HTTP modules are called as part of the request pipeline and have access to life-cycle events throughout the request.

HTTP modules, therefore, let you examine incoming requests and take action based on the request. They also let you examine the outgoing response and modify it.

In human-readable language: whenever a request reaches your application, HttpModule is here to react per application life cycle

Where are modules defined?

HttpModules are defined under 'system.webServer/modules' node in web.config:

http_module_definition

How do modules fit into request processing pipeline?

  1. An HttpApplication instance is assigned for the request processing
  2. HttpApplication has a collection of modules property that contains all the configured modules
  3. One application can process only one request at a time, so concurrent requests are processed by different application instances

Since modules are stored inside HttpApplication instance, they should logically be created together with HttpApplication.

Who creates HttpApplication instances?

The HttpApplicationFactory is responsible for providing HttpApplication instances, and uses object pooling - reusing constructed instances.

Once request processing is over, an object instance is returned into the pool.

Idea: New objects are created only when the pool is empty.

Do not believe anything until you reproduce

The game plan is to submit requests to Sitecore faster than it can process them.

We'll create a 'SleepBaby.aspx' page that will be processed slowly, thus taking an application instance from the pool for a while:

void Page_Load(object sender, System.EventArgs e)

{

System.Threading.Thread.Sleep(30* 1000);

}

Action plan:

  1. Let Sitecore start, and inspect logs
  2. Open new tab in the browser, and request 'SleepBaby.aspx' page
  3. Open a few tabs more, and request the same page again and again

Result:

  • Each request requires an instance of HttpApplication
  • The HttpApplication factory tries to get an HttpApplication from inner pool
  • Once pool becomes empty, new HttpApplation with inner collections of HttpModules is created, thus message is printed into logs
  • Each further incoming request would provoke new HttpApplication creation together with all the HttpModules

Summary of all the boring arguments

HttpModule is being initialized message is logged only when all existing application instances are used for requests processing.

These messages are completely expected when an application starts as it should create sufficient objects as it has concurrent requests.

HttpApplication instances will not be created thanks to pooling implementation if the load is constant and server can handle it.

Seeing these messages in log files means either:

  • A burst of traffic reached server - more requests than usually are to be processed
  • Requests are reaching server faster than it can process them

Note: The message is printed by Sitecore.Nexus.Web.HttpModule class constructor.