Stuck on stop process

[Unknow0]

Hi,

From time to time we have a job that stuck in the stop()
i know that we have some communication issues with the loki server but when it happend when the job running we have a log and the retry finish to send it without error.

Here we have no error in the console only the job stuck until we kill it.

stacktrace:

"main" #1 prio=5 os_prio=0 cpu=69979.56ms elapsed=59957.15s tid=0x00007fc7fb06c0f0 nid=0x7 waiting on condition  [0x00007fc802e0b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.14/Native Method)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.14/LockSupport.java:376)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.waitSendQueueLessThan(AsyncBufferPipeline.java:398)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.waitSendQueueIsEmpty(AsyncBufferPipeline.java:176)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.stop(AsyncBufferPipeline.java:156)
        at com.github.loki4j.logback.Loki4jAppender.stop(Loki4jAppender.java:189)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.detachAndStopAllAppenders(AppenderAttachableImpl.java:107)
        at ch.qos.logback.classic.Logger.detachAndStopAllAppenders(Logger.java:209)
        at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:333)
        at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:382)
        at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:359)
        at [...].main([..].java:64)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=3.33ms elapsed=59957.08s tid=0x00007fc7fb06d330 nid=0xe waiting on condition  [0x00007fc799fff000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.14/Native Method)
        at java.lang.ref.Reference.processPendingReferences(java.base@17.0.14/Reference.java:253)
        at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.14/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.67ms elapsed=59957.08s tid=0x00007fc7fb06d9a0 nid=0xf in Object.wait()  [0x00007fc799efc000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.14/Native Method)
        - waiting on <0x00000007015d9d48> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.14/ReferenceQueue.java:155)
        - locked <0x00000007015d9d48> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.14/ReferenceQueue.java:176)
        at java.lang.ref.Finalizer$FinalizerThread.run(java.base@17.0.14/Finalizer.java:172)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.41ms elapsed=59957.07s tid=0x00007fc7df3ac070 nid=0x10 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=39.02ms elapsed=59957.07s tid=0x00007fc7df3ac6d0 nid=0x11 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=5664.80ms elapsed=59957.07s tid=0x00007fc7df3acd30 nid=0x12 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=18380.60ms elapsed=59957.07s tid=0x00007fc7df3ad390 nid=0x13 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=3699.65ms elapsed=59957.07s tid=0x00007fc7df3ada00 nid=0x14 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=62.20ms elapsed=59957.07s tid=0x00007fc7df3a00a0 nid=0x15 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Notification Thread" #10 daemon prio=9 os_prio=0 cpu=0.14ms elapsed=59957.07s tid=0x00007fc7df3a0700 nid=0x16 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=66.56ms elapsed=59957.07s tid=0x00007fc7df3a0d70 nid=0x18 in Object.wait()  [0x00007fc7995e1000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.14/Native Method)
        - waiting on <no object reference available>
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.14/ReferenceQueue.java:155)
        - locked <0x00000007015d9f58> (a java.lang.ref.ReferenceQueue$Lock)
        at jdk.internal.ref.CleanerImpl.run(java.base@17.0.14/CleanerImpl.java:140)
        at java.lang.Thread.run(java.base@17.0.14/Thread.java:840)
        at jdk.internal.misc.InnocuousThread.run(java.base@17.0.14/InnocuousThread.java:162)

"HttpClient-1-SelectorManager" #12 daemon prio=5 os_prio=0 cpu=1522.33ms elapsed=59955.37s tid=0x00007fc7990af010 nid=0x19 runnable  [0x00007fc798e90000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPoll.wait(java.base@17.0.14/Native Method)
        at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@17.0.14/EPollSelectorImpl.java:118)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@17.0.14/SelectorImpl.java:129)
        - locked <0x00000007015da218> (a sun.nio.ch.Util$2)
        - locked <0x00000007015da1c8> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(java.base@17.0.14/SelectorImpl.java:141)
        at jdk.internal.net.http.HttpClientImpl$SelectorManager.run(java.net.http@17.0.14/HttpClientImpl.java:894)

"loki4j-sender-0" #13 daemon prio=5 os_prio=0 cpu=67451.58ms elapsed=59955.35s tid=0x00007fc7990af6b0 nid=0x1a waiting on condition  [0x00007fc798d8d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.14/Native Method)
        - parking to wait for  <0x00000007015d9410> (a com.github.loki4j.client.pipeline.AsyncBufferPipeline)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.14/LockSupport.java:252)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.sendStep(AsyncBufferPipeline.java:288)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.runSendLoop(AsyncBufferPipeline.java:224)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.lambda$start$3(AsyncBufferPipeline.java:131)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline$$Lambda$183/0x00007fc79f148000.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.14/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.14/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.14/Thread.java:840)

"loki4j-encoder-0" #14 daemon prio=5 os_prio=0 cpu=70923.81ms elapsed=59955.35s tid=0x00007fc7990afd60 nid=0x1b waiting on condition  [0x00007fc798c8a000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.14/Native Method)
        - parking to wait for  <0x00000007015d9410> (a com.github.loki4j.client.pipeline.AsyncBufferPipeline)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.14/LockSupport.java:252)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.encodeStep(AsyncBufferPipeline.java:233)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.runEncodeLoop(AsyncBufferPipeline.java:214)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline.lambda$start$4(AsyncBufferPipeline.java:134)
        at com.github.loki4j.client.pipeline.AsyncBufferPipeline$$Lambda$184/0x00007fc79f148228.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.14/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.14/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.14/Thread.java:840)

"loki4j-scheduler-0" #15 daemon prio=5 os_prio=0 cpu=22.11ms elapsed=59955.35s tid=0x00007fc7990b0400 nid=0x1c waiting on condition  [0x00007fc798b86000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.14/Native Method)
        - parking to wait for  <0x0000000700f25bc8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(java.base@17.0.14/LockSupport.java:341)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.14/AbstractQueuedSynchronizer.java:506)
        at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.14/ForkJoinPool.java:3465)
        at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.14/ForkJoinPool.java:3436)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.14/AbstractQueuedSynchronizer.java:1630)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.14/ScheduledThreadPoolExecutor.java:1170)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.14/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.14/ThreadPoolExecutor.java:1062)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.14/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.14/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.14/Thread.java:840)

"BufferPoolPruner-1-thread-1" #19 daemon prio=5 os_prio=0 cpu=183.67ms elapsed=59949.65s tid=0x00007fc7994370e0 nid=0x20 waiting on condition  [0x00007fc798183000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.14/Native Method)
        - parking to wait for  <0x00000007015da618> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.14/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@17.0.14/AbstractQueuedSynchronizer.java:1679)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.14/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.14/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.14/ThreadPoolExecutor.java:1062)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.14/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.14/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.14/Thread.java:840)

"VM Periodic Task Thread" os_prio=0 cpu=34448.65ms elapsed=59957.07s tid=0x00007fc7df3b7d50 nid=0x17 waiting on condition  

"VM Thread" os_prio=0 cpu=1645.13ms elapsed=59957.09s tid=0x00007fc7df3bf060 nid=0xd runnable  

"G1 Service" os_prio=0 cpu=12640.18ms elapsed=59957.12s tid=0x00007fc7df69df80 nid=0xc runnable  

"G1 Refine#0" os_prio=0 cpu=6.71ms elapsed=59957.12s tid=0x00007fc7ebe47cc0 nid=0xb runnable  

"G1 Conc#0" os_prio=0 cpu=39.16ms elapsed=59957.15s tid=0x00007fc7ebe479b0 nid=0xa runnable  

"G1 Main Marker" os_prio=0 cpu=0.63ms elapsed=59957.15s tid=0x00007fc7ebe47690 nid=0x9 runnable  

"GC Thread#0" os_prio=0 cpu=244.05ms elapsed=59957.15s tid=0x00007fc7ebe47340 nid=0x8 runnable  

JNI global refs: 15, weak refs: 0

Heap
 garbage-first heap   total 4194304K, used 143599K [0x0000000700000000, 0x0000000800000000)
  region size 2048K, 62 young (126976K), 2 survivors (4096K)
 Metaspace       used 22374K, committed 22656K, reserved 1114112K
  class space    used 2411K, committed 2560K, reserved 1048576K

Logback config:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>

<configuration>
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{yyyy-MM-dd'T'HH:mm:ssXXX} %-5level [%logger] %msg%n</pattern>
		</encoder>
	</appender>

	<appender name="LOKI" class="com.github.loki4j.logback.Loki4jAppender">
		<http>
			<url>https://lokiurl</url>
			<tenantId>tenant</tenantId>
		</http>
		<format>
			<label>
				<pattern>namespace=namespace,service_name=${APP_NAME:-updater-test},level=%level</pattern>
			</label>
			<message>
				<pattern>%-5level [%logger] %msg%n</pattern>
			</message>
		</format>
	</appender>

	<logger name="package" level="info" />
	<root level="warn">
		<appender-ref ref="STDOUT" />
		<appender-ref ref="LOKI" />
	</root>
</configuration>

Regards.

[nehaev]

Hi @Unknow0, thanks for reporting this!

Even with this thread dump, it's still hard to figure out what exactly has happened in this case. If you're willing to help with that, please enable the tracing mode and attach the log to this issue. It will print out a lot of stuff, but we're only interested in what's going on starting from Pipeline is stopping... log line.

As a workaround, you can set drainOnStop to false in you loki4j config (related docs).

[nehaev]

Yeah, one more thing: I wonder if you can confirm that stuck happens only if there were send errors and retries during that session?

[Unknow0]

Hi,

I will try to enable it and we will see the next time it happen, as it happen not very often (the job is launched every 20min but it stale like that less than once a month i think)

And no it had no error and retries in this run and i think it didn't send logs at all before the stop (as the run is short and have very few line of logs to send)

Regards.

[Unknow0]

Hi @nehaev

sorry i miss clicked on the close issues ><