You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Dominik Psenner (JIRA)" <ji...@apache.org> on 2017/08/30 18:43:01 UTC
[jira] [Commented] (LOG4NET-573) Appenders Deadlock
[ https://issues.apache.org/jira/browse/LOG4NET-573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16147792#comment-16147792 ]
Dominik Psenner commented on LOG4NET-573:
-----------------------------------------
Hi Michal.
There's a lot going on in these stacktraces. There is NHibernate, ServiceModel Rpc, AppDomain Timers, Autofac, Mailer jobs and a lot more pieces that all add up to a great deal of complexity without explanation how these pieces are supposed to fit together. The log4net configuration is complicated too, complicated enough that I couldn't understand it while reading it. With this information it is impossible to say if there is actually a deadlock or where it could be. It may be that a deadlock is not actually caused by log4net but rather a consequence of a bad configuration of the logging framework or even a design flaw of the application and an implication of how all the pieces work together.
Would you please explain the application in simple words? What does it do? Who logs what and where are these log events sinked to? Are there multiple processes involved? Are there multiple threads in multiple processes involved? How do all those processes interact? Please try to work away as much complexity as you can. I hope that you'll find the cause of the symptoms you experience while doing so because I'm afraid that this task is not an easy one and it will take days if not weeks to work out without having the entire application at hands.
Cheers
> Appenders Deadlock
> ------------------
>
> Key: LOG4NET-573
> URL: https://issues.apache.org/jira/browse/LOG4NET-573
> Project: Log4net
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 1.2.15
> Environment: Win10
> Reporter: Michal
> Priority: Blocker
> Attachments: LoggingConfiguration.log4net.config
>
>
> Hi,
> I have struggled with a deadlock using log4net when multiple threads are logging.
> This situation is hadr to reproduce but it happends from time to time
> Threads call stacks:
> {code:java}
> log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend Normal
> log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> MT.Spectra.BaseFramework.dll!MT.Spectra.BaseFramework.ILogExtensions.Log(log4net.Core.ILoggerWrapper logger, log4net.Core.Level level, System.Func<MT.Spectra.BaseFramework.MessageFormatter, string> formatter, System.Func<string> contextProvider, System.Exception exception)
> MT.Spectra.MtRpc.dll!MT.Spectra.MtRpc.ReconnectableRpcChannel.ConnectInnerChannel(MT.Spectra.MtRpc.IRpcChannel innerChannel)
> MT.Spectra.MtRpc.dll!MT.Spectra.MtRpc.ReconnectableRpcChannel.ReconnectableRpcChannel(MT.Spectra.MtRpc.IRpcChannel innerChannel, System.TimeSpan reconnectionTimeout, MT.Spectra.MtRpc.ReconnectableRpcChannel.ChannelStrategy strategy)
> MT.Spectra.MtRpc.dll!MT.Spectra.MtRpc.ReconnectableRpcChannel.CreateClientChannel(MT.Spectra.MtRpc.IRpcChannel innerChannel, System.TimeSpan reconnectionTimeout, System.TimeSpan reconnectionInterval)
> MT.SWF.MtRpc.Autofac.dll!MT.SWF.MtRpc.Autofac.RpcClientContextModule.ClientSideChannelFactory(Autofac.IComponentContext c, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> p)
> Autofac.dll!Autofac.Builder.RegistrationBuilder.ForDelegate.AnonymousMethod__0(Autofac.IComponentContext c, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> p)
> Autofac.dll!Autofac.Core.Activators.Delegate.DelegateActivator.ActivateInstance(Autofac.IComponentContext context, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.Core.Resolving.InstanceLookup.Activate(System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.Core.Resolving.InstanceLookup.Execute.AnonymousMethod__0()
> Autofac.dll!Autofac.Core.Lifetime.LifetimeScope.GetOrCreateAndShare(System.Guid id, System.Func<object> creator)
> Autofac.dll!Autofac.Core.Resolving.InstanceLookup.Execute()
> Autofac.dll!Autofac.Core.Resolving.ResolveOperation.GetOrCreateInstance(Autofac.Core.ISharingLifetimeScope currentOperationScope, Autofac.Core.IComponentRegistration registration, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.Core.Resolving.ResolveOperation.Execute(Autofac.Core.IComponentRegistration registration, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.Core.Lifetime.LifetimeScope.ResolveComponent(Autofac.Core.IComponentRegistration registration, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.ResolutionExtensions.TryResolveService(Autofac.IComponentContext context, Autofac.Core.Service service, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters, out object instance)
> Autofac.dll!Autofac.ResolutionExtensions.ResolveService(Autofac.IComponentContext context, Autofac.Core.Service service, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> Autofac.dll!Autofac.ResolutionExtensions.Resolve<MT.Spectra.MtRpc.IRpcChannel>(Autofac.IComponentContext context, System.Collections.Generic.IEnumerable<Autofac.Core.Parameter> parameters)
> MT.SWF.MtRpc.Autofac.dll!MT.SWF.MtRpc.GenericRpcClient.CreateContext(MT.Spectra.MtRpc.IRpcPort rpcPort)
> MT.Spectra.MtRpc.dll!MT.Spectra.MtRpc.RpcClient<MT.SWF.MtRpc.GenericRpcContext>.Connect(System.TimeSpan connectionTimeout)
> MT.SWF.MtRpc.Autofac.dll!MT.SWF.MtRpc.Autofac.OwnedRpcClient.Connect()
> MT.SWF.IND.FormPlus.DeviceGateway.dll!MT.SWF.IND.Devices.DiscoveredDevice.Probe() Line 170
> MT.SWF.IND.FormPlus.DeviceGateway.dll!MT.SWF.IND.Managers.SyncPlusDeviceManager.ProcessDiscoveredDevice(System.Collections.Generic.IEnumerable<MT.SWF.IND.Devices.DiscoveredDevice> discoveredDevices) Line 476
> MT.SWF.IND.FormPlus.DeviceGateway.dll!MT.SWF.IND.Managers.SyncPlusDeviceManager.AutoDiscoveryLoop(object context) Line 426
> mscorlib.dll!System.Threading.ThreadHelper.ThreadStart_Context(object state)
> mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx)
> mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx)
> mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state)
> mscorlib.dll!System.Threading.ThreadHelper.ThreadStart(object obj)
> [Native to Managed Transition]
> {code}
> {code:java}
> log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend Normal
> log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> log4net.dll!log4net.Core.LogImpl.DebugFormat(System.IFormatProvider provider, string format, object[] args)
> MT.Backbone.Data.NHibernate.dll!MT.SWF.DataAccess.TransactionService.CreateTransactionScope(MT.SWF.DataAccess.TransactionType transactionType, System.Data.IsolationLevel isolationLevel)
> MT.Backbone.Data.NHibernate.dll!MT.SWF.DataAccess.TransactionService.CreateTransactionScope()
> MT.SWF.IND.FormPlus.BusinessLogic.dll!MT.SWF.IND.Security.ClientSessionManager.Renew() Line 164
> MT.Backbone.dll!MT.SWF.ServiceModel.Dispatcher.ClientSessionServerInspector.BeforeCall(string operationName, object[] inputs)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.DispatchOperationRuntime.InspectInputsCore(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage41(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage4(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage31(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage3(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage2(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage11(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(ref System.ServiceModel.Dispatcher.MessageRpc rpc)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.MessageRpc.Process(bool isOperationContextSet)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(System.ServiceModel.Channels.RequestContext request, bool cleanThread, System.ServiceModel.OperationContext currentOperationContext)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(System.ServiceModel.Channels.RequestContext request, System.ServiceModel.OperationContext currentOperationContext)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(System.IAsyncResult result)
> System.ServiceModel.dll!System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(System.IAsyncResult result)
> System.ServiceModel.Internals.dll!System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult result)
> System.ServiceModel.Internals.dll!System.Runtime.AsyncResult.Complete(bool completedSynchronously)
> System.ServiceModel.dll!System.ServiceModel.Channels.TransportDuplexSessionChannel.TryReceiveAsyncResult.OnReceive(System.IAsyncResult result)
> System.ServiceModel.Internals.dll!System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult result)
> System.ServiceModel.Internals.dll!System.Runtime.AsyncResult.Complete(bool completedSynchronously)
> System.ServiceModel.dll!System.ServiceModel.Channels.SynchronizedMessageSource.ReceiveAsyncResult.OnReceiveComplete(object state)
> System.ServiceModel.dll!System.ServiceModel.Channels.SessionConnectionReader.OnAsyncReadComplete(object state)
> System.ServiceModel.dll!System.ServiceModel.Channels.SocketConnection.FinishRead()
> System.ServiceModel.dll!System.ServiceModel.Channels.SocketConnection.OnReceiveAsync(object sender, System.Net.Sockets.SocketAsyncEventArgs eventArgs)
> System.ServiceModel.dll!System.ServiceModel.Channels.SocketConnection.OnReceiveAsyncCompleted(object sender, System.Net.Sockets.SocketAsyncEventArgs e)
> System.dll!System.Net.Sockets.SocketAsyncEventArgs.OnCompleted(System.Net.Sockets.SocketAsyncEventArgs e)
> System.dll!System.Net.Sockets.SocketAsyncEventArgs.FinishOperationSuccess(System.Net.Sockets.SocketError socketError, int bytesTransferred, System.Net.Sockets.SocketFlags flags)
> System.dll!System.Net.Sockets.SocketAsyncEventArgs.CompletionPortCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* nativeOverlapped)
> mscorlib.dll!System.Threading._IOCompletionCallback.PerformIOCompletionCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* pOVERLAP)
> [Native to Managed Transition]
> {code}
> {code:java}
> log4net.dll!log4net.Appender.ColoredConsoleAppender.Append Normal
> [Managed to Native Transition]
> mscorlib.dll!System.IO.__ConsoleStream.WriteFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle hFile, byte[] bytes, int offset, int count, bool useFileAPIs)
> mscorlib.dll!System.IO.__ConsoleStream.Write(byte[] buffer, int offset, int count)
> mscorlib.dll!System.IO.StreamWriter.Flush(bool flushStream, bool flushEncoder)
> mscorlib.dll!System.IO.StreamWriter.Write(char[] buffer, int index, int count)
> log4net.dll!log4net.Appender.ColoredConsoleAppender.Append(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent)
> log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception)
> log4net.dll!log4net.Core.LogImpl.Info(object message)
> MT.SWF.IND.FormPlus.BusinessLogic.dll!MT.SWF.IND.Notifications.InterruptionMailerJob.NotifyInterruptedBatches() Line 113
> MT.SWF.IND.FormPlus.BusinessLogic.dll!MT.SWF.IND.Notifications.InterruptionMailerJob.StartPeriodicalChecks.AnonymousMethod__12_0(object state) Line 88
> MT.SWF.BaseFramework.dll!MT.SWF.Threading.ThreadFactory.CreateSynchronousTimer.AnonymousMethod__0(object sender, MT.SWF.Threading.TimerEventArgs e)
> MT.SWF.BaseFramework.dll!MT.SWF.Threading.WrappedTimer..ctor.AnonymousMethod__1()
> MT.SWF.BaseFramework.dll!MT.SWF.Threading.WrappedTimer.SynchronousWorkerWrapper(System.Action worker)
> MT.SWF.BaseFramework.dll!MT.SWF.Threading.WrappedTimer..ctor.AnonymousMethod__0(object x)
> mscorlib.dll!System.Threading.TimerQueueTimer.CallCallbackInContext(object state)
> mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx)
> mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx)
> mscorlib.dll!System.Threading.TimerQueueTimer.CallCallback()
> mscorlib.dll!System.Threading.TimerQueueTimer.Fire()
> mscorlib.dll!System.Threading.TimerQueue.FireNextTimers()
> mscorlib.dll!System.Threading.TimerQueue.AppDomainTimerCallback()
> [Native to Managed Transition]
> {code}
> Im also attaching configurtation file.
> Could someone help me to confirmat, that is a bug?
> Also if additional information are needed, fell free to ask
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)