Grepped lines are missing the log timestamp sometimes

[Itox001]

Describe the bug Thanks for the awesome extension, it rocks.

Having said that, I ran into an issue when using it: I can grep for a certain term, and while this works and I see my filtered logs, once in a while the timestamp of a log line will be missing. Naturally the original log line contains the timestamp, just like the rest. This is reproduceable, the same log line will always have the timestamp missing.

Example:

I am pretty sure that this is a bug, because once I press the "Reload" button, the filtered console reloads and all timestamps look correct:

Example of the log line you see in the screenshots: 2024-05-17T18:20:05.196+02:00 DEBUG 68728 --- [pool-5-thread-1] c.m.p.frontend.config.JwtTokenValidator : Refreshing JWKS ---- ScheduledRefreshInitiatedEvent

I am using Spring Boot 3 with slf4j logging. IDE is Intellij IDEA Ultimate 2024.1.1 running on MacOS. Let me know if you need more information.

Thanks!

[krasa]

There is some special handling for incomplete lines, maybe it is not enough. Try this:

[Itox001]

I tried setting the Buffer Streams option, quit Intellij and started it again, but sadly the issue persists. I also tried with the Filtering option that is next to it, quit and restart again, but it still remains. Any other ideas?

[krasa]

Conflict with another plugin? https://github.com/krasa/GrepConsole/issues/303#issuecomment-2117294362

[krasa]

Or debugging the plugin :(

[Itox001]

I dont think I have any other plugin which would interfere with console logging. This are the Downloaded + Enabled plugins currently:

• AspectJ (241.15989.21)
• Big Data Tools Core (241.15989.150)
• Cucumber for Java (241.14494.158)
• Gherkin (241.14494.150)
• Go (241.15989.21)
• Grep Console (12.25.0-IJ2023.3)
• Kafka (241.14494.158)
• Makefile Language (241.14494.150)
• Package Search (241.0.9)
• Space (241.15989.9)
• Statistic (4.2.14)
• VisualVM Launcher (1.23.1-IJ2023.3)

Do you see anything suspicious?

[krasa]

nope.

Debugging would be easy

• gradle runIde
• conditional breakpoint here, for no timestamp,... https://github.com/krasa/GrepConsole/blob/cacfced9a35d6c828c216e284dde73b2138037b9/src/main/java/krasa/grepconsole/grep/listener/GrepFilterSyncListener.java#L100

[Itox001]

Setting it up was easier than expected:

It seems that by the time it hits this breakpoint, the timestamp is already gone. It is a bit hard to diagnose, without any knowledge of how it is working and it will probably take me quite some time to investigate how this whole thing works and understand what is the problem. Could you give me some hints on what to look for? Meanwhile I will start taking a look.

Thanks!

[krasa]

I would just go back in the stack, to see if it is missing from the beginning.

Then perhaps add logging for GrepFilterSyncListener#previousIncompleteToken and check what is happening and that the same thread uses it.

[Itox001]

So I gave it a shot, and perhaps I am simplyfing a bit since I don't really get how the system interconects yet, but this is what I found. When my faulty log is being processed, the first token that arrives is the timestamp "2024-05-17T21:11:36.224+02:00". This is the middle of the log, so the code from the file GrepFilterSyncListener lines 61-73 should collect the tokens until it reaches the \n:

But somehow, that substraction on line 63 evaluates to something greater than 1000 (used the conditional breakpoint to stop if the evaluation is >1000 and log it, and the logged time is pretty much the time between my logs which belong to a scheduled job), this results in the block with the continue being skipped, and we get to the next if (line 75) that evaluates to true (previousIncompleteToken.get() evaluates to "" and not null) which nulls out the previousTimestamp and previousIncompleteToken. Then the processing continues, and when the next token arrives (next token is just " "), it doesnt find any previous incomplete token so its not able to concatenate them.

I would need to dive some more to see why this is the case, but it looks like there is some issue related to this previousTimestamp, perhaps it is not cleaned up somewhere. One thing which seems to be relevant here that I mentioned above: My log is that of a scheduled job, so there is no logging activity for the past 45 seconds when it arrives.

Are you able to make sense of this?

[krasa]

Thanks. Makes sense, maybe that condition should be removed, so that it always waits for a line break.

So you are printing a log like by pieces? That is strange. I would understand if it happened at random due to GC. I see, it is because of ANSI colors. That splits the original line...

[krasa]

And perhaps java.lang.System#currentTimeMillis is not as accurate on mac, should have used nanoTime.

[Itox001]

After debugging it, I realized that I can actually reproduce it with any scheduled job, even with 10 seconds interval.

Are you not able to reproduce this on your side? You'd need just to print logs with some interval, and probably some logging framework which introduces the ANSI colors which you mention are the ones splitting my logs. I am certainly not printing my logs in parts on purpose :)

I use Spring Boot, and my logs look like this normally (not my image):

My previous screenshots show them only gray because of Grep Console grey Debug highlighting.

[Itox001]

Normal console:

Grepped console:

[krasa]

I reproduced it with spring boot, should be good now :-) Thanks!

[Itox001]

You sir are a gentleman and a scholar. I could already download the update for the plugin directly from the Marketplace, and it works great. Thanks for being so responsive, you rock!

[krasa]

Thanks, you inspired me to implement grep with colors #119, the text might go missing again :-D

[Itox001]

I was already looking at that ticket yesteday after posting the screenshots of my gray grepped console, so its awesome that you'll work on it now. Hopefully we'll have both eventually!

[krasa]

It's already done, you can update :)

[Itox001]

You are on a streak! Works great.

But actually I first tried to test it using some JS project I had open now and could not. So following the plugin description link I found this one: https://youtrack.jetbrains.com/issue/IJPL-60196/TerminalExecutionConsole-Extension-points-support. Did you already see their feeedback request? Perhaps after 5 years it will finally be time for them to fix it!

[krasa]

Yes, I will split the issue when I stop procrastinating :-)