Invoke SetModuleContext without breaking IIS 10 logs

Published Dec 10 2018 01:47 AM 1,279 Views
Microsoft

When it comes to IIS extensibility, possibly ASP.NET is the easiest and most versatile choice. In fact, starting with IIS 7, the integrated pipeline allows custom managed code that implements System.Web.IHttpModule to be registered for all the IIS pipeline events. This means .NET code can be used to extend all sorts of applications, including those relying on native handlers, at the only cost of loading the .NET runtime within the IIS worker process.

 

However, there may well be situations where .NET is not the best option, let alone when it is just not an option at all. In such cases IIS also offers native pipeline extensibility solutions. The CGlobalModule and CHttpModule classes are great examples of how developers can implement their own classes and register them to the IIS pipeline notification events.
Compared to managed ones, native modules can be more articulated to develop. Still the design principles behind them are similar. Native modules can register to multiple pipeline notification events, which essentially means different functions can be invoked at different stages of the request lifecycle.

 

Thus, data persistence across multiple executions is key in building stateful modules. The IHttpStoredContext interface is designed to address this requirement.
As memory management in native code is more articulated and http modules and their stored context classes can access several resources shared with other parties (i.e. the other pipeline modules), a proper knowledge and usage of the APIs is paramount is preventing cumbersome issues like the following.

 

Issue

The problem is essentially IIS 10 not logging any request for a site where a native module is installed.

 

To add more context, let the module inherit from CHttpModule and implement IHttpStoredContext. Once installed the module works just fine and it is able to carry out all its tasks. Oddly enough, logs are also working for all the other sites which don’t have the module installed.
To complicate the situation even more, let the very same module (literally the same .dll file) be installed on a IIS 8.5 server with no logging issues at all.

 

At a first glance, such an issue would seem to relate to a regression in IIS 10. However, no relevant code changes between IIS 8.5 and 10 were made as far as native extensibility and logging are concerned.

 

Cause

Extensive and in-depth troubleshooting reveals the underlying issue is the custom module overwrites the HttpLoggingModule own stored context. How could it be?

 

The module is, among other things, registering for multiple pipeline events. It is also setting a custom context to persist data throughout the whole request lifecycle.
The module is registering its context with a code similar to:

        {
            CStoredContext* myCtx = new CStoredContext;
            myCtx->Initialize();
                …
            ctxContainer->SetModuleContext((IHttpStoredContext*)myCtx, NULL);
        }

It is key to note the SetModuleContext API expects the module registration ID as second parameter. IIS assigns a unique ID to each module when it first registers:

    static HRESULT RegisterGlobalModule
    (
        DWORD dwServerVersion,
        IHttpModuleRegistrationInfo* pModuleInfo,
        IHttpServer* pGlobalInfo
    ){…}

The module ID is actually more than just an identifier. Actually it is the index of the module registration within the registration array managed by IIS (the data structure is actually a more articulated linked list, but here we can safely assume it works exactly like an array).  

 

You may have noticed already that in the code above NULL is passed to SetModuleContext as second parameter. NULL is casted to 0 at runtime (HTTP_MODULE_ID defaults to 0) which means IIS will interpret the module registration to be in the first slot. Therefore, when writing to its own stored context, the module would overwrite any data previously set by other modules.

 

This is exactly the situation here: in fact the http logging module is registering as first in position 0. Then, whenever the other native module runs, it overwrites the previously registered context, preventing the actual log from being dispatched to the logging service for writing.

 

Resolution

This is a typical situation where a proper usage of the API can lead to a quick and immediate problem resolution. Specifically, all it takes is to properly pass the actual module registration id to SetModuleContext. A way to do this right is simply by storing the module id in a global variable: 

protected:
    DummyGlobalModule(HTTP_MODULE_ID moduleId)
    {
        m_moduleId = moduleId;
    }
private:
    HTTP_MODULE_ID m_moduleId;

Then, populate it when the module is registered:

    static HRESULT RegisterGlobalModule
    (
        DWORD dwServerVersion,
        IHttpModuleRegistrationInfo* pModuleInfo,
        IHttpServer* pGlobalInfo
    )
    {
        if (NULL == pModuleInfo)
        {
            return E_INVALIDARG;
        }

        HTTP_MODULE_ID moduleId = pModuleInfo->GetId();
        if (NULL == moduleId)
        {
            return E_INVALIDARG;
        }
        DummyGlobalModule* dummyModule = new DummyGlobalModule(moduleId);

Eventually call SetModuleContext like this:

        {
            CStoredContext* myCtx = new CStoredContext;
            myCtx->Initialize();
                …
            ctxContainer->SetModuleContext((IHttpStoredContext*)myCtx, m_moduleId);
        }

 

For those who are wondering why in IIS 8.5 this issue does not occur, the answer is again linked to the way the API works. In fact, the module registration order is opportunistically set at runtime and depends on the module registration order.
Indeed, in IIS 10 the http logging module was shifted earlier in the modules list. It is high likely in IIS 8.5 the native module is registering before the http logging module, hence getting assigned to the registration slot 0. This is what indirectly validates using NULL as module ID when calling SetModuleContext and makes everything work seamlessly, despite the API usage is incorrect.

 

%3CLINGO-SUB%20id%3D%22lingo-sub-298176%22%20slang%3D%22en-US%22%3EInvoke%20SetModuleContext%20without%20breaking%20IIS%2010%20logs%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-298176%22%20slang%3D%22en-US%22%3E%3CP%3EWhen%20it%20comes%20to%20IIS%20extensibility%2C%20possibly%20ASP.NET%20is%20the%20easiest%20and%20most%20versatile%20choice.%20In%20fact%2C%20starting%20with%20IIS%207%2C%20the%20%3CSTRONG%3Eintegrated%20pipeline%20%3C%2FSTRONG%3Eallows%20custom%20managed%20code%20that%20implements%20%3CSTRONG%3ESystem.Web.IHttpModule%3C%2FSTRONG%3E%20to%20be%20registered%20for%20all%20the%20IIS%20pipeline%20events.%20This%20means%20.NET%20code%20can%20be%20used%20to%20extend%20all%20sorts%20of%20applications%2C%20including%20those%20relying%20on%20native%20handlers%2C%20at%20the%20only%20cost%20of%20loading%20the%20.NET%20runtime%20within%20the%20IIS%20worker%20process.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EHowever%2C%20there%20may%20well%20be%20situations%20where%20.NET%20is%20not%20the%20best%20option%2C%20let%20alone%20when%20it%20is%20just%20not%20an%20option%20at%20all.%20In%20such%20cases%20IIS%20also%20offers%20native%20pipeline%20extensibility%20solutions.%20The%20%3CSPAN%3E%3CSTRONG%3E%3CA%20href%3D%22https%3A%2F%2Fmsdn.microsoft.com%2Fen-us%2Flibrary%2Fms694289(v%3Dvs.90).aspx%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3ECGlobalModule%3C%2FA%3E%3C%2FSTRONG%3E%3C%2FSPAN%3E%20and%20%3CSPAN%3E%3CSTRONG%3E%3CA%20href%3D%22https%3A%2F%2Fmsdn.microsoft.com%2Fen-us%2Flibrary%2Fms693685(v%3Dvs.90).aspx%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3ECHttpModule%3C%2FA%3E%3C%2FSTRONG%3E%3C%2FSPAN%3E%20classes%20are%20great%20examples%20of%20how%20developers%20can%20implement%20their%20own%20classes%20and%20register%20them%20to%20the%20IIS%20pipeline%20notification%20events.%3CBR%20%2F%3E%20Compared%20to%20managed%20ones%2C%20native%20modules%20can%20be%20more%20articulated%20to%20develop.%20Still%20the%20design%20principles%20behind%20them%20are%20similar.%20Native%20modules%20can%20register%20to%20multiple%20pipeline%20notification%20events%2C%20which%20essentially%20means%20different%20functions%20can%20be%20invoked%20at%20different%20stages%20of%20the%20request%20lifecycle.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EThus%2C%20data%20persistence%20across%20multiple%20executions%20is%20key%20in%20building%20stateful%20modules.%20The%20%3CSPAN%3E%3CSTRONG%3E%3CA%20href%3D%22https%3A%2F%2Fmsdn.microsoft.com%2Fen-us%2Flibrary%2Fms691151(v%3Dvs.90).aspx%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3EIHttpStoredContext%3C%2FA%3E%3C%2FSTRONG%3E%3C%2FSPAN%3E%20interface%20is%20designed%20to%20address%20this%20requirement.%3CBR%20%2F%3E%20As%20memory%20management%20in%20native%20code%20is%20more%20articulated%20and%20http%20modules%20and%20their%20stored%20context%20classes%20can%20access%20several%20resources%20shared%20with%20other%20parties%20(i.e.%20the%20other%20pipeline%20modules)%2C%20a%20proper%20knowledge%20and%20usage%20of%20the%20APIs%20is%20paramount%20is%20preventing%20cumbersome%20issues%20like%20the%20following.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CFONT%20size%3D%225%22%3E%3CU%3E%3CSTRONG%3EIssue%3C%2FSTRONG%3E%3C%2FU%3E%3C%2FFONT%3E%3C%2FP%3E%0A%3CP%3EThe%20problem%20is%20essentially%20IIS%2010%20not%20logging%20%3CSTRONG%3Eany%20%3C%2FSTRONG%3Erequest%20for%20a%20site%20where%20a%20native%20module%20is%20installed.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3ETo%20add%20more%20context%2C%20let%20the%20module%20inherit%20from%20%3CSTRONG%3ECHttpModule%20%3C%2FSTRONG%3Eand%20implement%20%3CSTRONG%3EIHttpStoredContext.%20%3C%2FSTRONG%3EOnce%20installed%20the%20module%20works%20just%20fine%20and%20it%20is%20able%20to%20carry%20out%20all%20its%20tasks.%20Oddly%20enough%2C%20logs%20are%20also%20working%20for%20all%20the%20other%20sites%20which%20don%E2%80%99t%20have%20the%20module%20installed.%3CBR%20%2F%3E%20To%20complicate%20the%20situation%20even%20more%2C%20let%20the%20very%20same%20module%20(literally%20the%20same%20.dll%20file)%20be%20installed%20on%20a%20IIS%208.5%20server%20with%20no%20logging%20issues%20at%20all.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EAt%20a%20first%20glance%2C%20such%20an%20issue%20would%20seem%20to%20relate%20to%20a%20regression%20in%20IIS%2010.%20However%2C%20no%20relevant%20code%20changes%20between%20IIS%208.5%20and%2010%20were%20made%20as%20far%20as%20native%20extensibility%20and%20logging%20are%20concerned.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CFONT%20size%3D%225%22%3E%3CSTRONG%3E%3CU%3ECause%3C%2FU%3E%3C%2FSTRONG%3E%3C%2FFONT%3E%3C%2FP%3E%0A%3CP%3EExtensive%20and%20in-depth%20troubleshooting%20reveals%20the%20underlying%20issue%20is%20the%20custom%20module%20overwrites%20the%20%3CSTRONG%3EHttpLoggingModule%3C%2FSTRONG%3E%20own%20stored%20context.%20How%20could%20it%20be%3F%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EThe%20module%20is%2C%20among%20other%20things%2C%20registering%20for%20multiple%20pipeline%20events.%20It%20is%20also%20setting%20a%20custom%20context%20to%20persist%20data%20throughout%20the%20whole%20request%20lifecycle.%3CBR%20%2F%3E%20The%20module%20is%20registering%20its%20context%20with%20a%20code%20similar%20to%3A%3C%2FP%3E%0A%3CPRE%3E%20%20%20%20%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20CStoredContext*%20myCtx%20%3D%20new%20CStoredContext%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20myCtx-%26gt%3BInitialize()%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%E2%80%A6%0A%20%20%20%20%20%20%20%20%20%20%20%20ctxContainer-%26gt%3BSetModuleContext((IHttpStoredContext*)myCtx%2C%20NULL)%3B%0A%20%20%20%20%20%20%20%20%7D%0A%3C%2FPRE%3E%0A%3CP%3EIt%20is%20key%20to%20note%20the%20%3CSPAN%3E%3CSTRONG%3E%3CA%20href%3D%22https%3A%2F%2Fmsdn.microsoft.com%2Fen-us%2Flibrary%2Fms693620(v%3Dvs.90).aspx%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3ESetModuleContext%3C%2FA%3E%3C%2FSTRONG%3E%3C%2FSPAN%3E%20API%20expects%20the%20module%20registration%20ID%20as%20second%20parameter.%20IIS%20assigns%20a%20unique%20ID%20to%20each%20module%20when%20it%20first%20registers%3A%3C%2FP%3E%0A%3CPRE%3E%20%20%20%20static%20HRESULT%20RegisterGlobalModule%0A%20%20%20%20(%0A%20%20%20%20%20%20%20%20DWORD%20dwServerVersion%2C%0A%20%20%20%20%20%20%20%20IHttpModuleRegistrationInfo*%20pModuleInfo%2C%0A%20%20%20%20%20%20%20%20IHttpServer*%20pGlobalInfo%0A%20%20%20%20)%7B%E2%80%A6%7D%0A%3C%2FPRE%3E%0A%3CP%3EThe%20module%20ID%20is%20actually%20more%20than%20just%20an%20identifier.%20Actually%20it%20is%20the%20index%20of%20the%20module%20registration%20within%20the%20registration%20array%20managed%20by%20IIS%20(the%20data%20structure%20is%20actually%20a%20more%20articulated%20linked%20list%2C%20but%20here%20we%20can%20safely%20assume%20it%20works%20exactly%20like%20an%20array).%20%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EYou%20may%20have%20noticed%20already%20that%20in%20the%20code%20above%20NULL%20is%20passed%20to%20%3CSTRONG%3ESetModuleContext%3C%2FSTRONG%3E%20as%20second%20parameter.%20NULL%20is%20casted%20to%200%20at%20runtime%20(HTTP_MODULE_ID%20defaults%20to%200)%20which%20means%20IIS%20will%20interpret%20the%20module%20registration%20to%20be%20in%20the%20first%20slot.%20Therefore%2C%20when%20writing%20to%20its%20own%20stored%20context%2C%20the%20module%20would%20overwrite%20any%20data%20previously%20set%20by%20other%20modules.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EThis%20is%20exactly%20the%20situation%20here%3A%20in%20fact%20the%20http%20logging%20module%20is%20registering%20as%20first%20in%20position%200.%20Then%2C%20whenever%20the%20other%20native%20module%20runs%2C%20it%20overwrites%20the%20previously%20registered%20context%2C%20preventing%20the%20actual%20log%20from%20being%20dispatched%20to%20the%20logging%20service%20for%20writing.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CFONT%20size%3D%225%22%3E%3CU%3E%3CSTRONG%3EResolution%3C%2FSTRONG%3E%3C%2FU%3E%3C%2FFONT%3E%3C%2FP%3E%0A%3CP%3EThis%20is%20a%20typical%20situation%20where%20a%20proper%20usage%20of%20the%20API%20can%20lead%20to%20a%20quick%20and%20immediate%20problem%20resolution.%20Specifically%2C%20all%20it%20takes%20is%20to%20properly%20pass%20the%20actual%20module%20registration%20id%20to%20%3CSTRONG%3ESetModuleContext%3C%2FSTRONG%3E.%20A%20way%20to%20do%20this%20right%20is%20simply%20by%20storing%20the%20module%20id%20in%20a%20global%20variable%3A%26nbsp%3B%3C%2FP%3E%0A%3CPRE%3Eprotected%3A%0A%20%20%20%20DummyGlobalModule(HTTP_MODULE_ID%20moduleId)%0A%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20m_moduleId%20%3D%20moduleId%3B%0A%20%20%20%20%7D%0Aprivate%3A%0A%20%20%20%20HTTP_MODULE_ID%20m_moduleId%3B%3C%2FPRE%3E%0A%3CP%3EThen%2C%20populate%20it%20when%20the%20module%20is%20registered%3A%3C%2FP%3E%0A%3CPRE%3E%20%20%20%20static%20HRESULT%20RegisterGlobalModule%0A%20%20%20%20(%0A%20%20%20%20%20%20%20%20DWORD%20dwServerVersion%2C%0A%20%20%20%20%20%20%20%20IHttpModuleRegistrationInfo*%20pModuleInfo%2C%0A%20%20%20%20%20%20%20%20IHttpServer*%20pGlobalInfo%0A%20%20%20%20)%0A%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20if%20(NULL%20%3D%3D%20pModuleInfo)%0A%20%20%20%20%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20return%20E_INVALIDARG%3B%0A%20%20%20%20%20%20%20%20%7D%0A%0A%20%20%20%20%20%20%20%20HTTP_MODULE_ID%20moduleId%20%3D%20pModuleInfo-%26gt%3BGetId()%3B%0A%20%20%20%20%20%20%20%20if%20(NULL%20%3D%3D%20moduleId)%0A%20%20%20%20%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20return%20E_INVALIDARG%3B%0A%20%20%20%20%20%20%20%20%7D%0A%20%20%20%20%20%20%20%20DummyGlobalModule*%20dummyModule%20%3D%20new%20DummyGlobalModule(moduleId)%3B%0A%3C%2FPRE%3E%0A%3CP%3EEventually%20call%20%3CSTRONG%3ESetModuleContext%3C%2FSTRONG%3E%20like%20this%3A%3C%2FP%3E%0A%3CPRE%3E%20%20%20%20%20%20%20%20%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20CStoredContext*%20myCtx%20%3D%20new%20CStoredContext%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20myCtx-%26gt%3BInitialize()%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%E2%80%A6%0A%20%20%20%20%20%20%20%20%20%20%20%20ctxContainer-%26gt%3BSetModuleContext((IHttpStoredContext*)myCtx%2C%20m_moduleId)%3B%0A%20%20%20%20%20%20%20%20%7D%0A%3C%2FPRE%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EFor%20those%20who%20are%20wondering%20why%20in%20IIS%208.5%20this%20issue%20does%20not%20occur%2C%20the%20answer%20is%20again%20linked%20to%20the%20way%20the%20API%20works.%20In%20fact%2C%20the%20module%20registration%20order%20is%20opportunistically%20set%20at%20runtime%20and%20depends%20on%20the%20module%20registration%20order.%3CBR%20%2F%3E%20Indeed%2C%20in%20IIS%2010%20the%20http%20logging%20module%20was%20shifted%20earlier%20in%20the%20modules%20list.%20It%20is%20high%20likely%20in%20IIS%208.5%20the%20native%20module%20is%20registering%20before%20the%20http%20logging%20module%2C%20hence%20getting%20assigned%20to%20the%20registration%20slot%200.%20This%20is%20what%20indirectly%20validates%20using%20NULL%20as%20module%20ID%20when%20calling%20%3CSTRONG%3ESetModuleContext%20%3C%2FSTRONG%3Eand%20makes%20everything%20work%20seamlessly%2C%20despite%20the%20API%20usage%20is%20incorrect.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-TEASER%20id%3D%22lingo-teaser-298176%22%20slang%3D%22en-US%22%3E%3CP%3EThis%20blog%20article%20provides%20a%20high-level%20overview%20of%20IIS%20native%20modules%20extensibility%20APIs.%20In%20particular%2C%20it%20focuses%20on%20the%20proper%20usage%20of%20the%20IHttpStoredContext%20interface.%3C%2FP%3E%0A%3CP%3EStarting%20from%20a%20real-world%20support%20case%26nbsp%3Bworked%20by%20the%20Microsoft%20IIS%20Support%20team%2C%20it%20demonstrates%20how%20a%20proper%20usage%20of%20the%20native%20IIS%20APIs%20can%20prevent%20incurring%20into%20cumbersome%20issues.%3C%2FP%3E%3C%2FLINGO-TEASER%3E%3CLINGO-LABS%20id%3D%22lingo-labs-298176%22%20slang%3D%22en-US%22%3E%3CLINGO-LABEL%3Ecoding%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3Ehttp%20module%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3EIIS%3C%2FLINGO-LABEL%3E%3C%2FLINGO-LABS%3E
Version history
Last update:
‎Dec 10 2018 01:47 AM
Updated by: