TDS Timeout and TDSService.asmx 500 error

The title of this blog post was exactly what I googled when I was troubleshooting the TDS deployment timeout issue for one of my projects. Sad, there are not much help out there on how to troubleshoot this issue. There are some suggestions from Hedgehog in the FAQ section. I tried to apply that but that didn’t help much. There was not much information in any log files, except below in the IIS log (500 error).

2015-04-08 17:59:59 10.0.1.6 POST /_DEV/TdsService.asmx – 80  – – 500 0 0 233538

The problem was sporadic. Sometime it’s 500 error, sometime TDS Timeout and sometime it worked. But, most of the time build was failing. Although there was 500 error in the IIS Log, site was working fine. Pretty frustrating and nothing to look into to get more information.

I wanted to know what exactly going on in the IIS Process. Maybe that will give me some clue. So, I took a memory dump of the Application Pool and opened up the memory dump in Windbg. The first thing I needed to check, what threads were taking most CPU time. Usually that sheds some idea about what’s running in the process. The command to do that in windbg is !runaway. Showing top 8 threads below

0:000> !runaway
User Mode Time
Thread      Time
7:4b4         0 days 0:01:43.265
6:82c         0 days 0:01:12.625
23:adc       0 days 0:00:16.187
21:11d0     0 days 0:00:14.125
22:1088    0 days 0:00:13.828
24:12b4    0 days 0:00:13.578
10:110c     0 days 0:00:07.500
11:8d0       0 days 0:00:06.046
….

Looks like thread# 7 was consuming most CPU time. Let’s look at the stack for that thread. Again, there were lots of information here but, this shows that the thread was executing the code from Application_Start method from global.asax and it was trying to open connection to the SQL server. It got my attention immediately because failure in Application_Start does throw 500 error if not handled gracefully. So was there any error? What database connection was it opening?

0:007> !clrstack
OS Thread Id: 0x4b4 (7)
        Child SP               IP Call Site
00000005b8507dd8 00007fff25140dca [InlinedCallFrame: 00000005b8507dd8] <Module>.SNIReadSyncOverAsync(SNI_ConnWrapper*, SNI_Packet**, Int32)
00000005b8507dd8 00007fff0c4bcb71 [InlinedCallFrame: 00000005b8507dd8] <Module>.SNIReadSyncOverAsync(SNI_ConnWrapper*, SNI_Packet**, Int32)
00000005b8507db0 00007fff0c4bcb71 DomainNeutralILStubClass.IL_STUB_PInvoke(SNI_ConnWrapper*, SNI_Packet**, Int32)
00000005b8507e80 00007fff0c4a350f SNINativeMethodWrapper.SNIReadSyncOverAsync(System.Runtime.InteropServices.SafeHandle, IntPtr ByRef, Int32)
00000005b8507ef0 00007fff0c4a322e System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
00000005b8507fa0 00007fff0c4a3140 System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
00000005b8507fe0 00007fff0c4a3918 System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
00000005b8508010 00007fff0c4a67a2 System.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
00000005b8508050 00007fff0c4a57d6 System.Data.SqlClient.TdsParser.TryRun(System.Data.SqlClient.RunBehavior, System.Data.SqlClient.SqlCommand, System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.BulkCopySimpleResultSet, System.Data.SqlClient.TdsParserStateObject, Boolean ByRef)
00000005b85081f0 00007fff0c4a53f4 System.Data.SqlClient.TdsParser.Run(System.Data.SqlClient.RunBehavior, System.Data.SqlClient.SqlCommand, System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.BulkCopySimpleResultSet, System.Data.SqlClient.TdsParserStateObject)
00000005b8508250 00007fff0c4a5285 System.Data.SqlClient.SqlInternalConnectionTds.CompleteLogin(Boolean)
00000005b85082e0 00007fff0c49ff10 System.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(System.Data.SqlClient.ServerInfo, System.String, System.Security.SecureString, Boolean, System.Data.ProviderBase.TimeoutTimer, Boolean)
00000005b8508370 00007fff0c49f1eb System.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(System.Data.SqlClient.ServerInfo, System.String, System.Security.SecureString, Boolean, System.Data.SqlClient.SqlConnectionString, System.Data.SqlClient.SqlCredential, System.Data.ProviderBase.TimeoutTimer)
00000005b8508510 00007fff0c49ed6d System.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(System.Data.ProviderBase.TimeoutTimer, System.Data.SqlClient.SqlConnectionString, System.Data.SqlClient.SqlCredential, System.String, System.Security.SecureString, Boolean)
00000005b85085c0 00007fff0c49e9ce System.Data.SqlClient.SqlInternalConnectionTds..ctor(System.Data.ProviderBase.DbConnectionPoolIdentity, System.Data.SqlClient.SqlConnectionString, System.Data.SqlClient.SqlCredential, System.Object, System.String, System.Security.SecureString, Boolean, System.Data.SqlClient.SqlConnectionString, System.Data.SqlClient.SessionData)
00000005b8508660 00007fff0c49e5fa System.Data.SqlClient.SqlConnectionFactory.CreateConnection(System.Data.Common.DbConnectionOptions, System.Data.Common.DbConnectionPoolKey, System.Object, System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnection, System.Data.Common.DbConnectionOptions)
00000005b8508770 00007fff0c49e0b8 System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnection, System.Data.Common.DbConnectionOptions, System.Data.Common.DbConnectionPoolKey, System.Data.Common.DbConnectionOptions)
00000005b85087e0 00007fff0c49de75 System.Data.ProviderBase.DbConnectionPool.CreateObject(System.Data.Common.DbConnection, System.Data.Common.DbConnectionOptions, System.Data.ProviderBase.DbConnectionInternal)
00000005b85088a0 00007fff0c49dbb7 System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(System.Data.Common.DbConnection, System.Data.Common.DbConnectionOptions, System.Data.ProviderBase.DbConnectionInternal)
00000005b85088f0 00007fff0c49d2ec System.Data.ProviderBase.DbConnectionPool.TryGetConnection(System.Data.Common.DbConnection, UInt32, Boolean, Boolean, System.Data.Common.DbConnectionOptions, System.Data.ProviderBase.DbConnectionInternal ByRef)
00000005b85089d0 00007fff0c49cfe4 System.Data.ProviderBase.DbConnectionPool.TryGetConnection(System.Data.Common.DbConnection, System.Threading.Tasks.TaskCompletionSource`1<System.Data.ProviderBase.DbConnectionInternal>, System.Data.Common.DbConnectionOptions, System.Data.ProviderBase.DbConnectionInternal ByRef)
00000005b8508a60 00007fff0c49cac7 System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(System.Data.Common.DbConnection, System.Threading.Tasks.TaskCompletionSource`1<System.Data.ProviderBase.DbConnectionInternal>, System.Data.Common.DbConnectionOptions, System.Data.ProviderBase.DbConnectionInternal, System.Data.ProviderBase.DbConnectionInternal ByRef)
00000005b8508b20 00007fff0c49c48b System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory, System.Threading.Tasks.TaskCompletionSource`1<System.Data.ProviderBase.DbConnectionInternal>, System.Data.Common.DbConnectionOptions)
00000005b8508b80 00007fff0c499ff9 System.Data.SqlClient.SqlConnection.TryOpenInner(System.Threading.Tasks.TaskCompletionSource`1<System.Data.ProviderBase.DbConnectionInternal>)
00000005b8508c20 00007fff0c499eb6 System.Data.SqlClient.SqlConnection.TryOpen(System.Threading.Tasks.TaskCompletionSource`1<System.Data.ProviderBase.DbConnectionInternal>)
00000005b8508c90 00007fff0c4999bf System.Data.SqlClient.SqlConnection.Open()
00000005b8508d00 00007fff0ee34733 System.Web.DataAccess.SqlConnectionHolder.Open(System.Web.HttpContext, Boolean)
00000005b8508d80 00007fff0ee33859 System.Web.DataAccess.SqlConnectionHelper.GetConnection(System.String, Boolean)
00000005b8508e10 00007fff0ef4a3b5 System.Web.Security.SqlRoleProvider.GetAllRoles()
00000005b8508ed0 00007ffec193af3e Sitecore.Data.DataProviders.NullRetryer.Execute[[System.__Canon, mscorlib]](System.Func`1<System.__Canon>, System.Action)
....
....
00000005b850b630 00007ffebdb3ab65 InsiteForSitecore.Web.MvcApplication.Application_Start()
....

Let’s see if there was any exception in this stack. The command for that is !pe. There was only one error. It’s a NullReferenceException and it didn’t seem to create the problem because the code continued after that method call.

0:007> !pe
Exception object: 00000005b9700ea0
Exception type:   System.NullReferenceException
Message:          Object reference not set to an instance of an object.
InnerException:   <none>
StackTrace (generated):
    SP               IP               Function
    00000005B850B568 00007FFEBDB3B19D Microsoft_Practices_ServiceLocation!Microsoft.Practices.ServiceLocation.ServiceLocator.get_Current()+0xd
    00000005B850B570 00007FFEBDB3B056 InsiteForSitecore_Web!InsiteForSitecore.Web.MvcApplication.ConfigureServiceLocation()+0x46

StackTraceString: <none>
HResult: 80004003

But, it seemed the code was trying to open a SQL Connection and that was taking long time to execute. To find the SQL Connection , I decided to dump the stack object using the command !dso and found the System.Data.SqlClient.SqlConnectionString object in the stack. Dumping this object and then dumping the _usersConnectionString object shows me the connectionstring that it was trying to open the core database. Also, the time out value is set to 15 seconds (default value).

0:007> !do 00000006bb9cfab0
Name:        System.Data.SqlClient.SqlConnectionString
MethodTable: 00007fff0c514950
EEClass:     00007fff0c3594f8
Size:        208(0xd0) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\System.Data\v4.0_4.0.0.0__b77a5c561934e089\System.Data.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007fff1bc80bd8  40002cd        8        System.String  0 instance 00000007b99846e0 _usersConnectionString
00007fff1bc84b98  40002ce       10 ...ections.Hashtable  0 instance 00000006bb9cfb80 _parsetable
00007fff0c516670  40002cf       18 ...mon.NameValuePair  0 instance 00000006bb9cfd20 KeyChain
00007fff1bc7f370  40002d0       28       System.Boolean  1 instance                1 HasPasswordKeyword
00007fff1bc7f370  40002d1       29       System.Boolean  1 instance                0 UseOdbcRules
00007fff1bc82458  40002d2       20 ...ity.PermissionSet  0 instance 00000006bb9d0dc8 _permissionset
00007fff1abd8228  40002c9      2d8 ...Expressions.Regex  0   shared           static ConnectionStringValidKeyRegex
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:NotInit  0000000a10219980:NotInit  <<
00007fff1abd8228  40002ca      2e0 ...Expressions.Regex  0   shared           static ConnectionStringValidValueRegex
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:NotInit  0000000a10219980:NotInit  <<
00007fff1abd8228  40002cb      2e8 ...Expressions.Regex  0   shared           static ConnectionStringQuoteValueRegex
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:NotInit  0000000a10219980:NotInit  <<
00007fff1abd8228  40002cc      2f0 ...Expressions.Regex  0   shared           static ConnectionStringQuoteOdbcValueRegex
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:NotInit  0000000a10219980:NotInit  <<
00007fff1bc7f370  40010e7       2a       System.Boolean  1 instance                0 _integratedSecurity
00007fff1bc7f370  40010e8       2b       System.Boolean  1 instance                1 _connectionReset
00007fff1bc7f370  40010e9       bc       System.Boolean  1 instance                0 _contextConnection
00007fff1bc7f370  40010ea       bd       System.Boolean  1 instance                0 _encrypt
00007fff1bc7f370  40010eb       be       System.Boolean  1 instance                0 _trustServerCertificate
00007fff1bc7f370  40010ec       bf       System.Boolean  1 instance                1 _enlist
00007fff1bc7f370  40010ed       c0       System.Boolean  1 instance                0 _mars
00007fff1bc7f370  40010ee       c1       System.Boolean  1 instance                0 _persistSecurityInfo
00007fff1bc7f370  40010ef       c2       System.Boolean  1 instance                1 _pooling
00007fff1bc7f370  40010f0       c3       System.Boolean  1 instance                0 _replication
00007fff1bc7f370  40010f1       c4       System.Boolean  1 instance                0 _userInstance
00007fff1bc7f370  40010f2       c5       System.Boolean  1 instance                0 _multiSubnetFailover
00007fff1bc837c8  40010f3       2c         System.Int32  1 instance               15 _connectTimeout
00007fff1bc837c8  40010f4       98         System.Int32  1 instance                0 _loadBalanceTimeout
00007fff1bc837c8  40010f5       9c         System.Int32  1 instance              100 _maxPoolSize
00007fff1bc837c8  40010f6       a0         System.Int32  1 instance                0 _minPoolSize
00007fff1bc837c8  40010f7       a4         System.Int32  1 instance             8000 _packetSize
00007fff1bc837c8  40010f8       a8         System.Int32  1 instance                1 _connectRetryCount
00007fff1bc837c8  40010f9       ac         System.Int32  1 instance               10 _connectRetryInterval
00007fff0c520418  40010fa       b0         System.Int32  1 instance                0 _applicationIntent
00007fff1bc80bd8  40010fb       30        System.String  0 instance 00000008b87ed558 _applicationName
00007fff1bc80bd8  40010fc       38        System.String  0 instance 00000005b87d1420 _attachDBFileName
00007fff1bc80bd8  40010fd       40        System.String  0 instance 00000005b87d1420 _currentLanguage
00007fff1bc80bd8  40010fe       48        System.String  0 instance 00000006bb9cfcf8 _dataSource
00007fff1bc80bd8  40010ff       50        System.String  0 instance 0000000000000000 _localDBInstance
00007fff1bc80bd8  4001100       58        System.String  0 instance 00000005b87d1420 _failoverPartner
00007fff1bc80bd8  4001101       60        System.String  0 instance 00000006bb9cfe28 _initialCatalog
00007fff1bc80bd8  4001102       68        System.String  0 instance 00000006bb9d01a0 _password
00007fff1bc80bd8  4001103       70        System.String  0 instance 00000006bb9d00e0 _userID
00007fff1bc80bd8  4001104       78        System.String  0 instance 00000005b87d1420 _networkLibrary
00007fff1bc80bd8  4001105       80        System.String  0 instance 0000000000000000 _workstationId
00007fff0c5326a8  4001106       b4         System.Int32  1 instance             2008 _typeSystemVersion
00007fff1bc85590  4001107       88       System.Version  0 instance 00000007b99881f8 _typeSystemAssemblyVersion
00007fff0c52a450  400110a       b8         System.Int32  1 instance                0 _transactionBinding
00007fff1bc80bd8  400110b       90        System.String  0 instance 0000000000000000 _expandedAttachDBFilename
00007fff1bc84b98  40010e5      ef0 ...ections.Hashtable  0   shared           static _sqlClientSynonyms
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:00000007b9988238 0000000a10219980:00000005b889f280 <<
00007fff1bc84b98  40010e6      ef8 ...ections.Hashtable  0   shared           static _netlibMapping
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:0000000000000000 0000000a10219980:0000000000000000 <<
00007fff1bc85590  4001108      f00       System.Version  0   shared           static constTypeSystemAsmVersion10
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:00000007b99881f8 0000000a10219980:00000005b889f240 <<
00007fff1bc85590  4001109      f08       System.Version  0   shared           static constTypeSystemAsmVersion11
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:00000007b9988218 0000000a10219980:00000005b889f260 <<

0:007> !do 00000007b99846e0
Name:        System.String
MethodTable: 00007fff1bc80bd8
EEClass:     00007fff1b611aa8
Size:        266(0x10a) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      Data Source=(local);Initial Catalog=Sitecore_core;Integrated Security=False;User ID=******;Password=******
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007fff1bc837c8  40000ab        8         System.Int32  1 instance              120 m_stringLength
00007fff1bc81f38  40000ac        c          System.Char  1 instance               44 m_firstChar
00007fff1bc80bd8  40000ad       18        System.String  0   shared           static Empty
                                 >> Domain:Value  00000005b83561f0:NotInit  0000000a10215940:NotInit  0000000a10219980:NotInit  <<

At this point I know that the longest running thread was trying to open a connection to the core database, the connection timeout was 15 seconds and the thread was running longer than that. There was no timeout error in the stack but, I thought increasing timeout might fix the issue. I increased the timeout and that fixed the issue.

Final Words

I wrote this blog not to tell what I found but to talk about an approach to troubleshoot this kind of problem. I hope this helps others with similar issues.

References

All about Windbg
SOS.dll (SOS Debugging Extension)

Advertisements

About Himadri Chakrabarti

I am a software developer architect and a Sitecore MVP. My professional interest is everything and anything related to Software Architecture, .NET, Sitecore, Node.js, NoSQL etc. Outside of my profession, I am a hobbyist photographer. Link to my photography site http://himadriphotography.com/
This entry was posted in Debugging, Sitecore and tagged , , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s