search

klogging / klogging

Kotlin logging library with structured logging and coroutines support
https://klogging.io
Apache License 2.0
182 stars 18 forks source link

StringIndexOutOfBounds in io.klogging.rendering.RenderAnsiKt::shortenName #218

Closed chile12 closed 11 months ago

chile12 commented 11 months ago

This function will cause an IooB Exception if given a sting with many delimiters:

image

java.lang.StringIndexOutOfBoundsException: Range [0, -12) out of bounds for length 34

    at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:55)
    at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:52)
    at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:213)
    at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:210)
    at java.base/jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:98)
    at java.base/jdk.internal.util.Preconditions.outOfBoundsCheckFromToIndex(Preconditions.java:112)
    at java.base/jdk.internal.util.Preconditions.checkFromToIndex(Preconditions.java:349)
    at java.base/java.lang.String.checkBoundsBeginEnd(String.java:4602)
    at java.base/java.lang.String.substring(String.java:2715)
    at java.base/java.lang.String.subSequence(String.java:2753)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:79)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.getRight20(RenderAnsi.kt:60)
    at io.klogging.rendering.RenderAnsiKt$RENDER_ANSI$1.invoke(RenderAnsi.kt:88)
    at io.klogging.rendering.RenderAnsiKt$RENDER_ANSI$1.invoke(RenderAnsi.kt:86)
    at io.klogging.sending.SendingKt$senderFrom$1$1.invoke(Sending.kt:32)
    at io.klogging.sending.SendingKt$senderFrom$1$1.invoke(Sending.kt:32)
    at kotlin.text.StringsKt__AppendableKt.appendElement(Appendable.kt:85)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinTo(_Collections.kt:3490)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinToString(_Collections.kt:3507)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinToString$default(_Collections.kt:3506)
    at io.klogging.sending.SendingKt$senderFrom$1.invoke(Sending.kt:32)
    at io.klogging.sending.SendingKt$senderFrom$1.invoke(Sending.kt:31)
    at io.klogging.internal.Sink.sendDirect$klogging(Sink.kt:88)
    at io.klogging.internal.Dispatcher.sendDirect$klogging(Dispatcher.kt:57)
    at io.klogging.internal.Emitter.emitDirect(Emitter.kt:69)
    at io.klogging.impl.KloggerImpl.emitEvent(KloggerImpl.kt:43)
    at io.klogging.Klogger$DefaultImpls.log(Klogger.kt:50)
    at io.klogging.impl.KloggerImpl.log(KloggerImpl.kt:35)
    at ...
    at ...
    at ...
    at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:46)
    at ...
    at _COROUTINE._CREATION._(CoroutineDebugging.kt:34)
    at kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:122)
    at kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:30)
    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
    at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
    at ...
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
    at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
    at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:53)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
Caused by: java.lang.StringIndexOutOfBoundsException: Range [0, -12) out of bounds for length 34
    at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:55)
    at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:52)
    at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:213)
    at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:210)
    at java.base/jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:98)
    at java.base/jdk.internal.util.Preconditions.outOfBoundsCheckFromToIndex(Preconditions.java:112)
    at java.base/jdk.internal.util.Preconditions.checkFromToIndex(Preconditions.java:349)
    at java.base/java.lang.String.checkBoundsBeginEnd(String.java:4602)
    at java.base/java.lang.String.substring(String.java:2715)
    at java.base/java.lang.String.subSequence(String.java:2753)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:79)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.shortenName(RenderAnsi.kt:76)
    at io.klogging.rendering.RenderAnsiKt.getRight20(RenderAnsi.kt:60)
    at io.klogging.rendering.RenderAnsiKt$RENDER_ANSI$1.invoke(RenderAnsi.kt:88)
    at io.klogging.rendering.RenderAnsiKt$RENDER_ANSI$1.invoke(RenderAnsi.kt:86)
    at io.klogging.sending.SendingKt$senderFrom$1$1.invoke(Sending.kt:32)
    at io.klogging.sending.SendingKt$senderFrom$1$1.invoke(Sending.kt:32)
    at kotlin.text.StringsKt__AppendableKt.appendElement(Appendable.kt:85)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinTo(_Collections.kt:3490)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinToString(_Collections.kt:3507)
    at kotlin.collections.CollectionsKt___CollectionsKt.joinToString$default(_Collections.kt:3506)
    at io.klogging.sending.SendingKt$senderFrom$1.invoke(Sending.kt:32)
    at io.klogging.sending.SendingKt$senderFrom$1.invoke(Sending.kt:31)
    at io.klogging.internal.Sink.sendDirect$klogging(Sink.kt:88)
    at io.klogging.internal.Dispatcher.sendDirect$klogging(Dispatcher.kt:57)
    at io.klogging.internal.Emitter.emitDirect(Emitter.kt:69)
    at io.klogging.impl.KloggerImpl.emitEvent(KloggerImpl.kt:43)
    at io.klogging.Klogger$DefaultImpls.log(Klogger.kt:50)
    at io.klogging.impl.KloggerImpl.log(KloggerImpl.kt:35)
mjstrasser commented 11 months ago

Hi @chile12 thanks for raising this issue.

Your problem was caused by passing a nonsense value of -12 for width. Can you change your code to pass meaningful values?

I will soon update the definition of shortenName() to ensure values make sense. I need to decide what is a meaningful minimum width value.

chile12 commented 11 months ago

Sorry for not being clear. The nonsense value is generated automatically by recursively calling shortenName (line 76) applying width -2. I do not call this function, the RenderAnsi Renderer does.

mjstrasser commented 11 months ago

I see: the issue arises if the extension function right20() is called on a string that has too many delimiters in it. It then calls shortenName(). From your stack trace, RENDER_ANSI calls right20() on the logger name.

That had never happened in my testing. It is fixed by my most recent commit.

Out of interest, what is the name of the logger that caused your issue?