Horror of Closing Connections in Finalize()…

Artykuł
09/04/2008

Problem
Your ASP.NET Web-site times out during production with the following error:
Errors
Event Type: Warning
Event Source: ASP.NET 2.0.50727.0
Event Category: Web Event
Event ID: 1309
Date: 8/27/2008
Time: 5:48:43 PM
User: N/A
Computer: 128110-WEB3
Description:
Event code: 3005
Event message: An unhandled exception has occurred.
Event time: 8/27/2008 6:48:43 PM
Event time (UTC): 8/27/2008 10:48:43 PM
Event ID: cf61970ee1f44fd4a108e27432b7019b
Event sequence: 4495
Event occurrence: 29
Event detail code: 0
Application information:
Application domain: /LM/W3SVC/899608909/Root/App-1-128643479726573178
Trust level: Full
Application Virtual Path: /App
Application Path: C:\Web\MyApp\App\
Machine name: XXXXXX
Process information:
Process ID: 5392
Process name: w3wp.exe
Account name: NT AUTHORITY\NETWORK SERVICE
Exception information:
Exception type: NullReferenceException
Exception message: Object reference not set to an instance of an object.
Request information:
Request URL:
Request path:
User host address:
User:
Is authenticated: False
Authentication Type:
Thread account name: NT AUTHORITY\NETWORK SERVICE
Thread information:
Thread ID: 14
Thread account name: NT AUTHORITY\NETWORK SERVICE
Is impersonating: False
Stack trace: at XXXXXXXXXXXXXX() at ASP.global_asax.Session_End(Object sender, EventArgs e)
DEBUGGING SESSION
1. Thread 17 is the thread with the exception.
2. Last exception which we get is a System.InvalidOperationException for .Net Framework Data Provider
        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
3. Lets check what this Exception Object is "Exception object: 1c655480" by dumping it.
        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
4. This Exception object has few interesting fields. But we are interested in the _remoteStackTraceString field. Which is again a string object.
MT Field Offset Type VT Attr Value Name
790f9244 40000be 28 System.String 0 instance 1c658718 _remoteStackTraceString
5. Dumping _remoteStackTraceString whose value is 1c658718
790f9244 40000be 28 System.String 0 instance 1c658718 _remoteStackTraceString
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()
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 <<
6. So this is the stacktrace.
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()
This trace is originating from a custom library's Finalize() method and next call to finalize() is Dispose().
A little theory would be appropriate to understand about Implicit and Explicit resource cleanup.
Implicit and Explicit resource cleanup
In general the rule of the thumb is Finalizer is called by the .NET Framework and Dispose is used by Developers.
When do you DO Dispose or finalize?
Check out the following article [ https://msdn.microsoft.com/en-us/library/b1yfkh5e(VS.71).aspx]
In our situation
-- SomeLib.Data.ConnectionManager is calling Finalize() which triggers Dispose() which then calls ClearResources() method.
-- 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.
-- Need to know the code which is executing this to confirm that they are calling the Connection.close() method in Finalize (or, Dispose())
7. However I am still curious to know how exactly this assembly is doing the Resource Cleanup. And to know more about the code
(Since, I don't have the actual code to look at)
-- One of the loaded module in this dump is:
08d80000 08db2000 SomeLib_8d80000 (deferred)
8. Lets Dump this module
        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
9. Notice the start address of this assembly which is 08d80000. Save this module as a DLL c:\somelib.dll
    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
10. Opening somelib.dll with reflector revealed the problem:
a. Finalizer is calling Dispose()

   ~ConnectionManager()

     this.Dispose();

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

     public virtual void Dispose()

         GC.SuppressFinalize(this);

         if (this._cn != null)

             this.CleanResources();

c. ClearResources() finally closes the connection

 private void CleanResources()

         this._cn.Close();

         this._cn = null;

         Current = null;

Conclusion
It's not recommended to call Close or Dispose on a Connection, a DataReader, or any other managed object in the Finalize method of
your class.
[https://msdn.microsoft.com/en-us/library/system.data.sqlclient.sqldatareader.close.aspx]
Refer
https://forums.microsoft.com/MSDN/ShowPost.aspx?PostID=473449&SiteID=1
https://msdn2.microsoft.com/en-us/library/ms971481.aspx

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!

Udostępnij za pośrednictwem

Horror of Closing Connections in Finalize()…

Comments

Dodatkowe zasoby