Logging To Preserve Color Output

[jlpoolen]

Since upgrading, I have found at least one camera, if not two, have erratic saving, if at all. I'm using 4 Reolink cameras This behavior compares with performance I had with Moonfire-nvr software in the version as of June, 2020. While the problem may be with the cameras, or my network, or my Raspberry Pi4, I feel the first thing to do is have a protocol for creating, preserving and staging log files. Al the while, I simultaneously am using Reolink's Windows software to display real time and capture events for all four cameras and its performance does not seem much different. Sometimes I have to reset a camera. But the disparity between a recent version of Moonfire-nvr and June 2020 vs. Reolink's is noteworthy and merits an investigation which I'll undertake. In the meantime, I thought I would post and preserve a protocol I propose to use so that files with the ANSI colors are preserved.

The log files are in color format and I think it is important to retain the ANSI codes coloring the output given that the files can be so large and classes of errors more identifiable when colorized. So, what I have started is a procedure to run moonfire-nvr as following:

In console No. 1:

     # Change to special user
     sudo moonfire-nvr

     # Since I connect remotely to my Raspberry Pi4, 
     # prevent broken connections from interrupting the process by using "screen"
     screen -t MoonfireShell

     # create a unique environment value for log differentiation
     export START_TIME=`date +"%Y-%b-%d_%H_%M"`

     # use "script" to preserve the ANSI colors of the output
     script --flush /tmp/moonfire-nvr_${START_TIME}.log  ./moonfire-nvr run

     # [To leave screen (and script): Ctrl-d a]

In console No. 2:

    #open a 2nd console and tail -f the log file
    ls /tmp
    tail -f /tmp/moonfire[tab]

TODO: 1) log rotation without destruction of events, 2) document ansi2html to other display method to share logs while preserving the colorization.

[scottlamb]

It took me a second to figure out what you meant by ANSI colors because I didn't write any code for colorizing logs and don't see it for myself. I'm a little groggy and wondered if I woke up in bizarro-world. But Moonfire calls into ffmpeg for its RTSP handling, and ffmpeg logs. There's a hook for overriding the log callback (av_log_set_callback) but looks like I'm not calling it now. That means ffmpeg's default behavior applies for that portion of the logs. It colorizes logs if the output is a tty. As for why I don't see it, when I do moonfire-nvr run, I either run it within Docker or systemd. Either way, it's not a tty, and there's no color.

As an aside, this makes me realize I probably should be setting the log callback so ffmpeg's logs and Moonfire's are handled consistently.

One bad thing with the procedure you're describing here is that it doesn't happen automatically on startup, so after a power failure you have a larger-than-necessary gap in your recording. I think almost anything that supervises processes will do so without creating a tty, so no color. But it should be possible to colorize after the fact. Hmm, this serverfault question points out some canned utilities for those. We could teach it about the log format Moonfire NVR uses (which is based on Google's logging format if they don't already know about it, or change Moonfire NVR's format to match one they already know about.

[scottlamb]

A sufficiently recent lnav (I tried the one from git; the one packaged in Debian 10 is too old works fine also) will colorize logs after the fact with the attached format file. How does this look?

$ lnav -i moonfire_log.json
$ lnav nvr-logs

moonfire_log.json.txt

lnav also apparently allows nice things like querying the logs with SQLite3.

I also realized I'm not quite matching glog's timestamp format. glog has a : separator for the time that I left out by mistake, and (as of recently glog also includes the date.

I've also been meaning to add in a guide on how to read the logfiles. That'd be a good place to mention lnav.

[jlpoolen]

I think your comment that you do not colorize your output and that the ffmpeg errors are passed through is important. I think what must be coming through to me are ffmpeg errors... lots of rtsp-type errors. I'm thinking Perl may provide what I feel is needed for managing logs to address what errors are causing my instance to have two camera failures. It may be that the problems are emanating from ffmpeg, in which case preserving their color scheme, rather than trying to after-the-fact colorize, could be helpful should I have to engage assistance from the developers of ffmpeg. It would be a good thing to present to them their logs as they have colorized them. Later today, I'll post a sample in converted HTML format to give you a flavor of what I am capturing. It is important to isolate the ffmpeg from your code's output so triaging where the problem is arising can be quickly made. Also, a bit off topic, I have my Xen server running now, so I can devote a VM to exploring and testing different versions. It is time that I need - you've seen me rue about this before.

…

On Mon, Mar 8, 2021, 10:41 PM Scott Lamb ***@***.***> wrote: A sufficiently recent lnav <https://lnav.org/> (I tried the one from git; the one packaged in Debian 10 is too old) will colorize logs after the fact with the attached format file. How does this look? $ lnav -i moonfire_log.json $ lnav nvr-logs [image: image] <https://user-images.githubusercontent.com/8949524/110427774-17877800-805d-11eb-8430-bd283e0fcda9.png> moonfire_log.json.txt <https://github.com/scottlamb/moonfire-nvr/files/6106309/moonfire_log.json.txt> lnav also apparently allows nice things like querying the logs with SQLite3. I also realized I'm not quite matching glog's timestamp format. glog has a : separator for the time that I left out by mistake, and (as of recently <google/glog#516> glog also includes the date. I've also been meaning to add in a guide on how to read the logfiles. That'd be a good place to mention lnav. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#112 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABXP4KUNGOMOQAUCBFBWMDTCW7H5ANCNFSM4Y2CK5IA> .

[scottlamb]

I agree what you're seeing are ffmpeg errors.

But to be honest, I'm not optimistic about ffmpeg developers jumping to fix RTSP bug reports with Moonfire NVR logs attached, and I don't think ANSI color output will help that. They haven't even looked at the ones I submitted when I followed their bug reporting instructions that involve reproducing with the ffmpeg commandline tool. Note also that their instructions cause ANSI color codes to be dropped. They say to either copy/paste from the console or use the -report commandline argument. Neither way preserves ANSI color codes. I also find them these escape sequences to be a pain when using tools like less, grep, etc. so I prefer working without them. When I look at a file that includes them, often the first thing I do is to look up a command to strip them out.

That's not to say RTSP problems are hopeless. I definitely want Moonfire NVR to record reliably and welcome bug reports in Moonfire NVR's tracker even if the offending line of code is in ffmpeg. There are several avenues we can take to get them fixed:

1. any problem Moonfire NVR encounters with ffmpeg's rtsp layer should be reproducible with the ffmpeg tool itself, following their bug report guidelines. Maybe someone can convince them to look at one of these bug reports...
2. I'm more optimistic about them applying a patch that we prepare to fix the problem.
3. even if they don't, we can alter Moonfire NVR's build to prepare a patched version of ffmpeg ourselves.
4. lastly, I still plan to eventually reimplement RTSP handling in pure Rust code. (pure Rust RTSP client library #37) It's not top of my list, but this strikes me as an achievable goal. We'd still need ffmpeg for H.264 decoding when using on-NVR analytics (on-NVR video analytics #30), but fortunately that part of the library gets a lot more attention.

[jlpoolen]

I've uploaded a 14 MB log file converted to HTML preserving the coloration. It represents March 4th - 9th for a 4 camera operation. I'm sharing this just so you have a quick overview. I would like to first study the log myself and then open another issue for the problem I discern from the log. I'd like to keep this issue relating to the topic of preserving and formatting logs and not have it dive into the underlying problem I am facing.

https://drive.google.com/file/d/1UrQgLzgetLfCT8681uOOO9u1a_gGGKjU/view?usp=sharing

Here is a sample of how the preserved colorized log appears in Firefox:

Here's what the current interface for moonfire-nvr shows (2 cameras completely down). Keep in mind Reolink's monitoring software for the four cameras shows them as active and that software is actively saving events for all four cameras.

[jlpoolen]

In response to your Comment ,
what I am experiencing with the revised installation vs. the older suggests something in the upgrade brought in something that does not play nicely. I'll open another issue to focus on the problem I face. I want to try a few things.

For posterity, I took my log file created by "script" and pushed it through ansi2html:

ares /home/jlpoole # cat moonfire-nvr_Mar4-9.log |ansi2html >moonfire.html
ares /home/jlpoole # ls -la
total 24792
...
-rw-r--r-- 1 jlpoole jlpoole 10329920 Mar 9 08:19 moonfire-nvr_Mar4-9.log
-rw-r--r-- 1 root root 14821039 Mar 9 08:20 moonfire.html
...
ares /home/jlpoole #

[scottlamb]

Thank you for bringing this up and sharing the example.

I just played with that log, and I'm afraid I don't like this format much. Web browers are pretty slow to scroll on a page that large and their built-in find doesn't support jumping to a time, searching by regexp, etc. I find it more pleasant to work with logs via either general-purpose CLI tools (less, rg, etc.) or a more log-specific CLI/TUI tool like lnav.

I did a quick look for how to convert back to plain text. lynx -dump doesn't work well because it introduces new line breaks that make it hard to grep through. (You can crank up the line width with -width but there's still a limit.) I'm sure I could find something (looks like a script that just strips the HTML tags and the character data within <script> would suffice) but prefer just text for logs on the issue tracker. Folks can pipe that into something like lnav if they want to see colors.

Right now the ANSI colors give you some information about log levels that isn't present in the text (thus the lnav approach is imperfect) but I can install a log callback that translate's ffmpeg's log level to moonfire's log format. This will also give timestamps and more consistency that I think will make the logs more understandable.

[scottlamb]

I also wouldn't mind too much logs with ANSI color codes in them (without converting to HTML). They're a bit easier than the HTML to strip out: perl -pe 's/\e\[?.*?[\@-~]//g' should do, according to a stackexchange answer.

If you want to make logs with those now, the environment variable AV_LOG_FORCE_COLOR will turn that on even when run from a process supervisor (systemd, Docker, etc). You don't have to run from a terminal via screen + script. And it wouldn't be hard for me to add similar ANSI color code output for Moonfire NVR's own log format (with a similar auto/on/off from an environment variable) if there's some reason folks don't like lnav-style tools.

[jlpoolen]

It's kinda looking like there should be a raw ANSI output, then if it desired to share via a Web page, an HTML version can be made, or if a review of the log in a console or Linux environment can strip the escape codes.

Having a process defined to achieve these goals is what I am hoping for. You reference to AV_LOG_FORCE_COLOR really would remove a lot of the complexity. A user should be able to decide what he wants in terms of log output and then easily share it via different methods. I'll try out your AV_LOG_FORCE_COLOR and see if it stands up to redirects in the console. This all started when I found redirecting STDERR to a log file caused the colors to be omitted and I was left with a log file with no color queues.

[scottlamb]

The logs should be quite a bit friendlier now. The docs on logs have been extended quite a bit and mention a new MOONFIRE_COLOR environment variable, which obsoletes AV_LOG_FORCE_COLOR. I also added an issue template for bug reporting.