Freigeben über

Horror of Closing Connections in Finalize()…

  • Artikel

  1.  

  2. Problem

  3.  

  4. Your ASP.NET Web-site times out during production with the following error:

  5. Errors

  6.  

  7. Event Type: Warning

  8. Event Source: ASP.NET 2.0.50727.0

  9. Event Category: Web Event

  10. Event ID: 1309

  11. Date: 8/27/2008

  12. Time: 5:48:43 PM

  13. User: N/A

  14. Computer: 128110-WEB3

  15. Description:

  16. Event code: 3005

  17. Event message: An unhandled exception has occurred.

  18. Event time: 8/27/2008 6:48:43 PM

  19. Event time (UTC): 8/27/2008 10:48:43 PM

  20. Event ID: cf61970ee1f44fd4a108e27432b7019b

  21. Event sequence: 4495

  22. Event occurrence: 29

  23. Event detail code: 0

  24.  

  25. Application information:

  26. Application domain: /LM/W3SVC/899608909/Root/App-1-128643479726573178

  27. Trust level: Full

  28. Application Virtual Path: /App

  29. Application Path: C:\Web\MyApp\App\

  30. Machine name: XXXXXX

  31.  

  32. Process information:

  33. Process ID: 5392

  34. Process name: w3wp.exe

  35. Account name: NT AUTHORITY\NETWORK SERVICE

  36.  

  37. Exception information:

  38. Exception type: NullReferenceException

  39. Exception message: Object reference not set to an instance of an object.

  40.  

  41. Request information:

  42. Request URL:

  43. Request path:

  44. User host address:

  45. User:

  46. Is authenticated: False

  47. Authentication Type:

  48. Thread account name: NT AUTHORITY\NETWORK SERVICE

  49.  

  50. Thread information:

  51. Thread ID: 14

  52. Thread account name: NT AUTHORITY\NETWORK SERVICE

  53. Is impersonating: False

  54. Stack trace: at XXXXXXXXXXXXXX() at ASP.global_asax.Session_End(Object sender, EventArgs e)

  55.  

  56.  

  57.  

  58. DEBUGGING SESSION

  59.  

  60. 1. Thread 17 is the thread with the exception.

  61. 2. Last exception which we get is a System.InvalidOperationException for .Net Framework Data Provider

  62.         0:017> !pe
            Exception object: 1c655480
            Exception type: System.InvalidOperationException
            Message: Internal .Net Framework Data Provider error 1.
            InnerException: <none>
            StackTrace (generated):
            <none>
            StackTraceString: <none>
            HResult: 80131509

  63.  

  64.  

  65. 3. Lets check what this Exception Object is "Exception object: 1c655480" by dumping it.

  66.         0:017> !do 1c655480
            Name: System.InvalidOperationException
            MethodTable: 791015cc
            EEClass: 7910155c
            Size: 72(0x48) bytes
             (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
            Fields:
                  MT    Field   Offset                 Type VT     Attr    Value Name
            790f9244  40000b5        4        System.String  0 instance 1c6562f8 _className
            79107d4c  40000b6        8 ...ection.MethodBase  0 instance 00000000 _exceptionMethod
            790f9244  40000b7        c        System.String  0 instance 1c656c3c _exceptionMethodString
            790f9244  40000b8       10        System.String  0 instance 1c65643c _message
            79112734  40000b9       14 ...tions.IDictionary  0 instance 1c6579a0 _data
            790f984c  40000ba       18     System.Exception  0 instance 00000000 _innerException
            790f9244  40000bb       1c        System.String  0 instance 00000000 _helpURL
            790f8a7c  40000bc       20        System.Object  0 instance 00000000 _stackTrace
            790f9244  40000bd       24        System.String  0 instance 00000000 _stackTraceString
            790f9244  40000be       28        System.String  0 instance 1c658718 _remoteStackTraceString
            790fdb60  40000bf       34         System.Int32  1 instance        0 _remoteStackIndex
            790f8a7c  40000c0       2c        System.Object  0 instance 00000000 _dynamicMethods
            790fdb60  40000c1       38         System.Int32  1 instance -2146233079 _HResult
            790f9244  40000c2       30        System.String  0 instance 1c656ed0 _source
            790fcfa4  40000c3       3c        System.IntPtr  1 instance        0 _xptrs
            790fdb60  40000c4       40         System.Int32  1 instance        0 _xcode

  67.  

  68.  

  69. 4. This Exception object has few interesting fields. But we are interested in the _remoteStackTraceString field. Which is again a string object.

  70. MT Field Offset Type VT Attr Value Name

  71. 790f9244 40000be 28 System.String 0 instance 1c658718 _remoteStackTraceString

  72.  

  73. 5. Dumping _remoteStackTraceString whose value is 1c658718  

  74.    790f9244 40000be 28 System.String 0 instance 1c658718 _remoteStackTraceString
      

  75.    Dumping 1c658718
    0:017> !do 1c658718
    Name: System.String
    MethodTable: 790f9244
    EEClass: 790f91a4
    Size: 1332(0x534) bytes
    (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
    String: at System.Data.ProviderBase.DbConnectionInternal.PrePush(Object expectedOwner)
    at System.Data.ProviderBase.DbConnectionPool.PutObject(DbConnectionInternal obj, Object owningObject)
    at System.Data.ProviderBase.DbConnectionInternal.CloseConnection(DbConnection owningObject, DbConnectionFactory connectionFactory)
    at System.Data.SqlClient.SqlInternalConnection.CloseConnection(DbConnection owningObject, DbConnectionFactory connectionFactory)
    at System.Data.SqlClient.SqlConnection.Close()
    at SomeLib.Data.ConnectionManager.ClearResources()
    at SomeLib.Data.ConnectionManager.Dispose()
    at SomeLib.Data.ConnectionManager.Finalize()

  76.         Fields:
    MT Field Offset Type VT Attr Value Name
    790fdb60 4000096 4 System.Int32 1 instance 658 m_arrayLength
    790fdb60 4000097 8 System.Int32 1 instance 657 m_stringLength
    790fad38 4000098 c System.Char 1 instance 20 m_firstChar
    790f9244 4000099 10 System.String 0 shared static Empty
    >> Domain:Value 000ed050:790d57b4 001050f8:790d57b4 0013a4d8:790d57b4 07b64160:790d57b4 03f62840:790d57b4 <<
    79122994 400009a 14 System.Char[] 0 shared static WhitespaceChars
    >> Domain:Value 000ed050:1c2d03f0 001050f8:1c2d43a4 0013a4d8:1c3ee26c 07b64160:1443150c 03f62840:1050e1e0 <<

  77.  

  78. 6. So this is the stacktrace.

  79.                      at System.Data.ProviderBase.DbConnectionInternal.PrePush(Object expectedOwner)

  80.    at System.Data.ProviderBase.DbConnectionPool.PutObject(DbConnectionInternal obj, Object owningObject)

  81.    at System.Data.ProviderBase.DbConnectionInternal.CloseConnection(DbConnection owningObject, DbConnectionFactory connectionFactory)

  82.    at System.Data.SqlClient.SqlInternalConnection.CloseConnection(DbConnection owningObject, DbConnectionFactory connectionFactory)

  83.    at System.Data.SqlClient.SqlConnection.Close()

  84.    at SomeLib.Data.ConnectionManager.ClearResources()

  85.    at SomeLib.Data.ConnectionManager.Dispose()

  86.    at SomeLib.Data.ConnectionManager.Finalize()

  87.  

  88.  

  89. This trace is originating from a custom library's Finalize() method and next call to finalize() is Dispose().

  90.  

  91. A little theory would be appropriate to understand about Implicit and Explicit resource cleanup.

  92. Implicit and Explicit resource cleanup

  93. In general the rule of the thumb is Finalizer is called by the .NET Framework and Dispose is used by Developers.

  94. When do you DO Dispose or finalize?

  95. Check out the following article [ https://msdn.microsoft.com/en-us/library/b1yfkh5e(VS.71).aspx]

  96.  

  97. In our situation

  98. -- SomeLib.Data.ConnectionManager is calling Finalize() which triggers Dispose() which then calls ClearResources() method.

  99. -- It is not safe to call any managed objects in Finalize, because it is called non-deterministically by the garbage collector on a separate thread.

  100. -- Need to know the code which is executing this to confirm that they are calling the Connection.close() method in Finalize (or, Dispose())

  101.  

  102.  

  103. 7. However I am still curious to know how exactly this assembly is doing the Resource Cleanup. And to know more about the code

  104. (Since, I don't have the actual code to look at)

  105.  

  106. -- One of the loaded module in this dump is:

  107. 08d80000 08db2000 SomeLib_8d80000 (deferred)

  108.  

  109. 8. Lets Dump this module

  110.         0:017> lmvm SomeLib_8d80000
            start    end        module name
            08d80000 08db2000   SomeLib_8d80000   (deferred)            
            Image path: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\jay\eccfc76c\7bdacbb0\assembly\dl3\33e5ab8b\00c8a41a_3708c901\SomeLib.DLL
            Image name: SomeLib.DLL
            Has CLR image header, track-debug-data flag not set
            Timestamp:        Wed Aug 27 16:51:51 2008 (48B538CF)
            CheckSum:         00000000
            ImageSize:        00032000
            File version:     1.0.0.0
            Product version:  1.0.0.0
            File flags:       0 (Mask 3F)
            File OS:          4 Unknown Win32
            File type:        2.0 Dll
            File date:        00000000.00000000
            Translations:     0000.04b0
            ProductName:      SomeLib
            InternalName:     SomeLib.dll
            OriginalFilename: SomeLib.dll
            ProductVersion:   1.0.0.0
            FileVersion:      1.0.0.0
            FileDescription:  SomeLib
            LegalCopyright:   © 2006 Jay Akhawri    All Rights Reserved

  111. 9. Notice the start address of this assembly which is 08d80000. Save this module as a DLL c:\somelib.dll

  112.     0:017> !savemodule 08d80000 c:\Somelib.dll
        3 sections in file
        section 0 - VA=2000, VASize=2a484, FileAddr=1000, FileSize=2b000
        section 1 - VA=2e000, VASize=328, FileAddr=2c000, FileSize=1000
        section 2 - VA=30000, VASize=c, FileAddr=2d000, FileSize=1000

  113.  

  114. 10. Opening somelib.dll with reflector revealed the problem:

  115. a. Finalizer is calling Dispose()    

  116.    ~ConnectionManager()

         {

         this.Dispose();

         }

  118.  

    b. Dispose() is first suppressingFinalize and calling ClearResources() method

         public virtual void Dispose()

         {

             GC.SuppressFinalize(this);

             if (this._cn != null)

             {

                 this.CleanResources();

             }

         }

  119.   c. ClearResources() finally closes the connection

       

     private void CleanResources()

         {

             this._cn.Close();

             this._cn = null;

             Current = null;

         }

  120.  

  121.  

  122. Conclusion

  123.  

  124. It's not recommended to call Close or Dispose on a Connection, a DataReader, or any other managed object in the Finalize method of

  125. your class.

  126. [https://msdn.microsoft.com/en-us/library/system.data.sqlclient.sqldatareader.close.aspx]

  127.  

  128. Refer

  129. https://forums.microsoft.com/MSDN/ShowPost.aspx?PostID=473449&SiteID=1

  130. https://msdn2.microsoft.com/en-us/library/ms971481.aspx

  131.  

  132.  

  133.  

Comments

  • Anonymous
    April 16, 2009
    Thank you very much for the detailed explanation. This solved my 2 month long problem once I knew why it happened. Kind Regards

  • Anonymous
    June 12, 2013
    Great post, even 4 years later!  The details helped greatly to sort out an elusive bug. Thank you!