logging filters, RFC

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