log more info when fvh failed

[waziqi89]

The fvh exception is not logged properly. Fix the bug, and add more context on the message.
from

[WARN ] 2024-01-19 15:06:37.546 [GrpcLuceneServerExecutor-6-thread-28] NRTFastVectorHighlighter - FVH failed creating fragments, and the exception is: }

to

[WARN ] 2024-01-22 16:29:36.059 [GrpcLuceneServerExecutor-5-thread-17] NRTFastVectorHighlighter - FVH failed creating fragments for the luceneDocId: 1, highlight query: #_nested_path:reviews +(((reviews.raw_text:pepper)^5.0 (reviews.raw_text:salt)^3.0)~1), exception: dummy runtime exception
java.lang.RuntimeException: dummy runtime exception
        at com.yelp.nrtsearch.server.luceneserver.highlights.NRTFastVectorHighlighter.getHighlights(NRTFastVectorHighlighter.java:131) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.highlights.HighlightFetchTask.processHit(HighlightFetchTask.java:80) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.search.FetchTasks.processHit(FetchTasks.java:161) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.SearchHandler$FillDocsTask.fetchSlice(SearchHandler.java:922) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.SearchHandler$FillDocsTask.run(SearchHandler.java:850) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.SearchHandler.fetchFields(SearchHandler.java:423) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.luceneserver.SearchHandler.handle(SearchHandler.java:222) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.grpc.LuceneServer$LuceneServerImpl.search(LuceneServer.java:1069) ~[nrtsearch-0.30.0.jar:?]
        at com.yelp.nrtsearch.server.grpc.LuceneServerGrpc$MethodHandlers.invoke(LuceneServerGrpc.java:3376) ~[clientlib-0.30.0.jar:?]
        at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182) ~[grpc-stub-1.46.0.jar:1.46.0]
        at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35) ~[grpc-api-1.46.0.jar:1.46.0]
        at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23) ~[grpc-api-1.46.0.jar:1.46.0]
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340) ~[grpc-core-1.46.0.jar:1.46.0]
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866) ~[grpc-core-1.46.0.jar:1.46.0]
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.46.0.jar:1.46.0]
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.46.0.jar:1.46.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]

Note that the query would be the "LUCENE" query, but still informative for engineers to debug.

[sarthakn7]

No need for String.format since you're only using logger, and you can also log the complete exception. So something like:

logger.warn(
              "FVH failed creating fragments for the luceneDocId: {}, highlight query: {}, exception: {}",
              leafDocId + hitLeaf.docBase,
              settings.getHighlightQuery(),
              runtimeException.getMessage(),
              runtimeException);

[sarthakn7]

Can you please add the exception as well like I had added in my previous comment?
Also can you please test it locally and verify that the log works as expected now? You can add the logged message in the PR description.

[waziqi89]

It's hard to reproduce the error unless we have a buggy analyzer. I created a dummy exception which will serve the test purpose.

[sarthakn7]

@waziqi89 if you log like this:

logger.warn(
              "FVH failed creating fragments for the luceneDocId: {}, highlight query: {}, exception: {}",
              leafDocId + hitLeaf.docBase,
              settings.getHighlightQuery(),
              runtimeException.getMessage(),
              runtimeException);

i.e. have the exception at the end without having a placeholder for it in the string message, it will log the entire stacktrace in addition to the message. Can you please do that?

[sarthakn7]

Let me know if you don't want to log the stacktrace.

[waziqi89]

In the latest commit, the exception is logged instead of message. Guess the test result is misleading because the dummy exception has not stacktrace

[sarthakn7]

Since you have exception: {} it'll just log the exception message and not the stacktrace. Example:

try {
      throw new RuntimeException("Test");
    } catch (Exception e) {
      logger.warn("Error: {}, Exception: {}", "Test error", e);
    }

The output is:

[WARN ] 2024-01-22 11:15:33.268 [Test worker] LoggerTest - Error: Test error, Exception: java.lang.RuntimeException: Test

vs

try {
      throw new RuntimeException("Test");
    } catch (Exception e) {
      logger.warn("Error: {}, Exception: {}", "Test error", e.getMessage(), e);
    }

Output:

[WARN ] 2024-01-22 11:17:36.810 [Test worker] LoggerTest - Error: Test error, Exception: Test
java.lang.RuntimeException: Test
	at com.yelp.nrtsearch.LoggerTest.logExceptionTest(LoggerTest.java:20) ~[test/:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) ~[junit-4.13.2.jar:4.13.2]
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413) ~[junit-4.13.2.jar:4.13.2]
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110) ~[?:?]
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58) ~[?:?]
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38) ~[?:?]
	at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62) ~[?:?]
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36) ~[?:?]
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) ~[?:?]
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33) ~[?:?]
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94) ~[?:?]
	at jdk.proxy2.$Proxy5.processTestClass(Unknown Source) ~[?:?]
	at org.gradle.api.internal.tasks.testing.worker.TestWorker$2.run(TestWorker.java:176) ~[?:?]
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129) ~[?:?]
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100) ~[?:?]
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60) ~[?:?]
	at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56) ~[?:?]
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:133) ~[?:?]
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:71) ~[?:?]
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69) ~[gradle-worker.jar:?]
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74) ~[gradle-worker.jar:?]

As you can see there is no stacktrace in the first case.

[sarthakn7]

Can you please also update the description with the new log that includes the stacktrace?