Osmocom Libraries » libosmocore

Tested gerrit # 1580 using following logging configuration:

log stderr
logging color 1
logging timestamp 0
logging level all everything

When running without debug mask DEBUGP messages are not printed.
When running with debug mask (.. -d DOML) than corresponding DEBUGP are printed.

It's the same if I use "logging level oml everything" instead.

Have I understood it correctly that with this configuration DEBUGP should be printed even without specifying the mask in command-line?

Fix is available in gerrit 1582.

I think it would be best to deprecate the 'logging level all everything' and fix it by adding a different command, to avoid situations where users have this in their conf file, not being aware of it, and suddenly the log explodes because the meaning of it changed (even though it changed to actually doing what it says). I happen to have it in my config files in my test setups, no idea why, and would need to adjust that "out of the blue". So if we really need this functionality, let's make it a different command and print a "% this command no longer exists" for the old one?

see https://gerrit.osmocom.org/#/c/1582/ for current patches related to this.

msuraev wrote:

Have I understood it correctly that with this configuration DEBUGP should be printed even without specifying the mask in command-line?

the log mask on the command line is nothing but a legacy way of configuring the stderr logging via vty/config file. I wasn't even aware somebody still uses it and I would remove the command line options altogether. However, some people seem to prefer that way.

So whether you specify something as command line log mask or as "log stderr" in the config file should never make any difference.

neels wrote:

I think it would be best to deprecate the 'logging level all everything' and fix it by adding a different command, to avoid situations where users have this in their conf file, not being aware of it, and suddenly the log explodes because the meaning of it changed (even though it changed to actually doing what it says). I happen to have it in my config files in my test setups, no idea why, and would need to adjust that "out of the blue". So if we really need this functionality, let's make it a different command and print a "% this command no longer exists" for the old one?

Well, it has its advantages and disadvantages. We shouldn't have to apologize to users if we fix bugs, even if the bugs have existed for years. Do you have a good proposal as to what this new command should be called?

BTW, a current workaround to get everything logged is simply

logging level all debug

to summarize, I can do following:
- make 'everything' alias to debug and print deprecation warning if it's used in the config
- make 'all' act as globing which sets default log level for any category
- double-check that any subsequent per-category log level overrides it
- double-check that it works regardless of cli parameters

Am I missing anything?

Gerrit 3148 has been sent for review. If you think that deprecating "everything" is the right way than +2 it, otherwise I'll try to fix gerrit 1582 to make "everything" alias to "debug".

Gerrit 3148 has been merged.

It's been reported on ML that "logging level all everything" somehow makes it possible to skip logging for certain subsystems while "logging level all debug" doesn't. Need more info to reproduce this properly.

My analysis posted to the ML: (simplified)

Using log facilities MNCC and DCC, connecting
and disconnecting osmo-sip-connector will log messages at
NOTICE on both those facilities.

I'm bringing up a fresh nitb with empty config file and
database. I will use some logging config commands and then
connect and disconnect the MNCC socket.

OpenBSC> enable
OpenBSC# logging enable
OpenBSC# logging level mncc fatal
OpenBSC# logging level cc fatal
OpenBSC# logging level all debug
OpenBSC# logging filter all 1
OpenBSC# <0006> mncc_sock.c:271 MNCC Socket has connection
with external call control application
<0006> mncc_sock.c:84 MNCC Socket has LOST connection
<0001> gsm_04_08.c:469 Clearing all currently active
transactions!!!

Here the specific per-subsystem levels were not
respected, rather they were over-ridden by the logging all
directive.

Change logging all to "everything":

OpenBSC# logging level all everything

Change Logging MNCC to info:

OpenBSC# logging level mncc info

OpenBSC# <0006> mncc_sock.c:271 MNCC Socket has connection
with external call control application
<0006> mncc_sock.c:84 MNCC Socket has LOST connection

Now the subsystem levels were respected, as CC was level FATAL
and MNCC was at level INFO

This is my desired behaviour.

OpenBSC# logging level cc info
OpenBSC# logging level mncc fatal
OpenBSC# <0001> gsm_04_08.c:469 Clearing all currently
active transactions!!!

Reversed. Levels still respected, good.

OpenBSC# logging level all debug
OpenBSC# <0006> mncc_sock.c:271 MNCC Socket has connection
with external call control application
<0006> mncc_sock.c:84 MNCC Socket has LOST connection
<0001> gsm_04_08.c:469 Clearing all currently active
transactions!!!

Again, Now everything is logging at DEBUG

Just to really really drive the point home:

OpenBSC# logging level all notice
OpenBSC# logging level cc fatal
OpenBSC# logging level mncc fatal
OpenBSC# <0006> mncc_sock.c:271 MNCC Socket has connection
with external call control application
<0006> mncc_sock.c:84 MNCC Socket has LOST connection
<0001> gsm_04_08.c:469 Clearing all currently active
transactions!!!

It is impossible to silence a subsystem when logging level
all [anything other than everything] has been issued.

I am only able to achieve this with logging
level all everything - This is the key to respecting the
per-subsystem levels.

It is impossible to have:

logging level X on Facility 1
and
logging level Y on facility 2
unless

logging level all everything has been issued.

(otherwise one gets level Z on all facilities after logging level all Z

msuraev wrote:

Need more info to reproduce this properly.

Do you somehow observe different behaviour to what I describe?

With current libosmocore,
do you know a sequence of logging vty commands that will display SMPP and only SMPP at level DEBUG?

I have sent https://gerrit.osmocom.org/#/c/4313/ for review,
This is the patch I am using currently to get the behaviour I desire.

Frankly, I think having "special" categories ("all" vs "cc", "smpp" etc) and levels ("everything" vs "notice", "error" etc) is a counter-intuitive hack. Which is undocumented as well. We should use separate, explicit commands for things like setting default log level for categories. For example "logging default-level notice". I'll follow-up with patches implementing it once I have time - don't hesitate to submit your version though. Or propose entirely different ideas.

I think the feature of seeing facility X at level debug while setting facility Y at level fatal is a good feature to have.

For the immediate, if it does not step on anybody's toes, I would appreciate gerrit #4313 as it allows me to see the logging i need at any given time from the VTY.

laforge wrote:

I've never
used it in my close to 10 years of OpenBSC work,

Well I can't argue with that.

But..
If you connect to a vty, enable logging and issue
show logging vty, the first line you will see is

Global Loglevel: EVERYTHING

and I always have
various different log levels for different sub-systems. You don't need
"everyhthing", nor do you need "all" for that.

I think in fact that you do "need" everything, as it is the default state.
I had a habit of issue a log level all debug command and you are saying you never use it.
So I see now where the confusion comes from.
I think what happens is that once you issue log level all debug, you cannot get BACK to the initial state where individual facility log levels are respected (let me call it "EVERYTHING") without being all to issue logging level all everything

Running latest master today, debugging some stuff I added a "log level all debug" to my config file to get all possible output into stderr:

log stderr
  logging color 1
  logging print extended-timestamp 1
  logging print category 1
  logging level all debug

After a while of not understanding why I was getting some messages but not all of them, I entered with telnet and checked "show running-config":

log stderr
  logging filter all 1
  logging color 1
  logging print category 1
  logging print extended-timestamp 1
  logging level all debug
  logging level rsl info
  logging level oml info
  logging level rll notice
  logging level rr notice
  logging level meas notice
  logging level pag info
  logging level l1c info
  logging level l1p info
  logging level dsp debug
  logging level pcu notice
  logging level ho notice
  logging level trx notice
  logging level loop notice
  logging level abis notice
  logging level rtp notice
  logging level sum notice
  logging level lglobal notice
  logging level llapd notice
  logging level linp notice
  logging level lmux notice
  logging level lmi notice
  logging level lmib notice
  logging level lsms notice
  logging level lctrl notice
  logging level lgtp notice
  logging level lstats notice
  logging level lgsup notice
  logging level loap notice
  logging level lss7 notice
  logging level lsccp notice
  logging level lsua notice
  logging level lm3ua notice
  logging level lmgcp notice

So, it seems my all debug is overridden automatically in lots of categories with "notice" level after my "all debug" line. Then I get into an scenario in which the following is printed:

    LOGP(DPCU, LOGL_INFO, "Sending RACH indication: qta=%d, ra=%d, " 
        "fn=%d\n", qta, ra, fn);

But not this one (immediately before in the code calling the previous message):

        LOGP(DL1P, LOGL_INFO, "RACH for packet access (toa=%d, ra=%d)\n",
            rach_ind->acc_delay, rach_ind->ra);

Which is really strange, because according to log levels it should be the opposite, like the first one not being printed (pcu cfg is NOTICE) and the second one being printed (l1p cfg is INFO).

If instead of using "logging level all debug", I take the output from the show-running-config and I add them to my cfg file modifying the lines to have them all with "debug" level, then everything works fine (and both messages are printed).

See patches submitted in gerrit (you can find links in #3409).

A related set of patches is up on gerrit, after the discussion on openbsc@ has seemingly concluded.
http://lists.osmocom.org/pipermail/openbsc/2018-September/012178.html
https://gerrit.osmocom.org/10883
https://gerrit.osmocom.org/10884
https://gerrit.osmocom.org/10885
https://gerrit.osmocom.org/10886
https://gerrit.osmocom.org/10887
https://gerrit.osmocom.org/10888
https://gerrit.osmocom.org/10889
https://gerrit.osmocom.org/10890

neels, what's missing here?

To summarize, 'everything' was either a misnomer or an implementation slip up. Either way it always meant "switch off a global logging clamp" that was before set by 'logging level all LEVEL'.
Now we have 'logging level force-all LEVEL' and 'no logging level force-all' as less confusing names for the same functionality.
The old 'logging level all LEVEL' and 'logging level all everything' are deprecated aliases for the same, i.e. they now again work exactly like they always did.

All patches merged.