AsyncAppender queueLoggingEvent method stuck when Ringbuffer is full with unread events

[noorulhaq]

Hi,

If the subscriber is unable to write logs because of any reason the logger doAppend stuck in an infinite waiting loop because the writer cannot surpass the reader. Below is the is the thread dump captured in that moment.

java.lang.Thread.State: WAITING
	  at sun.misc.Unsafe.park(Unsafe.java:-1)
	  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
	  at reactor.core.publisher.MultiProducerRingBuffer.next(RingBuffer.java:1850)
	  at reactor.core.publisher.MultiProducerRingBuffer.next(RingBuffer.java:1816)
	  at reactor.core.publisher.UnsafeRingBuffer.next(RingBuffer.java:1576)
	  at reactor.core.publisher.EventLoopProcessor.onNext(EventLoopProcessor.java:445)
	  at reactor.logback.AsyncAppender.queueLoggingEvent(AsyncAppender.java:238)
	  at reactor.logback.AsyncAppender.doAppend(AsyncAppender.java:104)
	  at reactor.logback.AsyncAppender.doAppend(AsyncAppender.java:46)
	  at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
	  at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
	  at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
	  at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
	  at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
	  at ch.qos.logback.classic.Logger.debug(Logger.java:503)
	  at com.non.reactive.bank.Application.main(Application.java:18)

Also, below is the code snippet where the requesting thread stuck. The code snippet is taken from reactor RingBuffer:

@Override
	public long next(int n)
	{
		if (n < 1)
		{
			throw new IllegalArgumentException("n must be > 0");
		}

		long current;
		long next;

		do
		{
			current = cursor.getAsLong();
			next = current + n;

			long wrapPoint = next - bufferSize;
			long cachedGatingSequence = gatingSequenceCache.getAsLong();

			if (wrapPoint > cachedGatingSequence || cachedGatingSequence > current)
			{
				long gatingSequence = RingBuffer.getMinimumSequence(gatingSequences, current);

				if (wrapPoint > gatingSequence)
				{
					if(spinObserver != null) {
						spinObserver.run();
					}
					LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy?
					continue;
				}

				gatingSequenceCache.set(gatingSequence);
			}
			else if (cursor.compareAndSet(current, next))
			{
				break;
			}
		}
		while (true);

		return next;
	}

I can see that that the wait strategy is not being used to handle this situation. Is there any way to get out of this situation either by throwing any timeout exception or anything else rational. I know we may loose logs for some time but at least the requesting threads will not hang because of this issue.

[noorulhaq]

This does not seem to be a reactor API issue. It happened because subscribers were unable to write logs due to some reason. This caused log publisher to keep on waiting for subscribers to read the log events from RingBuffer. Ideally, log writer should be monitored to avoid any such kind of situation. I have developed an extension of reactor-logback that uses Hystrix circuit breaker to monitor logging. In case there is any hiccup in file logging the circuit will open and will execute the fallback.
Please refer to below link if you are interested in avoiding cascading failure due to file logging with reactor logback.
https://github.com/noorulhaq/reactor-logback-hystrix