If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

ASP.NET Crash: Bad CacheItemRemovedCallback - Part II

ASP.NET Crash: Bad CacheItemRemovedCallback - Part II

  • Comments 13

In August I wrote about how you could cause a nasty high memory situation by using CacheItemRemovedCallbacks improperly, today I got a case where improper use of CacheItemRemovedCallback caused a crash, so I figured I'll use it to show you how you can use them to bring down your website in seconds...

Problem description

The scenario is a web site that constantly crashes within minutes or seconds of startup, and a dump has been taken on process shutdown (adplus -crash -pn w3wp.exe)

Debugging the issue

If we open the memory dump with windbg and take a quick peak at the callstack that calls Kernel32!TerminateProcess (with kb) we see:

0:026> kb
ChildEBP RetAddr Args to Child
03744980 7a059b67 ffffffff 800703e9 9fa3661f kernel32!TerminateProcess
037449e4 7a059c79 0374498c 00166268 00004000 mscorwks!EEPolicy::HandleFatalStackOverflow+0xd8
03744a08 79fce2f0 00000001 00000000 00000000 mscorwks!EEPolicy::HandleStackOverflow+0x157
03744a24 7c82eeb2 03744b08 0376f27c 03744b1c mscorwks!COMPlusFrameHandler+0xd8
03744a48 7c82ee84 03744b08 0376f27c 03744b1c ntdll!ExecuteHandler2+0x26
03744af0 7c82ecc6 03743000 03744b1c 03744b08 ntdll!ExecuteHandler+0x24
03744af0 77e55e02 03743000 03744b1c 03744b08 ntdll!KiUserExceptionDispatcher+0xe
03744e3c 79feef3c e053534f 00000000 00000000 kernel32!RaiseException+0x53
03744e54 7a0900a3 00000001 79124228 03744ec8 mscorwks!ReportStackOverflow+0x7e
03744e64 79e88774 00000094 00000000 00080000 mscorwks!Alloc+0x3b
03744f30 79e7e877 653dbde2 03744fe0 00000001 mscorwks!AllocateArrayEx+0x1d1
03744ff4 652c012b 00000000 1cd07984 1cd07a0c mscorwks!JIT_NewArr1+0x167

So the cause for the process termination was a fatal stackoverflow, which is typically caused by a recursive loop.

The next step is to take a look at the .net callstack (with !clrstack from sos.dll), and doing so will reveal a long callstack with the following contents

<stack cut to save space>
03761b14 6601bc92 System.Web.Caching.Cache.Insert(System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback)
03761b4c 05d54422 MyNameSpace.MyClass.RefreshCache(System.String, System.Object, System.Web.Caching.CacheItemRemovedReason)
03761b8c 6601e39c System.Web.Caching.CacheEntry.CallCacheItemRemovedCallback(System.Web.Caching.CacheItemRemovedCallback, System.Web.Caching.CacheItemRemovedReason)
03761bc8 6601e60d System.Web.Caching.CacheEntry.Close(System.Web.Caching.CacheItemRemovedReason)
03761c04 6630239c System.Web.Caching.CacheSingle.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03761cd4 65fa82ea System.Web.Caching.CacheMultiple.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03761cf8 65fa8e2a System.Web.Caching.CacheInternal.DoInsert(Boolean, System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback, Boolean)
03761d54 6601bc92 System.Web.Caching.Cache.Insert(System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback)
03761d8c 05d54422 MyNameSpace.MyClass.RefreshCache(System.String, System.Object, System.Web.Caching.CacheItemRemovedReason)
03761dcc 6601e39c System.Web.Caching.CacheEntry.CallCacheItemRemovedCallback(System.Web.Caching.CacheItemRemovedCallback, System.Web.Caching.CacheItemRemovedReason)
03761e08 6601e60d System.Web.Caching.CacheEntry.Close(System.Web.Caching.CacheItemRemovedReason)
03761e44 6630239c System.Web.Caching.CacheSingle.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03761f14 65fa82ea System.Web.Caching.CacheMultiple.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03761f38 65fa8e2a System.Web.Caching.CacheInternal.DoInsert(Boolean, System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback, Boolean)
03761f94 6601bc92 System.Web.Caching.Cache.Insert(System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback)
03761fcc 05d54422 MyNameSpace.MyClass.RefreshCache(System.String, System.Object, System.Web.Caching.CacheItemRemovedReason)
0376200c 6601e39c System.Web.Caching.CacheEntry.CallCacheItemRemovedCallback(System.Web.Caching.CacheItemRemovedCallback, System.Web.Caching.CacheItemRemovedReason)
03762048 6601e60d System.Web.Caching.CacheEntry.Close(System.Web.Caching.CacheItemRemovedReason)
03762084 6630239c System.Web.Caching.CacheSingle.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03762154 65fa82ea System.Web.Caching.CacheMultiple.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03762178 65fa8e2a System.Web.Caching.CacheInternal.DoInsert(Boolean, System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback, Boolean)
037621d4 6601bc92 System.Web.Caching.Cache.Insert(System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback)
0376220c 05d54422 MyNameSpace.MyClass.RefreshCache(System.String, System.Object, System.Web.Caching.CacheItemRemovedReason)
0376224c 6601e39c System.Web.Caching.CacheEntry.CallCacheItemRemovedCallback(System.Web.Caching.CacheItemRemovedCallback, System.Web.Caching.CacheItemRemovedReason)
03762288 6601e60d System.Web.Caching.CacheEntry.Close(System.Web.Caching.CacheItemRemovedReason)
037622c4 6630239c System.Web.Caching.CacheSingle.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
03762394 65fa82ea System.Web.Caching.CacheMultiple.UpdateCache(System.Web.Caching.CacheKey, System.Web.Caching.CacheEntry, Boolean, System.Web.Caching.CacheItemRemovedReason, System.Object ByRef)
037623b8 65fa8e2a System.Web.Caching.CacheInternal.DoInsert(Boolean, System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback, Boolean)
03762414 6601bc92 System.Web.Caching.Cache.Insert(System.String, System.Object, System.Web.Caching.CacheDependency, System.DateTime, System.TimeSpan, System.Web.Caching.CacheItemPriority, System.Web.Caching.CacheItemRemovedCallback)
0376244c 05d54422 MyNameSpace.MyClass.RefreshCache(System.String, System.Object, System.Web.Caching.CacheItemRemovedReason)
0376248c 6601e39c System.Web.Caching.CacheEntry.CallCacheItemRemovedCallback(System.Web.Caching.CacheItemRemovedCallback, System.Web.Caching.CacheItemRemovedReason)
037624c8 6601e60d System.Web.Caching.CacheEntry.Close(System.Web.Caching.CacheItemRemovedReason)
<stack cut to save space>

So what do we have here?

Well, we can see that MyNameSpace.MyClass.RefreshCache inserts something in cache, which in turn updates the cache and for some reason closes out a cache item, and calls the RefreshCache function again.

If we take a peak at the MyNameSpace.MyClass.RefreshCache function it looks like this:

protected void RefreshCache(string key, object item, CacheItemRemovedReason reason)
{
    ...
ContextHandler.Cache.Insert(
       "MyCacheItem",
       CacheValue,
       null,
       DateTime.Now.AddHours(9),
       TimeSpan.Zero,
       CacheItemPriority.NotRemovable,
       new CacheItemRemovedCallback(this.RefreshCache));
}

 

So from first look, it looks like a very logical way to perform what needs to be performed.  What we want to do is insert a new item, and in the case where it is removed we want to reinsert it using the same function.  In fact, from looking at it, it is very hard to see how this could ever cause a problem.

But, dear Watson, there is a major problem with this code....

When an item is inserted the first time into cache everything will be cool, but what will happen the next time you go through this function? 

Answer:  The insert will insert a new cache item "MyCacheItem", and at the same time it will remove the previous copy of this item, causing the CacheItemRemovedCallback handler to be called (RefreshCache), this will in turn insert a new copy, remove the old one and so on and so on... and we have ourselves a neverending recursive loop that causes a stackoverflow and a crashing website.

Final thoughts

The morale of the story is, don't use the CacheItemRemovedCallback to add a new copy of the same cache item. Instead use sliding expiration, and instead add the cached item when you try to access the cached item and this item is null.   

Til next time,
Tess





  • I discovered your blog today (my bad). Good stuff !

    -- Henkk

  • Common Gotcha: Don't forget to when adding providers [Via: ScottGu ] Mounting ISO Images with Vista...

  • Hi,

    I don't understand this - can you explain a bit better why the RefreshCache function causes a recursive loop?

    From what I see, the cache item is removed, the event fires, RefreshCache() is run and the item is re-inserted.

    How come the previous cache item is still there when it tries to insert the replacement? Surely is must have already been removed or the event wouldn't have fired?!

    Help, I don't understand!

    Rob

  • The cached item is still there when the event fires.  

    Without going through the code and looking at the exact details I would hazard to guess that this is to allow the eventhandler to still access the properties of this object.

    Of course, once the event is fired the object should then go away.

  • thanks, i guess that sort of makes sense. shame, it would be nice to easily refresh a cache every 30mins without a user having to initiate it and take the performance hit.

  • Dude, this is awesome.  I came across this article while trying to see what KiFastSystemCall does. There is no documentation whatsoever about what this mysterious function does.

  • When you see it on top of a stack in a dump it is usually an effect of the debugger stepping in to momentarily pause the threads to gather the stack.

    You can just ignore it and go on to the next frame on the stack...

  • Add 'if' statement to your RefreshCache(string key, object item, CacheItemRemovedReason reason) method like this:

    if (reason == CacheItemRemovedReason.Removed || reason == CacheItemRemovedReason.Underused)

    return;

    and now it will go into recursive loop.

  • "don't use the CacheItemRemovedCallback to add a new copy of the same cache item"...

    uhm... not the best practice.

    Simply put your code into an 'if' statement

    if (

    reason == CacheItemRemovedReason.DependencyChanged

    || reason == CacheItemRemovedReason.Expired

    || reason == CacheItemRemovedReason.Underused)

    {

         //your code.

    }

  • I have written a few posts about stackoverflow exceptions, here, here , here and here . The one I am

  • Shoud or should not my callback method notify me about expiration and removing my cached object after 120 sec.

    It does not work. Can you please tell me what is wrong?

    private Cache AppCache;

    AppCache.Insert(

        key,

        objValue,

        null,

        DateTime.Now.AddSeconds(120),

        Cache.NoSlidingExpiration,                  

        CacheItemPriority.High,            

        new CacheItemRemovedCallback(itemRemovedCallback));

    My callback method is:

    private void itemRemovedCallback(String key, object value, CacheItemRemovedReason reason)

           {

                   System.Diagnostics.Trace.WriteLine("Note: Item with key=" + key + " has been removed from cache");

           }

    and I use debugview to see message.

    Thanks,

    VKK

  • I have used the following VB code... and it works... but according to this article, it shouldn't work.  

    If I set the expiry to 1 minute and debug, the cache is reset every 1 minute.  If I put a breakpoint in the code to see what the value of the cache item is (theCache(Common.CACHE_AllRates), where Common.CACHE_AllRates is just a string constant), the cache item = Nothing when the CacheItemRemovedCallback is executed.

    I'm confused.  Is some fluke causing my code to work?  Do you know of a case where this code would break?

    ' in Global.asax.vb

    ...

    Shared theCache As Cache

    ...

       Sub Application_Start(ByVal sender As Object, ByVal e As EventArgs)

           ' Fires when the application is started

           'set global cache variable

           theCache = Context.Cache

           Dim dsAllRates As DataSet = Common.GetAllRates()

           theCache.Insert(Common.CACHE_AllRates, _

                           dsAllRates.Tables(0), _

                           Nothing, _

                           Date.Now.AddMinutes(15), _

                           Cache.NoSlidingExpiration, _

                           CacheItemPriority.Default, _

                           New CacheItemRemovedCallback(AddressOf Update_DS_AllRates))

       End Sub

       Shared Sub Update_DS_AllRates(ByVal key As String, ByVal item As Object, ByVal reason As CacheItemRemovedReason)

           Try

               'get all ActiveEmployees

               Dim dsAllRates As DataSet = Common.GetAllRates()

               'store dataset in cache

               theCache.Insert(Common.CACHE_AllRates, _

                               dsAllRates.Tables(0), _

                               Nothing, _

                               Date.Now.AddMinutes(15), _

                               Cache.NoSlidingExpiration, _

                               CacheItemPriority.Default, _

                               New CacheItemRemovedCallback(AddressOf Update_DS_AllRates))

           Catch ex As Exception

               ...

           End Try

       End Sub

    ...

Page 1 of 1 (13 items)
Leave a Comment
  • Please add 6 and 6 and type the answer here:
  • Post