• Thomas Pollinger
• 13.07.2018

Root Cause Analysis: "Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding."

Wenn Projekte über Jahre wachsen und bestimmte Aufgaben nur selten durchgeführt werden. Kann es urplötzlich zu neuen Fehlermeldungen im wsms.log kommen, welche erstmal sehr "böse" aussehen. Jedoch sich dann meistens herausstellt, dass es einfach nur Einstellungs- bzw. Optmierungsthemen sind. Wie in diesem Fall...

Regel 45

Ein Kollege mit zu vielen Rechten führt ein Update ohne Backup durch und macht deine ganze Arbeit zunichte. (Entwicklerweisheit)

Verhalten

Diese nachfolgenden Fehlermeldungen kommen aus dem wsms.log:

<DbError time="{date}">
  <Message><![CDATA[Could not execute SQL statement]]></Message>
  <SqlStatement id="IO_REL.INSERT_InheritPublishingPackageIfNotAlreadySet">INSERT INTO IO_REL (REL0,REL1,REL2,REL3,REL4,REL5,REL6,REL7,REL8,REL9,REL10,REL11,REL12,REL13) SELECT REPLACE(CONVERT(NVARCHAR(MAX),NEWID()),'-',''),PGE0,'PGE',REL3,REL4,REL5,REL6,REL7,REL8,REL9,REL10,REL11,REL12,REL13 FROM IO_REL REL1,IO_PGE WHERE PGE1=@0 AND PGE5&gt;0 AND REL4='EXS' AND NOT EXISTS (SELECT 1 FROM IO_REL REL2 WHERE REL2.REL1=PGE0 AND REL4='EXS') AND (REL1.REL1=@1 OR (REL1.REL1=PGE4 AND NOT EXISTS (SELECT 1 FROM IO_REL REL2 WHERE REL2.REL1=@2 AND REL4='EXS')));@0,IO_PGE.PGE1,E038791C803B48238F9240C98A67AF9E;@1,IO_REL.REL1,;@2,IO_REL.REL1,; </SqlStatement>
  <ConnectionString>Provider="SQLOLEDB";Data Source="{dbserver}";Initial Catalog="{dbname}";Trusted_Connection=yes;Min Pool Size="10";Max Pool Size="400";Connection Lifetime="60";Pooling="true"</ConnectionString>
  <Exception type="System.Data.SqlClient.SqlException">
    <Message><![CDATA[Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.]]></Message>
    <Exception type="System.ComponentModel.Win32Exception">
      <Message><![CDATA[The wait operation timed out]]></Message>
    </Exception>
    <StackTrace>
      <Call>System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)</Call>
      <Call>System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)</Call>
      <Call>System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean&amp; dataReady)</Call>
      <Call>System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption)</Call>
      <Call>System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task&amp; task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)</Call>
      <Call>System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task&amp; task, Boolean&amp; usedCache, Boolean asyncWrite, Boolean inRetry)</Call>
      <Call>System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean&amp; usedCache, Boolean asyncWrite, Boolean inRetry)</Call>
      <Call>System.Data.SqlClient.SqlCommand.ExecuteNonQuery()</Call>
      <Call>OpenText.WS.MS.Core.DataAccess.RdConnection.InternalExecute(CommandExecuteType commandExecuteType, SqlStatement sqlStatement, ICollection`1 sqlArguments, Object&amp; result, Boolean doFixSqlStatement)</Call>
    </StackTrace>
  </Exception>
  <StackTrace>
    <Call>OpenText.WS.MS.Core.DataAccess.RdConnection.AddException(SqlStatement statement, Exception exception, String messageFormat, Object[] args)</Call>
    <Call>OpenText.WS.MS.Core.DataAccess.RdConnection.InternalExecute(CommandExecuteType commandExecuteType, SqlStatement sqlStatement, ICollection`1 sqlArguments, Object&amp; result, Boolean doFixSqlStatement)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.InheritContentWorkflowAndPublishingPackages(RdObject rObjA)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.LoadAndCheckPageElements(RdObject rObjA, String sPageGUIDA, String sPGESqlA, SqlStatement sWhereA, Dictionary`2 nTemplateElementsA, TemplateElementType[]&amp; aTemplateElements, Dictionary`2 nPageElementsA, PageElementType2[]&amp; aPageElementsA, Boolean&amp; fHeadlineForTranslationA, Boolean&amp; fNoHeadLineA)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.LoadPageElements(RdObject&amp; rObjA, CMSCacheFiles&amp; oCMSCacheFilesA)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.Elements(RdObject&amp; rObjA, String&amp; stateGuid)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.Page(RdObject&amp; rObjA, Boolean&amp; fExitA)</Call>
    <Call>OpenText.WS.MS.PageModule.RDPage.Execute(RdObject rObjA)</Call>
    <Call>OpenText.WS.MS.XMLServer.XmlServer.ExecuteRql(RdObject oIoData, String&amp; pageBuilderUpdateError, RdObject oSettings, String sThreadGuid, String&amp; sTempError, String sName, RdObject&amp; oIoProcObj, Int32 fRepeatCount, String sRet, Boolean&amp; doUpdatePageBuilder, Boolean&amp; fIgnoreError, String&amp; resultInfoA)</Call>
    <Call>OpenText.WS.MS.XMLServer.XmlServer.Execute(String rqlA, String&amp; errorA, String&amp; resultInfoA)</Call>
    <Call>OpenText.WS.MS.XMLServer.MainService.XmlServerExecute(String request, String&amp; errorA, String&amp; resultInfo)</Call>
    <Call>System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Object[]&amp; outArgs)</Call>
    <Call>System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg)</Call>
    <Call>System.Runtime.Remoting.Messaging.ServerObjectTerminatorSink.SyncProcessMessage(IMessage reqMsg)</Call>
    <Call>System.Runtime.Remoting.Messaging.ServerContextTerminatorSink.SyncProcessMessage(IMessage reqMsg)</Call>
    <Call>System.Runtime.Remoting.Channels.CrossContextChannel.SyncProcessMessageCallback(Object[] args)</Call>
    <Call>System.Runtime.Remoting.Channels.ChannelServices.DispatchMessage(IServerChannelSinkStack sinkStack, IMessage msg, IMessage&amp; replyMsg)</Call>
    <Call>System.Runtime.Remoting.Channels.BinaryServerFormatterSink.ProcessMessage(IServerChannelSinkStack sinkStack, IMessage requestMsg, ITransportHeaders requestHeaders, Stream requestStream, IMessage&amp; responseMsg, ITransportHeaders&amp; responseHeaders, Stream&amp; responseStream)</Call>
    <Call>System.Runtime.Remoting.Channels.Tcp.TcpServerTransportSink.ServiceRequest(Object state)</Call>
    <Call>System.Runtime.Remoting.Channels.SocketHandler.ProcessRequestNow()</Call>
    <Call>System.Runtime.Remoting.Channels.RequestQueue.ProcessNextRequest(SocketHandler sh)</Call>
    <Call>System.Net.LazyAsyncResult.Complete(IntPtr userToken)</Call>
    <Call>System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)</Call>
    <Call>System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)</Call>
    <Call>System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)</Call>
    <Call>System.Net.ContextAwareResult.Complete(IntPtr userToken)</Call>
    <Call>System.Net.LazyAsyncResult.ProtectedInvokeCallback(Object result, IntPtr userToken)</Call>
    <Call>System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)</Call>
    <Call>System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)</Call>
  </StackTrace>
</DbError>

Ursache

Der Timeout für die SQL-Verbindung ist zu klein.

Lösung

In der rdserver.ini den Wert für CommandTimeout= höher setzen, dieser steht per Default auf 60. Der Wert gibt den Timeout in Sekunden an.

Über den Autor: