logging filters, RFC

[Neels Hofmeyr]

Summary:
[1] some problems found in the current logging filter implementation.
[2]..[7] a long discussion on where we could take Osmocom logging.
  [2] logging "lifter" instead of a filter
  [3] setting logging levels for flagged objects
  [4] multiple log targets and multiple flagged objects
  [5] FSM instance logging
  [6] setting the log context
  [7] VTY logging commands


[1]

In the VLR development, I'm going to split the gsm_subscriber to a
bsc_subscriber and a vlr_subscriber. Hence I need to care about the logging
filter code, that e.g. drops all logging except that for a given subscriber.

At first I wanted to drop it altogether, but in fact filtering on a given
subscriber is an important feature. See https://gerrit.osmocom.org/1685

Looking further into adapting this to two types of subscriber struct being used
in the code, I found that in fact the logging filter code looks quite neglected
and degraded.

- One functional problem is that the constants for BSC_CTX_SUBSCR and
  GPRS_CTX_BVC actually have the same value: they both resolve to 1, and both
  thus access the same logging context pointer with conflicting types.
  openbsc debug.c's filter_fn appears to use both BSC_CTX_SUBSCR and
  GPRS_CTX_BVC, but GPRS_* are only set in libosmocore/src/gb/ code.  Could be
  justified by osmo-nitb and osmo-sgsn not overlapping much, but I doubt that
  it's on purpose.

- A log target's filter_data[] possibly holds a subscr_get() reference.  If a
  log target is closed, like a VTY closing, the reference count may leak,
  because there is no filter data tear down that could subscr_put() it back.

- log_set_nsvc_filter() and log_set_bvc_filter() are declared in
  openbsc/debug.h, but the only implementations I can find are *static* in
  libosmocore/src/gb/gprs_bssgp_vty.c and gprs_ns_vty.c, respectively.

- The openbsc/debug.h enum defining LOG_FILTER_* is never used, because it is
  bascially duplicated in debug.c, where the values are called FLT_* instead.

- The BSC_CTX_BTS and BSC_CTX_LCHAN are each set once by a call to
  log_set_context(), but no filter function ever reads them back out from the
  context array. So they are utterly unused.

Hence in libbsc/libmsc, the *only* logging filter practically used is the IMSI
filter.

The filter code screams for attention and more safety. I would collect the
various constants in a central place in libosmocore to avoid collisions (like
ports.h does), and would use the same constant for both...
  the filter ctx array index:  ctx[FLT_CONSTANT]
  and the bitmask:             filter_map & (1 << FLT_CONSTANT)
with a static assert to ensure that the filter category constants don't outgrow
the filter_data[], ctx[], filter_map sizes. I'd drop unused definitions, add a
tear down cb.



[2]

While talking about logging, I'm thinking back to 33c3 where we had a large
active network and might want to highlight a few subscribers in the logging...

Any comments on below bold plans to overhaul the logging semantics are welcome.
Despite the long discussion, implementation of this should not be a lot of work
really.

Nevertheless, there are pressing topics in need of attention, and this mail
doesn't mean that it will be implemented now. It's a unicorn's dream of where I
would take Osmocom logging, and it _might_ be a good time to do it now...

If you will, join me on an extensive journey through our logging:

So far the logging checking goes like this:

1. If a msg's logging category is disabled, drop the msg.
2. If a msg's logging level surpasses the currently set log level of that
   category, drop it. otherwise:
3. If filter_all is set (= "don't filter"), log the message; otherwise:
4. If no filter function is set, log the message (in libbsc/libmsc operation, a
   filter function is always set).
   If a filter function is set:
5. Ask the filter function whether to log:
   5.1 If no IMSI filter is set, drop the message. (!)
   5.2 If an IMSI filter is set and the ctx has a different subscriber, drop
       the message.
   5.3 If an IMSI filter is set and it *is* the subscriber, log the message.

The result is that in essence, we don't ever see any logging unless we say
'logging filter all 1'. And then, if filter_all is set, the IMSI filter has no
further effect. To see logging for a specific IMSI, we set 'logging filter all
0' and set the IMSI filter to the subscriber. In that situation, all logging
will cease except for those matching the selected IMSI (assuming that the
filter context is always set correctly). Any logging for this IMSI that would
be more detailed than the given category's global logging level is still
dropped, and parts of the code where the subscriber ctx is not set yet also
shows no logging. One could call it a prohibitive logging paradigm. I had a
hard time understanding the UI for it: makes sense only when reading the code.

My logging vision would be the other way around, more of a logging "lifter". In
a general logging landscape, I would like to flag certain subscribers (plural)
to stand out from this landscape with a more detailed logging level. For
example, I set all categories to level ERROR, but on top allow all MM, RSL and
RR logging on INFO level; but for subscribers 1234 and 5678 I also want to see
all DEBUG level logs across all (or specifically selected) categories.

It would look like this:

1. If there is a logging_lifter function:
   1.1 If any items are flagged for more detailed logging, ask the lifter:
   1.2 If the logging context is set to a subscriber, and this subscriber is
       flagged for more detailed logging, log the message; see also [3].
2. If a msg's logging level is within the currently set general log level of
   that category, log the message.
3. Otherwise, drop the message.

This way the general logging landscape remains freely configurable while
certain objects' logging can be made more verbose.

[3]

A problem with 1.2 is that we would always see all categories' logging in all
detail for that subscriber. We could a) set a full category mask per subscriber
for complete logging freedom; Instead I'd go for: b) define one global "raised
logging" category mask to lift flagged subscribers to, and for each subscriber
simply have a boolean flag set to true to make them log on the raised logging
levels -- but what about several logging targets? see [4].


[4]

So far so good, but there is still this clumsiness in my plan: there can be any
number of logging targets. Even if I'd like to highlight subscriber 1234 on my
VTY, I don't necessarily want stderr and other VTYs to raise logging for 1234
as well. So if we flagged raised logging in a subscriber struct, we'd basically
make it affect all logging targets in the same way.

In the current code, I can open N VTY telnets and on each of them show only
logging for a selected IMSI, because all logging flags are saved for each
logging target. But I *can't* lift more than one subscriber instance to raised
logging on *the same* log output, because for each target there is only one
IMSI; and I *can't* combine detailed logging of a given IMSI with a general
background of normal logging on the same log output, because I have to filter
all logging away before I can allow a specific IMSI ('logging filter all 0').

The easiest way to allow multiple subscribers with raised logging on the same
log target is to store the "raise-logging" flag with the subscriber instance,
but to keep the log targets separate, I would instead have in struct log_target
an llist of void* for each filter_data where we can point to N instances we'd
like to flag for raised logging. Then, if the current ctx[] matches any of
those, use the raised logging levels. (Expecting the list to remain short)

This can be filter_fn implementation specific: the filter_data can be used to
point at the first llist_head instead of just one subscriber.


[5]

There's another interesting logging topic: FSM instances. We have the
osmo_fsm_inst feature where we can set all logging emitted by an FSM instance
to a certain logging level. One "problem" with this is that the entire FSM logs
on the same level, and we can only raise or lower all of these messages as one.
The implementation is: remember a logging category and a logging level with the
FSM instance, and log all messages from the FSM on this category and level. The
state transitions and events logged from fsm.c are logged on this logging
level.

Because I wanted to specifically mark some logging as LOGL_ERROR, I've already
broken up that idea by adding the LOGPFSML() macro. It allows passing an
explicit logging level instead of using the FSM instance's. I like to think of
it like this: the FSM instance's logging level tells the fsm.c code on which
level to log state transitions and events (like Debug). The logging I write in my
FSM implementation that I want to stand out from the state transitions (read:
logging that's more than Debug) should be given more specific logging levels,
like any other code we write. We could actually make LOGPFSML() use
MAX(fsm_inst.log_level, log_level_arg) so that changing an FSM instance's log
level raises all log messaging.

One could now think, if I want raised logging for a given subscriber, I could
set its FSM instances' logging level so that it prints more logging. But, again
this implies the clumsiness like in [4]: the raised logging would be global
across all logging targets. In this case, there's no easy way to make the
feature log target specific, and neither do we need to...

FSM instance specific logging levels, while sounding very nice at first, are a
non-feature when taking multiple logging targets into account. The simpler way
to show FSM logging for a specific subscriber is to use above suggested
features: flag the subscriber for raised logging on a speicific log target and
set the raised logging level for DVLR to Debug, relying on the logging ctx to
be set correctly when the subscriber's FSMs are active [6]. No need to adjust
an FSM instance's logging level individually. So, the log level could also be
stored in the osmo_fsm definition instead of each separate osmo_fsm_inst.


[6]

Setting the log context needs to generally happen in these situations:
- message received (e.g. from the MS or HLR)
- timer callback called (e.g. state timeout, SMS queue)

Particularly for timeouts on FSM instances' states this is a bit tricky. If the
fsm.c code triggers the timeout, there isn't a general hook to set the log
context to the FSM's subscriber first. The FSM instances that have timeouts set
need to also set a specific timer_cb to update the log context and repeat the
timeout logging "Timeout of T123" that comes from fsm.c before timer_cb() is
called. (That means the timeout logging may be issued twice in some situations,
once by fsm.c and once by the FSM implementation's timer_cb after setting the
log context to make sure raised logging includes it.)

Maybe we can add a pre_timer_cb to osmo_fsm, or teach osmo_fsm to set a
specific log context whenever it logs things? Probably not that important.


[7]

In the VTY, my plan would look like this:

  logging = e:RSL,RR,n:MM,CC    ! replace all levels
  logging + n:PAG               ! set some more
  logging raised = d:MM,i:CC    ! applies to flagged logging contexts
  logging raised + d:PAG,NM
  logging raise subscriber (imsi|msisdn|...) 1234
  ...
  logging raise subscriber (imsi|msisdn|...) 1234 not

For setting the logging levels, I would like to introduce letters f, e, n, i, d
for the log levels (Fatal, Error, Notice, Info, Debug) instead of the level
numbers that are "hidden" in logging.h, plus o for Off to disable categories.

I would prefer the format:
  [l:]CAT[,[l:]CAT[,...]]
so that a level is followed by N categories to be on this level, possibly
followed by another level and another categories list. (i.e. from the current
format, swap meaning of ',' and ':', reverse the current <cat>[,<level>] order
to [<level>:]<cat> and carry the level over to following categories.)

I would also add the 'all' keyword in the logging category parsing:
  logging = n:all,i:MM,CC,PAG
which would put all levels on Notice, except MM, CC and PAG on Info.

To avoid confusion with the old 'logging categories' format, I would like to go
for '=' and '+' commands (yes, the VTY can handle these).  The old 'logging
categories' might even co-exist.

'logging = ...' and 'logging + ...' should imply 'logging enable'.

The 'logging raised *' sets the logging levels used for flagged subscribers;
they should default to d:all, i.e. everything on debug level.
'logging raise *' flags a given subscriber (or what else we want to add later).

To remove a raise flag from a subscriber, 'logging no raise *' makes sense, but
it is often useful to just recall a previous VTY command and append a keyword,
so I'd make it 'logging raise subscriber imsi 1234 not' for convenience.

The current 'logging level <CAT> <LVL>' can remain as-is; I would add a
'logging raised level' command.

I would completely drop the 'logging filter' commands. But it would still be
useful on a VTY to mute logging to get a usable prompt without the need to
discard the log target:

  logging (mute|off)
  logging (unmute|on)

These are shorter and more intuitive than 'logging filter all (0|1)'.

The current 'logging filter all everything' command is ambiguous. It sounds
like it would aggressively turn on every last logging message. But instead it
does the opposite: it can only add a general *restriction* on the logging level
for all categories of a log target. Any category that is not enabled will still
not log anything. Also, even if a log target has a more detailed level set, the
log target's global logging level potentially prevents the detailed logging. So
the command should sound more like 'logging restrict all to LEVEL'. It needs a
rename, but IMHO we could also just drop it.

Turning on every last log message could be done by 'logging = d:all'.
Restrictions can be imposed by 'logging + e:RSL,MM,...'. Going back to a
previous complex logging setup can be achieved by recalling the previous
'logging = ' commandline. The VTY could print such a paste-back-able line
showing the current logging levels, so that going back is just a copy-paste on
the VTY.


So much for the unicorn's dream. For now, I'll start off with tidying up the
things under [1] above.

~N
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: Digital signature
URL: <http://lists.osmocom.org/pipermail/openbsc/attachments/20170217/a45d1300/attachment.bin>