[Bug]: CloseChannelAsync: System.TimeoutException: Receive timed out after 00:00:00

[chekm8]

Duplicate ?

• I have searched issues/discussions and did not find other issues/discussions reporting this bug.

Product version

1.6.0

Describe expected behavior

Note, this may be similar to #1534 , but since the my issue is a completely different stack trace I am requesting assistance.

We are randomly receiving the System.TimeoutException: Receive timed out after 00:00:00 exceptions and are not able to find a way to reproduce the issue. Most of our timeout settings (SendTimout, ReceiveTimeout, OpenTimeout) are explicitly set to a default value so I am unsure as to why we are seeing a "00:00:00" value when this occurs. Any guidance you can provide as to how to determine why this timeout is set this value would be helpful.

Describe actual behavior

We are randomly receiving the System.TimeoutException: Receive timed out after 00:00:00 exceptions called from CloseChannelAsync(). Full stack trace is below

Which binding

NetTcp

security

None

Which .NET version

.NET 8

Which os platform

Windows

Code snippet used to reproduce the issue

Our global handler is catching the exception of an async so we are not getting an explicit stack trace that include our code.

Stacktrace if any

System.TimeoutException: Receive timed out after 00:00:00. The time allotted to this operation may have been a portion of a longer timeout.
 ---> System.TimeoutException: Cannot claim lock within the allotted timeout of 00:00:00. The time allotted to this operation may have been a portion of a longer timeout.
   --- End of inner exception stack trace ---
   at CoreWCF.Channels.SynchronizedMessageSource.ReceiveAsync(CancellationToken token)
   at CoreWCF.Channels.TransportDuplexSessionChannel.EnsureInputClosedAsync(CancellationToken token)
   at CoreWCF.Channels.TransportDuplexSessionChannel.OnCloseAsync(CancellationToken token)
   at CoreWCF.Channels.ServerFramingDuplexSessionChannel.OnCloseAsync(CancellationToken token)
   at CoreWCF.Channels.CommunicationObject.CloseAsync(CancellationToken token)
   at CoreWCF.Channels.ServiceChannel.OnCloseAsync(CancellationToken token)
   at CoreWCF.Channels.CommunicationObject.CloseAsync(CancellationToken token)
   at CoreWCF.Dispatcher.MessageRpc.CloseChannelAsync()

[mconnew]

The explanation for the 0 timeout is in my comment on the issue you linked to:

The reason for the wrong value being reported is the WCF codebase doesn't use CancellationToken, it passes around a TimeSpan timeout value. CoreWCF uses CancellationToken through all its api surface instead. You can't get the timeout back out of a CancellationToken very easily.

I'll follow up in a bit about what's going on here specifically. How are you registering your error handler? Is it an IErrorHandler?

[mconnew]

I tracked down what timeout was used here. It's a static timeout that doesn't come from any bindings, and is defined in ChannelHandler.CloseAfterFaulTimeout. The value is 10 seconds. Basically the channel was faulted, so then it attempts to close the channel, but will only wait up to 10 seconds to do so.
It goes down this code path when a fault happened and it's considered unhandled. There are several ways for this to be considered the case. The easiest way to find out why is to provide an IErrorHandler and in the ProvideFault method, record what exception needed handling and if there was a default fault message provided just before this. If there isn't a default fault message (it's null) and you don't provide one, it's considered unhandled. Even if there is a fault message, if the exception is a FaultException and FaultException.Fault.Code.SubCode.Namespace is "http://schemas.microsoft.com/net/2005/12/windowscommunicationfoundation/dispatcher" as well as FaultException.Fault.Code.SubCode.Name is "InternalServiceFault", then it's also considered unhandled.
There are a couple of other ways this can happen. If a message inspector throws and exception. On WCF it can also happen is you have a message property that implements IMergeEnabledMessageProperty and throws, but that doesn't exist in CoreWCF.
But basically this is happening because an exception way thrown somewhere, and either the default fault provider couldn't provide a fault, or it did and your own code replaced it with null, or the FaultException had these very narrow and specific properties, or you have a message inspector that's throwing an exception.

[chekm8]

The explanation for the 0 timeout is in my comment on the issue you linked to:

The reason for the wrong value being reported is the WCF codebase doesn't use CancellationToken, it passes around a TimeSpan timeout value. CoreWCF uses CancellationToken through all its api surface instead. You can't get the timeout back out of a CancellationToken very easily.

I'll follow up in a bit about what's going on here specifically. How are you registering your error handler? Is it an IErrorHandler?

@mconnew : Yes, IErrorHandler implementation is what we use:

public class ErrorHandler : IErrorHandler {...}

Inside of HandleError(Exception ex) we log the exceptions.

It was my understanding that ProvideFault() was only used if you wanted to transform the exception. Are you saying there should be additional logic in that method?

Do you have a link to examples of what would be expected to be in the ProvideFault() method to log information that is not already in HandelError()?

[mconnew]

I was saying you could work out what was causing this condition using the ProvideFault method, you don't need to do anything different

[chekm8]

@mconnew I'm not sure that I am following on all the possibilities that you listed above, however my code does always log exceptions and the "System.TimeoutException: Receive timed out after 00:00:00." is the only exception in my logs currently. This seems to imply that it's not as a result of some other exception occurring first, otherwise that one would have been logged around the same time period.

We do not have any code that implements IMergeEnabledMessageProperty , we are using WCFCore so that rules out that one too.

Additionally, You mentioned in your Feb 4th post "The value is 10 seconds". Why would the exception be showing "00:00:00" if there was an actual timeout value?

I prefer to find the root cause of an exception, but if that is not possible, is there harm in swallowing this specific exception?