LogViewPlus Support » LogViewPlus Support » Help & Support » LogViewPlus is failing when logs are recreated

LogViewPlus is failing when logs are recreated

Miserableman — Fri, 05 Apr 2024 16:12:15 GMT

Hello,

I work for a medium-sized developer and I'm currently investigating the feasibility of us using LogViewPlus to view and debug the logs generated by the software we make. It has lots of killer features that would be very useful for us, but unfortunately at least one killer drawback.

The software being developed generates a text log, and overwrites this log each time the application is started. By default, LogViewPlus keeps the output from old logs in its view, so if you run the application five times and then try to filter the view, you see output from the previous four runs along with the current run. This confuses the output and is not desired.

I found the option in LogViewPlus settings to "Clear all log entries when the log file is rolled or recreated" which looks like it should solve this. However, when this option is enabled, LogViewPlus now shows the following prompt when the software being developed is restarted.

LogViewPlus then has to be restarted, or the logfile has to be re-added to its view, in order to view logs again.

A potential factor is that the log-generating software, when restarted, copies the old log file and renames it within the same folder. For example, if the application is set to write logs to client.log, when it starts up it will copy the previous client.log to client-backup-<timestamp>.log and then start a new client.log file. This behaviour may or may not be related.

Has anyone seen this issue before, and/or know how to fix it?

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Fri, 05 Apr 2024 16:12:15 GMT

Please see our definition of a log entry.

Consider the log line:
[code][2024.04.05-16.14.05:548][123]Logger: An error has occurred!
--- CALLSTACK ---=[C](-1) : ?
@C:/Path/To/Source/Files/sourceA.py(123) : functionA
@C:/Path/To/Source/Files/sourceB.py(456) : functionB
@C:/Path/To/Source/Files/sourceC.py(789) : functionC
--- CALLSTACK ---[/code]
Is that one long entry - or four or six? According to our definition, it is one log entry because there is only one timestamp.

The parser configuration:
[code]%c: %m%n[/code]
Does not meet our definition of a log entry because it does not define a timestamp. This is actually a bug which I believe is specific to multi-patterns (which are an advanced feature). We will probably need to fix this in a future release. In fact, this thread is leading me to think it should be fixed with a higher priority because we don't test for this scenario and you are likely to have additional issues with this configuration in future (which we will not be able to support).

I would suggest using the parser configuration:
[code][%d{yyyy.MM.dd-HH.mm.ss:fff}][%t]%c: %m%n
%m, %d{dd/MM/yy %H:mm:ss}%n[/code]
Using this configuration, the file above contains 7 log entries. The two 'advanced' entries will be parsed across multiple lines:

If it is necessary to break the header up across multiple lines and you are not able to change your application, you may also want to consider a custom parser which will give you an opportunity to set a timestamp even if one does not exist in the log entry.

Hope that helps,

Toby

RE: LogViewPlus is failing when logs are recreated

Miserableman — Fri, 05 Apr 2024 15:47:00 GMT

[quote]Are you still using that pattern?[/quote]
Unfortunately so. That pattern matches the hundreds of lines produced after the first line, see the "Message with no timestamp" lines in the example log below:

[code]Log file open, 04/05/24 16:14:04
Logger: Message with no timestamp 1
Logger: Message with no timestamp 2
Logger: Message with no timestamp 3
Logger: Hundreds of these messages with no timestamp
[2024.04.05-16.14.05:545][123]Logger: Message with timestamp 1
[2024.04.05-16.14.05:546][123]Logger: Message with timestamp 2
[2024.04.05-16.14.05:547][123]Logger: Message with timestamp 3
[2024.04.05-16.14.05:548][123]Logger: An error has occurred!
--- CALLSTACK ---=[C](-1) : ?
@C:/Path/To/Source/Files/sourceA.py(123) : functionA
@C:/Path/To/Source/Files/sourceB.py(456) : functionB
@C:/Path/To/Source/Files/sourceC.py(789) : functionC
--- CALLSTACK ---
[2024.04.05-16.14.05:549][123]Logger: Message with timestamp 4
[2024.04.05-16.14.05:550][123]Logger: Message with timestamp 5[/code]

I think I've now managed to get this working, with the following parser mapping:

[code][%d{yyyy.MM.dd}-%d{%H.mm.ss:fff}][%t]%c: %m%n
[%d{yyyy.MM.dd}-%d{%H.mm.ss:fff}][%t]%c: %m--- CALLSTACK ---%n
%c: %m%n
%m, %d{dd/MM/yy %H:mm:ss}%n[/code]

The additional --- CALLSTACK --- line seems to match these errors. Can you think of a reason why this wouldn't work and/or a better solution?

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Fri, 05 Apr 2024 14:45:19 GMT

This seems related to the configuration:
[code]%c: %m%n[/code]
Are you still using that pattern? Those call stack lines match that pattern, so it would make sense that LogViewPlus creates separate log entries for them. If this pattern was not included, I would expect LogViewPlus to append the lines to the message of the prior log entry. LogViewPlus will see a continuation of the previous log entry rather than a new log entry.

RE: LogViewPlus is failing when logs are recreated

Miserableman — Fri, 05 Apr 2024 14:05:26 GMT

Hello again, I have hit another interesting issue. It's unrelated to the issue with logfiles being recreated so I considered making another thread, but it is (probably) related to the parser mapping so I kept it here. I can make another thread if you prefer.

Sometimes, when the application that is generating logs hits an issue with the script that it's running, it outputs a callstack that looks like this:

[code][2024.04.05-12.07.39:248][514]Logger: An error has occurred!
--- CALLSTACK ---=[C](-1) : ?
@C:/Path/To/Source/Files/sourceA.py(123) : functionA
@C:/Path/To/Source/Files/sourceB.py(456) : functionB
@C:/Path/To/Source/Files/sourceC.py(789) : functionC
--- CALLSTACK ---
[2024.04.05-12.07.39:265][514]Logger: Next log output[/code]

With the parser configuration I gave further up this thread, the callstack output is listed completely separately from the lines surrounding it. These lines have no timestamp, so LogViewPlus gives them a timestamp of 00:00:00, and sorts them far away from the preceding line.

Is there any way to get these lines to sit together?

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Thu, 04 Apr 2024 16:52:29 GMT

Glad that helped and you have a working solution - thanks for letting me know.

I will look into the issues with the rule based approach. I know there was a rule fix in v3.1.6, so it may be worth checking you are on the latest version. I will try and do some testing here before the next release.

Regarding...
[code]%c: %m%n[/code]
I am actually surprised that this configuration works as it is a requirement that all log entries have a timestamp. You might find that some features in LogViewPlus (such as log file merging) work incorrectly with these log entries. We do not test for this scenario.

RE: LogViewPlus is failing when logs are recreated

Miserableman — Thu, 04 Apr 2024 16:40:25 GMT

Firstly, this:
[quote]When you filter for 'log file open', do you see a matching log entry?[/quote]
Yes I do. A filter for "Log file open," shows just the first properly-formatted line, with the detail view showing a truncated view of the several-hundred lines that precede it. However, the rule with description "For all log entries matched in filter "'Log file open,'" clear all log entries from the log file" doesn't seem to apply.

This no longer matters for me because, as you suspected, your multi-pattern configuration (almost) works. When applied, it now shows the first "Log file open" line, and then the main log entries with proper formatting, skipping the several-hundred entries that are missing a timestamp. However, I adapted your multi-line configuration to this:

[code][%d{yyyy.MM.dd}-%d{%H.mm.ss:fff}][%t]%c: %m%n
%c: %m%n
%m, %d{dd/MM/yy %H:mm:ss}%n[/code]

LogViewPlus now seems to full understand our logfile format - I get one "Log file open" entry with the correct time, several hundred entries with today's date but no timestamp (not that important), and then the 'proper' logs following that. Success!

Furthermore:

The "Clear all log entries when the log file is rolled or recreated." option now works entirely as expected.
The rule-based approach to clear log entries also now works, but it takes a reload of the logfile first.

I will use the first option, in settings, as it seems to match our use case the best.

Thankyou once again!

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Thu, 04 Apr 2024 15:18:42 GMT

That is all expected behaviour. LogViewPlus works hard to never hide a log entry - even if that log entry cannot be parsed. In this case, the header is considered part of the original log entry belonging to the first parsed log entry in the file. This way, header information is available when you search for it even though it is not visible in the grid.

> if "Log file open," is found, but it didn't work

That is a little odd. The log line cannot be accurately parsed, so this may be causing some problems (especially if there is a delay in writing the first log entry). Still, I would expect the text to be found and the action to work. When you filter for 'log file open', do you see a matching log entry? It is the matching log entry which triggers the action.

Fortunately, there is a timestamp in your header. I would suggest using a multi-pattern configuration like:

[code][%d{yyyy.MM.dd-HH.mm.ss:fff}][%t]%c: %m%n
%m, %d{dd/MM/yy %H:mm:ss}%n[/code]
Your log should then parse the header out separately. Something like:

I suspect this will resolve the issue with both of the 'clear' operations.

Hope that helps,

Toby

RE: LogViewPlus is failing when logs are recreated

Miserableman — Thu, 04 Apr 2024 14:58:23 GMT

The invalid log entry theory is promising. Our application does indeed write out several hundred lines of logfile entries in a different format, prior to its first line that conforms to the parser mapping.

First, there is a line in the form [code]Log file open, 04/04/24 15:25:27[/code]
Then, hundreds of lines in the form [code]Logger: Example log message[/code]
Then, the rest of the log entries in the main format, an example of which I give here:
[code][2024.04.04-14.25.28:584][123]Logger: Example log message[/code]

LogViewPlus only shows the log entries that conform to the main format. If I select the first of these, however, in the pane that shows the full log message it is displaying all log entries from the start of the file, as if it's interpreting all of them as one single entry (this view gets truncated as there are lots of them).

I followed the instructions on the link you gave to clear logs automatically if "Log file open," is found, but it didn't work, unfortunately.

I also tried to add "Logger: message" as a separate parser mapping that it can fall back on but it seems that some kind of timestamp is mandatory, so the wizard didn't let me proceed. I was able to use the wizard to make a separate parser configuration with a timestamp, and then remove the timestamp field manually, but this didn't work either.

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Thu, 04 Apr 2024 12:53:48 GMT

It might be that your application is writing an invalid log entry and this is confusing LogViewPlus. For example, a header at the top of the log file? LogViewPlus can correct for this if matching log entries are then found, but there could be some kind of race condition between the header being written, the log format being detected and then additional log entries written. The speed of the writes / read operations may explain why you only notice the problem with the "Clear all log entries" flag enabled.

The file format *.log is also very generic. I suspect it is shared between your two parser configurations. Is there any way to narrow down the file name pattern? Possibly by using a regex?

I would like to get to the bottom of this one, but a work-around might be to use a rule to clear the log. This has the advantage of being specific to your log parser (the application setting would apply to all logs opened by LogViewPlus).

RE: LogViewPlus is failing when logs are recreated

Miserableman — Thu, 04 Apr 2024 12:41:04 GMT

Thanks for the speedy reply. I already had a custom parser mapping that I used the wizard to create, it seems to work pretty well on all the various logfiles that the app can generate (it can write to multiple .log files, potentially, of which client.log is one).

However, the breakage was occurring with this parser mapping already in place.

Based on your response, I tried changing the file pattern of the default Basic Parser from .log to .txt, in the hope that it wouldn't fight with my custom mapping that also uses .log. This didn't help, however, so I've changed it back.

I have noticed the "Reload File" option that is shown when right-clicking on the client.log file in the Files view. Selecting this option successfully restores the view of the output after the application is run a second time. This is better than having to restart LogViewPlus, but it's still not ideal. Any further theories?

RE: LogViewPlus is failing when logs are recreated

LogViewPlus Support — Thu, 04 Apr 2024 11:29:23 GMT

Hi,

Thanks for reaching out. "Clear all log entries ..." is the correct application setting. I think you are having a problem with your parser configuration rather than the new setting.

The dialog you are seeing is LogViewPlus's attempt to understand a new log format. This should not be needed if the format is already known. I see the file pattern is "*.log". This pattern is usually reserved for the Basic Parser which requires no configuration. Can you check your parser configurations and confirm that the configured patterns are setup correctly? I would expect 'client.log' to point to a known pattern. It may help to create the initial setting based on static log file.

If you want to send me the log file name and a sample log entry, I may be able to help with creating a valid configuration pattern.

Hope that helps,

Toby