8 thoughts on - Logging Different Verbosity Levels

• Hm, the formatting of this mail seems to have got somewhat mangled on its way through the list server, I think – I’ll edit it and try again, just so it’s easier for people to see what I did:

  —
  “There is no reason for any individual to have a computer in their home.”

  – Ken Olsen, President of Digital Equipment Corporation (DEC, later consumed by Compaq, later merged with HP)

  Please reply to the list;
  please *don’t* CC me.

  —

• Hi.

  Does no-one else know either? I thought this was a simple question, and it was just me being unable to find the appropriate documentation to explain how these logging levels work.

  Please, can anyone help?

  —
  The Magic Words are Squeamish Ossifrage.

  Please reply to the list;
  please *don’t* CC me.

  —

• So this turned out more complicated than I originally thought!

  My expectation:

  Verbosity gets logged using an “at least” check against the current system’s verbose level, which if passed subsequently gets checked against the logging channel’s verbose level. Thus only verbose messages with a level less than or equal to the system’s level AND the channel’s level would be logged to that channel. For example given a system verbose level of 3, and your setup then the following should occur:

  same => n,Verbose(0,Test message verbosity 0) ; gets logged to logtest.verbose.3, logtest.verbose.2, logtest.verbose.1, and logtest.verbose.0
  same => n,Verbose(1,Test message verbosity 1) ; gets logged to logtest.verbose.3, logtest.verbose.2, and logtest.verbose.1
  same => n,Verbose(2,Test message verbosity 2) ; gets logged to logtest.verbose.3 and logtest.verbose.2
  same => n,Verbose(3,Test message verbosity 3) ; gets logged to logtest.verbose.3
  same => n,Verbose(4,Test message verbosity 4) ; nothing logged same => n,Verbose(5,Test message verbosity 5) ; nothing logged same => n,Verbose(6,Test message verbosity 6) ; nothing logged same => n,Verbose(7,Test message verbosity 7) ; nothing logged same => n,Verbose(8,Test message verbosity 8) ; nothing logged same => n,Verbose(9,Test message verbosity 9) ; nothing logged

  Reality:

  What you saw in your output. As to why? Well it’s a bit of a mess and it’s been that way for a while it seems. To start the app_verbose application gets capped at verbose level 4. Meaning the following:

  same => n,Verbose(7,Test message verbosity 7)

  Essentially gets changed to:

  same => n,Verbose(4,Test message verbosity 7)

  Next, Asterisk sets the global verbose logging level according to the following order with each level potentially overriding if greater than the preceding:

  1) core verbose level (set in asterisk.conf)
  2) console level (set via system CLI, or asterisk CLI)
  3) channel log level (set in logger.conf, e.g. verbose(9))

  This means in asterisk.conf if you set verbose=2, and then on the CLI set it to 3, and then for any channel in logger.conf specify verbose(9) then the final level will be 9! The levels too are tracked via different variables so given the preceding example the following will be output:

  *CLI> core show settings
  … Root console verbosity: 2
  …

  Despite the actual level being 9.

  Lastly, when the logger goes to output the actual log message to a channel it does indeed first check if the channel’s verbosity level is greater than some “level” variable. But guess what? This variable is always equal to 0. Thus as long as a channel’s level is > 0 it always passes and the message is output.

  So you can see in your setup the final system level is indeed 9, and all app_verbose messages being output are forced to 4 or less. Since the system level is 9, and the channel’s verbosity level is greater than zero then all messages are output to all files.

  Hope that makes sense!

  Given all that, in my opinion there seems to be at least one or more bugs with regards to verbose logging. Please file an issue at https://issues.asterisk.org/. Feel free to copy/paste what’s here as part of the issue description.

• Wow, thank you very much for:

  a) such a comprehensive answer

  b) confirming my findings

  c) most of all, working out why and how all this stuff works (or, perhaps, doesn’t).

  I wonder that nobody has discovered this before – do people not want selective logging levels in their dialplans?

  Hm.

  Thanks again,

  Antony.

  —
  Don’t procrastinate – put it off until tomorrow.

  Please reply to the list;
  please *don’t* CC me.

  —

• If I want to log something from the dialplan, I generally send it to a custom log level, as opposed to one of the built in ones. That way, it’s not combined with a bunch of other stuff from Asterisk itself that I generally don’t want. This also allows filtering on specific custom log levels. Verbose gets used for so much that if something got logged there it would just get lost.

  —

• How are you doing this?

  Indeed – that was precisely my reasoning for wanting to use the different Verbose(N,message) levels and corresponding log files – so that I could keep specific things separate from each other.

  Antony.

  —
  There’s a good theatrical performance about puns on in the West End. It’s a play on words.

  Please reply to the list;
  please *don’t* CC me.

  —

• See the custom_levels option in the sample logger.conf[1]. You’ll need a version of Asterisk from the last ~7 months or so, I think.

  It does sound like using custom levels might be better than your use case. You can also set up custom log files to log only the log levels you want to create the different “views” you want.

  [1] https://github.com/asterisk/asterisk/blob/master/configs/samples/logger.conf.sample

  —

• Ah. I use the Debian packaged version, which for the current stable Debian release is Asterisk 16.16.1 dated Feb 2021.

  custom_levels definitely isn’t in there.

  Indeed – thanks for the suggestion – looks like a nice feature.

  Antony.

  —
  This email was created using 100% recycled electrons.

  Please reply to the list;
  please *don’t* CC me.

  —