Logging no longer works?

[mawashii]

System info

Operating System: Ubuntu 20.04.6 LTS / Debian GNU/Linux 12 (bookworm)
Shaka Packager Version: packager version 3e71302-debug (current HEAD)

Issue and steps to reproduce the problem

Packager Command: ./packager --dump_stream_info input=testing.mp4 --v=9

I have tried all variations of the --v flag, I've also tried vmodule (deprecated), I've tried combinations with --minloglevel and --stderrthreshold which are new flags since the build system change but nothing can convince the tool to print more.

I've tried both a Release and a Debug build off HEAD. I can see that the Debug build does all the DCHECK stuff because if I use it to encrypt/decrypt something it takes longer than the Release build. But none of them print anything remotely verbose let alone the "normal" non-verbose output from the previous log system like Demuxer::Run() message as seen below.

When I run ./build/packager/packager_test however I do get the verbose logging output I'm expecting even if the formatting looks a bit off.

Running main() from ../packager/third_party/googletest/source/googletest/src/gtest_main.cc
[==========] Running 13 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 13 tests from PackagerTest
[ RUN      ] PackagerTest.Version
[       OK ] PackagerTest.Version (0 ms)
[ RUN      ] PackagerTest.Success
WARNING: All log messages before absl::InitializeLog() is called are written to STDERR
I0000 00:00:1703714503.296654 3166804 status.cc:76] 1 (UNKNOWN): Job uninitialized
I0000 00:00:1703714503.296883 3166806 demuxer.cc:94] Demuxer::Run() on file 'packager/media/test/data/bear-640x360.mp4'.
I0000 00:00:1703714503.296935 3166806 demuxer.cc:160] Initialize Demuxer for file 'packager/media/test/data/bear-640x360.mp4'.
I0000 00:00:1703714503.307072 3166807 local_file.cc:48] Read 65536 return 65536 error 0
I0000 00:00:1703714503.307172 3166807 local_file.cc:48] Read 65536 return 65536 error 0
I0000 00:00:1703714503.307184 3166806 mp4_media_parser.cc:928] Changing state: 1
I0000 00:00:1703714503.307219 3166807 local_file.cc:48] Read 65536 return 65536 error 0
I0000 00:00:1703714503.307254 3166806 local_file.cc:48] Read 16 return 16 error 0
I0000 00:00:1703714503.307264 3166807 local_file.cc:48] Read 65536 return 65536 error 0
I0000 00:00:1703714503.307278 3166806 local_file.cc:48] Read 16 return 16 error 0
I0000 00:00:1703714503.307299 3166806 offset_byte_queue.cc:29] Buffer pushed. head=0 tail=65536

I do not see what it does different if at all to explain why it has verbose logging but my invocation from CLI does not.

I've tried the build I created on 2 different systems (Debian+Ubuntu) and in different shells (zsh+bash) just in case it makes a difference for some reason, but it does not appear that way. I do not know what else I can try to rule out an error on my end. The previous shaka build (v2.6.1) works fine with the same arguments.

What is the expected result?

[1227/135446:INFO:demuxer.cc(89)] Demuxer::Run() on file 'testing.mp4'.
[1227/135446:INFO:demuxer.cc(155)] Initialize Demuxer for file 'testing.mp4'.
[1227/135446:VERBOSE2:local_file.cc(118)] Read 65536 return 65536 error 0
[1227/135446:VERBOSE2:local_file.cc(118)] Read 16 return 16 error 0
[1227/135446:VERBOSE2:local_file.cc(118)] Read 16 return 16 error 0
[1227/135446:VERBOSE2:local_file.cc(118)] Read 16 return 16 error 0
[1227/135446:VERBOSE2:mp4_media_parser.cc(371)] Skipping top-level box: ftyp
[1227/135446:VERBOSE2:mp4_media_parser.cc(371)] Skipping top-level box: free
[1227/135446:VERBOSE2:box_reader.cc(82)] Child mvhd size 0x6c
[1227/135446:VERBOSE2:box_reader.cc(82)] Child pssh size 0x28c
[1227/135446:VERBOSE2:box_reader.cc(82)] Child pssh size 0x79
[...]

File "testing.mp4":
Found 1 stream(s).
Stream [0] type: Video
 codec_string: hev1.2.4.L150.90
 time_scale: 24
 duration: 183847 (7660.3 seconds)
 is_encrypted: true
 codec: H265
 width: 3840
 height: 1920
 pixel_aspect_ratio: 1:1
 trick_play_factor: 0
 nalu_length_size: 4

[1227/135446:VERBOSE2:mp4_media_parser.cc(371)] Skipping top-level box: sidx
[1227/135446:VERBOSE2:box_reader.cc(82)] Child mfhd size 0x10
[1227/135446:VERBOSE2:box_reader.cc(82)] Child traf size 0x505
[1227/135446:VERBOSE2:box_reader.cc(82)] Child tfhd size 0x1c
[1227/135446:VERBOSE2:box_reader.cc(82)] Child tfdt size 0x14
[1227/135446:VERBOSE2:box_reader.cc(82)] Child trun size 0x198
[1227/135446:VERBOSE2:box_reader.cc(82)] Child saiz size 0x11
[1227/135446:VERBOSE2:box_reader.cc(82)] Child saio size 0x14
[1227/135446:VERBOSE2:box_reader.cc(82)] Child senc size 0x310
Packaging completed successfully.
[1227/135446:VERBOSE2:local_file.cc(118)] Read 65536 return 65536 error 0

What happens instead?

File "testing.mp4":
Found 1 stream(s).
Stream [0] type: Video
 codec_string: hev1.2.4.L150.90
 time_scale: 24
 duration: 183847 (7660.3 seconds)
 is_encrypted: true
 codec: H265
 width: 3840
 height: 1920
 pixel_aspect_ratio: 1:1
 trick_play_factor: 0
 nalu_length_size: 4

Packaging completed successfully.

[modernletter]

The reason of unit test logging behaviour is the fact, that (current) abseil doesn't fully support negative loglevels. You can set negative loglevel for filtering, but loglevel of all log entries is normalised to 0 (INFO). This makes shaka VLOG macro quite useless - all logging messages behave as logged by LOG(INFO) and displayed (as IXXX). It's quite annoying for verbose modules, like MPEG-TS parser

I'm not sure why there is no log verbose at all in application - maybe loglevel is not INFO.

Note: verbose logging support and VLOG macro was recently added into abseil - abseil/abseil-cpp@7b6c17e and later fixes.

[petzeb]

I noticed that the --v cli option no longer exist as well testing on latest main.
Probably dropped as part of this PR: #1337
@joeyparrish Is there some new flag to control log verbosity that should be used instead (I couldn't find any in the help text)?

[joeyparrish]

VLOG() macros were added to absl as noted by @modernletter, and a newer version was adopted by us in #1337. This should result in all logging flags being provided by absl directly.

I see this issue is from December 27, so let me see if I can reproduce it or today's comment from @petzeb with the latest source from main.

[joeyparrish]

Confirmed:

$ ./build/packager/packager --v=5
ERROR: Unknown command line flag 'v'. Did you mean: iv ?
$ ./build/packager/packager --minloglevel=4
ERROR: Unknown command line flag 'minloglevel'

I'll dig into this.

[joeyparrish]

The absl::log_flags target was being stripped by the linker. PR coming soon.

[petzeb]

@joeyparrish awesome! thanks for the quick fix!

[joeyparrish]

Happy to help. Thanks for alerting us to the problem!

[inkychris]

In response to the original issue, and why the application behaves differently to the test app, The --stderrthreshold option is limitting the console output. Setting this to 0 allows the logs to be controlled as expected with --v. This is explained in abseil/abseil-cpp#1537. Maybe the app should set up a default stdout log sink?

[joeyparrish]

I think we should default stderrthreshold to 0. Since we don't have another sink by default, I would expect minloglevel and v to "just work" without stderrthreshold.

[joeyparrish]

I put up PR #1350 for this.