March, 2009

  • Never doubt thy debugger

    Fatal Execution Engine Error on x64 Framework

    • 10 Comments

    I got two FEEE cases in a row last week, both of them for the same cause so I thought to blog about it hoping to save some stress and headshakes to someone else.

    The affected platform is 64 bit Framework (32 bit works fine), either Web or Windows application: randomly the application crashes and if you check your event log you’ll find messages like the following:

    Event Type:      Error
    Event Source:   .NET Runtime
    Date:                12-02-2009 10:58:36
    User:                N/A
    Computer:       <computername>
    Description: .NET Runtime version 2.0.50727.3082 - Fatal Execution Engine Error (000006427F8A5DC8) (80131506)

    The stack of the faulting thread looks like this:

    0:025> kpL1000
    Child-SP          RetAddr           Call Site
    00000000`0643e350 00000642`78acb013 mscorwks!COMCryptography::_DecryptData+0x329
    00000000`0643e590 00000642`801f4b87 mscorlib_ni!System.Security.Cryptography.CryptoAPITransform.TransformFinalBlock(<HRESULT 0x80004001>)+0x123
    00000000`0643e620 00000642`801f25c7 CryptoSample!MyCryptoClass.Decrypt(<HRESULT 0x80004001>)+0xf7
    00000000`0643e960 00000642`bc8e449b System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute(<HRESULT 0x80004001>)+0x257
    00000000`0643ea10 00000642`bc8f2215 System_Web_ni!System.Web.HttpApplication.ExecuteStep(<HRESULT 0x80004001>)+0xab
    00000000`0643eab0 00000642`bc8e3553 System_Web_ni!System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(<HRESULT 0x80004001>)+0x1a5
    00000000`0643eb60 00000642`bc8e7874 System_Web_ni!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(<HRESULT 0x80004001>)+0xd3
    00000000`0643ebc0 00000642`bc8e745c System_Web_ni!System.Web.HttpRuntime.ProcessRequestInternal(<HRESULT 0x80004001>)+0x1c4
    00000000`0643ec50 00000642`bc8e608c System_Web_ni!System.Web.HttpRuntime.ProcessRequestNoDemand(<HRESULT 0x80004001>)+0x7c
    00000000`0643ec90 00000642`7f602322 System_Web_ni!System.Web.Hosting.ISAPIRuntime.ProcessRequest(<HRESULT 0x80004001>)+0x18c
    00000000`0643edc0 00000642`7f503bb3 mscorwks!CallDescrWorker+0x82
    00000000`0643ee20 00000642`7f5251f8 mscorwks!CallDescrWorkerWithHandler+0xd3
    00000000`0643eec0 00000642`7f525563 mscorwks!ForwardCallToManagedMethod+0x160
    00000000`0643ef60 00000642`7f544738 mscorwks!COMToCLRWorkerBody+0x35b
    00000000`0643f1c0 00000642`7f50c8ae mscorwks!COMToCLRWorkerDebuggerWrapper+0x50
    00000000`0643f230 00000642`7f60249e mscorwks!COMToCLRWorker+0x366
    00000000`0643f520 00000642`fff58293 mscorwks!GenericComCallStub+0x5e
    00000000`0643f5d0 00000642`fff58633 webengine!HttpCompletion::ProcessRequestInManagedCode+0x2a3
    00000000`0643fa80 00000642`fff9abf4 webengine!HttpCompletion::ProcessCompletion+0x63
    00000000`0643fac0 00000642`7f48dc77 webengine!CorThreadPoolWorkitemCallback+0x24
    00000000`0643faf0 00000642`7f4a289a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x157
    00000000`0643fb90 00000642`7f41f0ac mscorwks!ThreadpoolMgr::WorkerThreadStart+0x1ba
    00000000`0643fc30 00000000`77d6b6da mscorwks!Thread::intermediateThreadProc+0x78
    00000000`0643ff80 00000000`00000000 kernel32!BaseThreadStart+0x3a
    
    
    
    
    
    0:025> !clrstack
    OS Thread Id: 0x1258 (25)
    Child-SP         RetAddr          Call Site
    000000000643e590 00000642801f4b87 System.Security.Cryptography.CryptoAPITransform.TransformFinalBlock(Byte[], Int32, Int32)
    000000000643e620 00000642801f25c7 MyCryptoClass.Decrypt(System.String, System.String, Boolean)
    000000000643e960 00000642bc8e449b System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
    000000000643ea10 00000642bc8f2215 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
    000000000643eab0 00000642bc8e3553 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
    000000000643eb60 00000642bc8e7874 System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
    000000000643ebc0 00000642bc8e745c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
    000000000643ec50 00000642bc8e608c System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
    000000000643ec90 000006427f602322 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

    If in your code you are calling Convert.FromBase64String (or CryptoAPITransform.TransformFinalBlock directly) assure you are not passing an empty string as the value to convert, for example:

    Public Function Decrypt(ByVal Source As String) As String
        
        Dim byteArr As Byte() = System.Convert.FromBase64String(Source)
        
        [...]
        
    End Function

    should instead look like this:

    Public Function Decrypt(ByVal Source As String) As String
        'convert from Base64 to binary
    
        If IsNullOrEmpty(Source) Then
            Return String.Empty
        End If
        
        Dim byteArr As Byte() = System.Convert.FromBase64String(Source)
        
        [...]
        
    End Function

    Carlo

    Quote of the day:
    The world is full of people whose notion of a satisfactory future is, in fact, a return to the idealized past. - Robertson Davies
  • Never doubt thy debugger

    IIS logs around midnight

    • 0 Comments

    Recently I had an interesting discussion with a friend of mine about IIS logging: basically he configured his web server to create a new log every day and then wanted to use a third party tool to extract some statistics and graphics from the logs. Unfortunately the tool often has troubles and gets weird results because sometime at the end of the old log file (the one about the ending day) they have some records whose date and time is into the new day. Something like the following:

    #Software: Microsoft Internet Information Services 7.0
    #Version: 1.0
    #Date: 2009-03-06 23:59:53
    #Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger.htm - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/global.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/light_sidebar_left_wide.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/customcss.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/vjr6phmypy.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/msAnalytics.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/PopupPanel.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/style.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
    2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/trans_pixel.gif - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0
    2009-03-07 00:00:01 ::1 GET /Themes/Blogs/luxinterior/style/print.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 0 2 15
    2009-03-07 00:00:01 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/Modal.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0
    2009-03-07 00:00:02 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/InlineEditor.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0

    Even if this is not easy to reproduce (I had to try quite a few times to get enough load on IIS and obtain the result above) this behavior is expected: when a client requests a web page, very likely IIS will have to serve multiple files as part of that same request (the page itself plus any linked/included image, CSS style, script etc…), we can say those resources are all part of a single logical request and therefore are treated as a single unit. So if for example you get a request at 23:59:59 very likely the page execution will take more than 1 second, let alone serving the images and other files that might be several Kb large… If we are around midnight we’ll very likely have a few resources served into the new day but logged in the previous day’s file, which is the one there the start of the logical request belongs. Usually this is a “gap” just a few seconds long, normally 2-3 seconds into the new day, even if a longer timeframe in theory cannot be excluded.

    A possible solution for this friend of mine is to customize the IIS logging mechanism (see Customize IIS logging), but this could have an impact on performance (one of the requirements here was to not affect the current performance in any way) even simply because of the time needed for the information to transit from kernel mode (IIS default) to user mode. This was not an option in our case.

    Anyway you can LogParser to extract your statistics (I have some sample scripts here), or as my friend finally chose, you can use LogParser to reformat your IIS log files and exactly dividing the records as you (or your statistical application) prefer. For example:

    logparser "select date, time, s-ip, cs-method, cs-uri-stem, cs-uri-query, s-port, cs-username, c-ip, 
                cs(User-Agent), sc-status, sc-substatus, sc-win32-status, time-taken into day_1.csv from *.log 
                where to_timestamp(date,time) between timestamp('2009/03/06 00:00:00', 'yyyy/MM/dd hh:mm:ss') 
                and timestamp('2009/03/06 23:59:59', 'yyyy/MM/dd hh:mm:ss')" 
                -i:iisw3c -o:tsv -headers:on -oSeparator:space

    As usual note that the command must be on a single line, I’m breaking the line here only to improve readability.

    The script above is quite simple and “static”, it takes into account only a specific day and output log file, anyway it should not be too difficult to include is in a vbscript or batch file to dynamically parse and output all of your IIS log files at once.

    By the way, do not forget the –consolidateLogs parameter for the IISW3C input file type if you have multiple virtual sites and want to consolidate your data:

    consolidateLogs

    Values: ON | OFF

    Default: OFF

    Description: Return entries from all the input log files ordering by date and time.

    Details:
    When a from-entity refers to log files from multiple IIS virtual sites, specifying ON for this parameter causes the IISW3C input format to parse all the input log files in parallel, returning entries ordered by the values of the "date" and "time" fields in the log files; the input records returned will thus appear as if a single IISW3C log file was being parsed.
    Enabling this feature is equivalent to executing a query with an "ORDER BY date, time" clause on all the log files. However, the implementation of this feature leverages the pre-existing chronological order of entries in each log file, and it does not require the extensive memory resources otherwise required by the ORDER BY query clause.

     

    Carlo

    Quote of the day:
    Your true value depends entirely on what you are compared with. - Bob Wells
  • Never doubt thy debugger

    WebResource.axd going over HTTP when we are browsing on HTTPS

    • 1 Comments

    Consider this scenario: you are browsing a web site which at some point switches from http to https, and your browser show you a warning.

    In Firefox you get:

    Connection Partially Encrypted
    Parts of the page you are viewing were not encrypted before being transmitted over
    the Internet.
    Information sent over the Internet without encryption can be seen by other people
    while it is in transit

    In Internet Explorer you get:

    This page contains both secure and nonsecure items.
    Do you want to display the nonsecure items?

    Security Information 

    You can check KB #910444 for SSL termination in ASP.NET; if this does not help, check this post, that was the situation I had to deal with a few days ago.

     

    Just an additional note: if you wish to control how your browser behaves in such situations, you can check (and change) the following settings in Internet Explorer and Firefox:

     

    Internet Explorer 
    Display mixed content in Internet Explorer

     

     

    Firefox 
    Warning messages in Firefox

     

     

    Carlo

    Quote of the day:
    The release of atomic energy has not created a new problem. It has merely made more urgent the necessity of solving an existing one. - Albert Einstein
Page 1 of 1 (3 items)