log level everything

Message ID c5a4968d-5e80-c4e8-f7ee-4bab3df77dfd@rhizomatica.org
State New
Headers show
Series
  • log level everything
Related show

Commit Message

Keith Sept. 10, 2017, 9:53 a.m.
Hi Max!

Since  https://gerrit.osmocom.org/#/c/3148/

I am no longer able to individually control log levels in
the vty.

I used to use logging level all everything, then this
allowed me to do such as

logging level smpp fatal (get rid of annoying bind check
every 30 secs)

logging level [category i'm interested in] debug

Now, all I seem to be able to do is turn all categories to a
level with

logging level all debug or logging level all notice.

individual category directives such as logging level pag
fatal make no difference.

What am I missing?

Thanks!

BTW, I get the behaviour I need back by moving your check
below the check for "all"::

+
+
        if (category < 0) {
                vty_out(vty, "Invalid category `%s'%s",
argv[0], VTY_NEWLINE);
                return CMD_WARNING;

Comments

Max Sept. 11, 2017, 12:47 p.m. | #1
Could you please share your complete logging configuration? It's rather hard to guess
how it should behave otherwise.

On 10.09.2017 11:53, Keith wrote:
> Hi Max!
>
> Since  https://gerrit.osmocom.org/#/c/3148/
>
> I am no longer able to individually control log levels in
> the vty.
>
> I used to use logging level all everything, then this
> allowed me to do such as
>
> logging level smpp fatal (get rid of annoying bind check
> every 30 secs)

Have you tried replacing "logging level all everything" with "logging level all
debug" or some other logging level?

Also, feel free to contribute to https://osmocom.org/issues/71 your ideas on how it
should behave or how better/simpler/more convenient configuration should look like.
Keith Sept. 11, 2017, 6:27 p.m. | #2
On 11/09/2017 14:47, Max wrote:
> Could you please share your complete logging configuration? It's rather hard to guess
> how it should behave otherwise.
There's nothing to share really.
I'm describing a case that can be reproduced if you take a
default config (touch osmo-nitb.cfg and start it up)
Then open a VTY and do
logging enable.
logging filter all 1
continue to configure logging level per facility as desired...

> Have you tried replacing "logging level all everything" with "logging level all
> debug" or some other logging level?
Then I get ALL facilities logging at debug.
If I do logging level all info notice for example, then I
don't get ANY debug level logging, regardless of any
facility's explicit level.
> Also, feel free to contribute to https://osmocom.org/issues/71 your ideas on how it
> should behave or how better/simpler/more convenient configuration should look like.
Right, I will take it up there. thanks for the pointer to
the ticket.
Harald Welte Sept. 11, 2017, 6:43 p.m. | #3
Hi Keith,

On Mon, Sep 11, 2017 at 08:27:31PM +0200, Keith wrote:

> I'm describing a case that can be reproduced if you take a
> default config (touch osmo-nitb.cfg and start it up)
> Then open a VTY and do
> logging enable.
> logging filter all 1
> continue to configure logging level per facility as desired...

Odd. I did not so far observe any broken behavior, I'm using osmocom
programs of current master more or less every day or every second day.

> > Have you tried replacing "logging level all everything" with "logging level all
> > debug" or some other logging level?
> Then I get ALL facilities logging at debug.

You should then get the specific per-subsystem levels you have configured.

> If I do logging level all info notice for example, then I
> don't get ANY debug level logging, regardless of any
> facility's explicit level.

that's correct.  You're basically saying "never log anything below notice". At that point,
it doesn't matter if any subsystem has a lower, more verbose log level.  Instead,
anything that's below notice will be dropped by the global minimum level "notice"
you've configured.
Neels Hofmeyr Sept. 11, 2017, 8:28 p.m. | #4
On Mon, Sep 11, 2017 at 08:27:31PM +0200, Keith wrote:
> > Also, feel free to contribute to https://osmocom.org/issues/71 your ideas on how it
> > should behave or how better/simpler/more convenient configuration should look like.
> Right, I will take it up there. thanks for the pointer to
> the ticket.

I've first had a simplified view of logging, and it expanded with OS#71.
I still have on my mental todo list to figure out one day what we actually want
and how to achieve that.

I also once wrote a mail with some improvement suggestions, but never followed
up on all of those. There's a lot in there...
https://lists.osmocom.org/pipermail/openbsc/2017-February/010312.html

I would welcome a comprehensive approach of defining all use cases we want to
support (like temporary reduction of everything to 'notice' level, and then
going back to the precise landscape of fine tuned logging that was in place
before that...) and then figure out how best to provide those with less
confusion and ideally without changing too much.

So if anyone would like to compile an overview, maybe write a wiki page... that
would be nice.

~N
Keith Sept. 12, 2017, 8:55 a.m. | #5
On 11/09/2017 20:43, Harald Welte wrote:

> Odd. I did not so far observe any broken behavior, 

I don't know if it is "broken" as it's never been clear what
the behaviour is expected to be.

>> Then I get ALL facilities logging at debug.
> You should then get the specific per-subsystem levels you have configured.

Well, I don't.

This may be overkill, but let me go through it step by step
to illustrate my need, experience, expected behaviour,
actual behaviour.

NOTE! I have my libosmocore patch in my original post on
this thread in place, so I can still do log level all
everything.

I'm going to use log facilities MNCC and DCC as 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.
In this example I would like to silence the CC message from
gsm_04_08.c and only see MNCC messages from mncc_sock.c
From the transcript below I hope the issue is obvious.


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.

OpenBSC# logging level all everything
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 FATAL,
MNCC was 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 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.

Is it possible that what we need to do here is to continue
to allow "everything" only for subsystem "all"?

It seems odd to me that there is confusion about this as we
should know what the code is doing, right?
For me personally to take this further the next step would
be analysis of the vty code, which I have not looked at all,
and well.. if you guys have doubts about it.. I don't have a
lot of desire to go there and unfortunately there are other
pressing issues I need to work on.
So for now, my workaround is to allow logging level all
everything, as it allows me to get on with what I need to do.

k/
Keith Sept. 12, 2017, 9:19 a.m. | #6
On 11/09/2017 22:28, Neels Hofmeyr wrote:
>
> up on all of those. There's a lot in there...
> https://lists.osmocom.org/pipermail/openbsc/2017-February/010312.html
Hi Neels!
Yes, there's a lot in there, I have to admit TL;skipped
through the middle once it started getting into a complexity
that is beyond my experience, there I trust you.. you know
what you're doing. :)

In the last section, re logging level all everything. Maybe
it should be called logging level all passthrough, or
logging level all respect or somesuch.

>
> I would welcome a comprehensive approach of defining all use cases we want to
> support (like temporary reduction of everything to 'notice' level, and then
> going back to the precise landscape of fine tuned logging that was in place
> before that...) 
What I think one needs most to avoid is having to type
 logging level subsystem level
for EVERY subsystem, although, as I mentioned at osmocon, I
have written up some expect scripts to open VTYs and do this.
If logging level all notice were to function as a filter
that respects individual subsystem levels, that would be
workable.

> So if anyone would like to compile an overview, maybe write a wiki page... that
> would be nice.
What do you think of allowing logging level all everything
for the moment?
Neels Hofmeyr Sept. 12, 2017, 11:19 p.m. | #7
On Tue, Sep 12, 2017 at 11:19:42AM +0200, Keith wrote:
> What do you think of allowing logging level all everything
> for the moment?

IIRC it was originally me that started the discussion that 'logging level all
everything' is broken and useless; maybe I oversaw something? If it really
solves a non-trivial situation for you, then maybe we should keep it?

In your example it's hard to follow because it's not obvious which log is on
which level ... we can turn on category printing but apparently we can't print
out each log line's level.

  logging print category 1

I guess best basis for discussion is a unit-test like program with three
categories logging on all levels, and different use cases of what should be
visible, showing whether/how we can reach it.

But I have my attention spread across too many cutting edges at the moment; I'd
love to jump right into it, but it wouldn't do justice to the urgency of other
tasks.

~N
Keith Sept. 13, 2017, 11:06 a.m. | #8
On 13/09/17 01:19, Neels Hofmeyr wrote:
>
> In your example it's hard to follow because it's not obvious which log is on
> which level ... 
Well I chose those to use as examples as they all log to NOTICE.

> But I have my attention spread across too many cutting edges at the moment; I'd
> love to jump right into it, but it wouldn't do justice to the urgency of other
> tasks.
I know the feeling. I am fine for the moment with what I have, in terms
of doing those other tasks I have on.

thanks
k/
Max Oct. 16, 2017, 12:26 p.m. | #9
Hi.

Pardon for reviving such an old thread - I've stumbled upon this while reviewing
https://osmocom.org/issues/71 and there seems to be no definite conclusion as to what
shall we implement and how.

On 12.09.2017 10:55, Keith wrote:
> NOTE! I have my libosmocore patch in my original post on
> this thread in place, so I can still do log level all
> everything.

Does it work the same way (modulo "everything" option) on libosmocore from master?

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

It seems like this have more to do with priorities rather than "everything" option:
shall the "logging level all XX" override the already set "logging level cc YY"? In
the existing manuals we do not document this either way which is an oversight which
shall be fixed. But before that we should agree on what's the expected behavior.

> It is impossible to silence a subsystem when logging level
> all 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 seems somewhat confusing when trying to follow interactive session. Could you
please make an example .cfg which demonstrates the issue you're facing and attach it
to https://osmocom.org/issues/71 alongside with the incorrect output?
Neels Hofmeyr Oct. 16, 2017, 1:10 p.m. | #10
On Mon, Oct 16, 2017 at 02:26:31PM +0200, Max wrote:
> Hi.
> 
> Pardon for reviving such an old thread - I've stumbled upon this while reviewing
> https://osmocom.org/issues/71 and there seems to be no definite conclusion as to what
> shall we implement and how.

It's a good thing to re-raise lost topics.  We'll probably keep raising this
one until one of us sits down and churns out all of the details of a fix
everyone agrees with...

I can't remember in detail anymore what was wrong about 'logging all
everything', but it was definitely not what I expected. I might have been
wrong, too. At this point I guess we have to:

- from all logging related mails and posts, collect use cases of what we want
  to be able to do.
- look at the code to see whether we cover those and how.
- write documentation, possibly submit patches.

I can't do this at the moment...

~N
Harald Welte Oct. 16, 2017, 1:30 p.m. | #11
My vote by now would actually be to simply remove this feature.  It seems
nobody has a common understanding of what it should do.
Max Oct. 16, 2017, 1:50 p.m. | #12
Could you please clarify which feature exactly?
If it's "logging level all everything" than it's already removed as of
ed0eda236c525377e3c25d04456cbeafcab21c2d in libosmocore
If it's "logging level all" than I can make corresponding patch but I'm pretty sure
there will be requests to somehow set "default" logging level for all the categories
not configured explicitly.

On 16.10.2017 15:30, Harald Welte wrote:
> My vote by now would actually be to simply remove this feature.  It seems
> nobody has a common understanding of what it should do.
Keith Oct. 17, 2017, 2:03 a.m. | #13
On 16/10/2017 08:30, Harald Welte wrote:
> My vote by now would actually be to simply remove this feature. 
As I said before, I am currently finding that the "feature"
is missing, so therefore removing it is not a solution. :-/
The feature being: Select log levels to display individually.
Will follow up on the ticket.

Patch

diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c
index 01480b1..fb2cab8 100644
--- a/src/vty/logging_vty.c
+++ b/src/vty/logging_vty.c
@@ -213,17 +213,18 @@  DEFUN(logging_level,
                return CMD_WARNING;
        }
 
-       if (strcmp(argv[1], "everything") == 0) { /* FIXME:
remove this check once 'everything' is phased out */
-               vty_out(vty, "%% Ignoring deprecated logging
level %s%s", argv[1], VTY_NEWLINE);
-               return CMD_SUCCESS;
-       }
-
        /* Check for special case where we want to set
global log level */
        if (!strcmp(argv[0], "all")) {
                log_set_log_level(tgt, level);
                return CMD_SUCCESS;
        }
 
+       if (strcmp(argv[1], "everything") == 0) { /* FIXME:
remove this check once 'everything' is phased out */
+               vty_out(vty, "%% Ignoring deprecated logging
level %s%s", argv[1], VTY_NEWLINE);
+               return CMD_SUCCESS;
+       }