-
Notifications
You must be signed in to change notification settings - Fork 577
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Logger#object_filter: restrict Logger to messages referring to specific objects #9844
base: master
Are you sure you want to change the base?
Conversation
lib/base/logger.hpp
Outdated
Log(LogSeverity severity, String facility, const String& message); | ||
Log(LogSeverity severity, String facility); | ||
Log(LogSeverity severity, String facility, const String& message, const std::vector<ConfigObject::Ptr>& involved = {}); | ||
Log(LogSeverity severity, String facility, const std::vector<ConfigObject::Ptr>& involved = {}); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I mean if you're building something that's useful and reusable anyways, make it a PR and we can look at it.
Any thoughts before I adjust every single caller?
lib/base/logger.cpp
Outdated
Log::Log(LogSeverity severity, String facility, const std::vector<ConfigObject::Ptr>& involved) | ||
: m_Severity(severity), m_Facility(std::move(facility)) | ||
{ | ||
std::set<ConfigObject::Ptr> objects; | ||
|
||
for (auto& obj : involved) { | ||
objects.merge(DependencyGraph::GetAllParents(obj)); | ||
} | ||
|
||
objects.insert(involved.begin(), involved.end()); | ||
|
||
for (auto& obj : objects) { | ||
auto severity (obj->GetOverrideSeverityRaw()); | ||
|
||
if (severity >= 0 && severity < m_OverriddenMinSeverity) { | ||
m_OverriddenMinSeverity = (LogSeverity)severity; | ||
} | ||
} | ||
|
||
m_IsNoOp = severity < std::min(Logger::GetMinLogSeverity(), m_OverriddenMinSeverity); | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks really expensive to do for every single debug log message that's probably going to be discarded in the end.
What I think could work better: pass only a single object to Log()
and only compare a single attribute of that object. That attribute would store the combined log severity of that object, i.e. the minimal severity configured on that object or any of its parents. It would be updated when the severity is set, not used, i.e. put the runtime overhead there instead of when log messages are generated. That would also mean that there would only be runtime overhead if that feature is actually used.
(FYI: I haven't put much time into thinking about whether DependencyGraph
actually stores a relation that's useful for this use-case or if it might include too much or too little.)
lib/base/dependencygraph.cpp
Outdated
std::set<ConfigObject::Ptr> objects; | ||
std::unordered_set<ConfigObject *> toDo {child.get()}; | ||
std::shared_lock<std::shared_mutex> lock (m_Mutex); | ||
|
||
do { | ||
auto current (*toDo.begin()); | ||
|
||
toDo.erase(toDo.begin()); | ||
|
||
auto it (m_Dependencies.find(current)); | ||
|
||
if (it != m_Dependencies.end()) { | ||
for (auto& kv : it->second) { | ||
if (objects.emplace(kv.first).second) { | ||
toDo.emplace(kv.first); | ||
} | ||
} | ||
} | ||
} while (!toDo.empty()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That attribute would store the combined log severity of that object, i.e. the minimal severity configured on that object or any of its parents. It would be updated when the severity is set, not used
Too bad relationships are runtime malleable, see e.g. dependencies.
(FYI: I haven't put much time into thinking about whether
DependencyGraph
actually stores a relation that's useful for this use-case or if it might include too much or too little.)
Now as you talk about relationships being "useful for this use-case" I should come out with a thought I had while building this:
This feature doesn't use the DependencyGraph. Instead ConfigObject provides a new virtual method for returning wisely chosen (not checkables across dependencies of course) immediate parents (host for service, checkable for downtime, ...). As it wouldn't include runtime-dynamic parents (checkables across dependencies) and due to #9407, objects could run the algorithm shown above once on creation and RAM-cache the result set.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Too bad relationships are runtime malleable, see e.g. dependencies.
That doesn't make it impossible, just more complicated as those values might need to be updated.
Anyways, how important are the exact details here? Wouldn't this already be useful if there was no cross-object magic at all? You wouldn't get a convenient "everything for that host" switch, but that still sounds useful to me. If I want debug logging for a host, do I even automatically also want debug logging for every service on that host?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If I want debug logging for a host, do I even automatically also want debug logging for every service on that host?
IMAO yes. Especially I want all downtimes and notifications of a service, don't I? And maybe even all hostgroup members.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
IMAO yes. Especially I want all downtimes and notifications of a service, don't I?
That would also be possible if we said something like "you can only filter on checkables". Each log message would be tagged with the checkable and this would simply be compared in the filter.
If that turns out to be too unflexible, maybe something like you suggested could be an option:
Instead ConfigObject provides a new virtual method for returning wisely chosen (not checkables across dependencies of course) immediate parents (host for service, checkable for downtime, ...).
But this should be bounded to a low number of objects, maybe like the object itself, a service, and a host at most.
And maybe even all hostgroup members.
In which case? If you specify a host group in the filter? Or any objects that share a host group?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But this should be bounded to a low number of objects, maybe like the object itself, a service, and a host at most.
Why? For performance reasons per log message? Please ignore them for a moment, I'll handle the performance in general soon.
Instead please have a look at the "parent_affecting_logging" commits from the UX perspective. I.e. user enables verbose logging for X -> Y, Z are affected -> OK?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But this should be bounded to a low number of objects, maybe like the object itself, a service, and a host at most.
Why? For performance reasons per log message? Please ignore them for a moment, I'll handle the performance in general soon.
Basically yes, as that would bound the per-message overhead to something like three set lookups.
Instead please have a look at the "parent_affecting_logging" commits from the UX perspective. I.e. user enables verbose logging for X -> Y, Z are affected -> OK?
I don't really understand the direction this PR is moving towards, but my feeling is that it is becoming more complex than anyone needs or asked for.
Currently, you are just pushing code with little explanation, so please explain in more detail what you're doing and why you're doing that way, including why you think this complexity is necessary.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Admittedly you're right, I'm fixing the OP...
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Instead please have a look at the "parent_affecting_logging" commits from the UX perspective. I.e. user enables verbose logging for X -> Y, Z are affected -> OK?
I don't really understand the direction this PR is moving towards, but my feeling is that it is becoming more complex than anyone needs or asked for.
Currently, you are just pushing code with little explanation, so please explain in more detail what you're doing and why you're doing that way, including why you think this complexity is necessary.
"necessary" is relative. I mean, I could omit the family tree at all. But then runtime-dynamic things like downtimes and comments wouldn't be auto-included along with their checkable, not to mention scheduled downtimes. Allowing just such edge cases would put up questions like but why can't I enable a hostgroup and all hosts are affected? Now you can. You don't have to, but you can.
Just read 1ce044c 06ea999 67fb214 d98bb31, but mirror it from the user perspective and imagine some recursion on top. E.g. a hostgroup specified in the logger filter implies also its hosts (06ea999), their services (67fb214) and the latter's downtimes (d98bb31).
PS: Yes, I know it doesn't compile yet, but Log#Log() callers are missing anyway.
lib/base/logger.cpp
Outdated
for (auto& obj : objects) { | ||
auto severity (obj->GetOverrideSeverityRaw()); | ||
|
||
if (severity >= 0 && severity < m_OverriddenMinSeverity) { | ||
m_OverriddenMinSeverity = (LogSeverity)severity; | ||
} | ||
} | ||
|
||
m_IsNoOp = severity < std::min(Logger::GetMinLogSeverity(), m_OverriddenMinSeverity); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This loop would still exist.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why/where do you need to pass multiple objects?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This loop would still exist.
Not for multiple objects. For an object's multiple parents.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Then I don't quite understand why the parameter is const std::vector<ConfigObject::Ptr>& involved
is at the moment (i.e. a vector instead of a single pointer). Looks like you want to specify multiple objects (where with the current code, the parents for each one would be looked up). Is there a situation where this is necessary (or at least useful)?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I didn't examine a single caller yet, not to mention all of them. If it turns out that no log message immediately involves multiple not necessarily related objects, I'll omit the vector.
lib/base/logger.cpp
Outdated
std::set<ConfigObject::Ptr> objects; | ||
|
||
for (auto& obj : involved) { | ||
objects.merge(DependencyGraph::GetAllParents(obj)); | ||
} | ||
|
||
objects.insert(involved.begin(), involved.end()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But it would iterate an existing small set, not a computed one like this.
What do you think?
In general, the overhead per Another question came to my mind where the answer might also help to reduce that overhead: if you configured that you want more verbose logging for some object, where will these messages be logged? If you have a logger writing only severity critical to syslog and another logger for a more verbose file, you certainly don't want to spam debug logging for a specific object to syslog. So there should probably be some configuration for where these messages go and if that's not configured, all that logic in the |
3e9b03d
to
48289a4
Compare
Almost done #7912 (comment), any concerns already? |
lib/base/logger.cpp
Outdated
if (filter) { | ||
if (!m_Involved) { | ||
continue; | ||
} | ||
|
||
auto indirect (DependencyGraph::GetAllParents({m_Involved})); | ||
|
||
indirect.emplace(m_Involved); | ||
|
||
// TODO(ak): do something useful here | ||
for (auto& object : indirect) { | ||
} | ||
|
||
ObjectLock lock (filter); | ||
|
||
for (auto& kv : filter) { | ||
auto type (Type::GetByName(kv.first)); | ||
} | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It will boil down to what exactly will happen here in the end as it doesn't look very finished so far.
I still see the call to DependencyGraph::GetAllParents()
here critical. As it's inside if (filter) {
it isn't terrible, but it isn't exactly great either. I'd probably prefer a variant that wouldn't need that for every message.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I still see the call to
DependencyGraph::GetAllParents()
here critical. As it's insideif (filter) {
it isn't terrible, but it isn't exactly great either. I'd probably prefer a variant that wouldn't need that for every message.
Despite how I've already optimised that data structure? If yes, this leads us back to the unfinished discussion above: #9844 (comment)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looking at the new version of Log::~Log()
you've just pushed, what you're doing there is far from being (almost) free: walking a graph, creating and deleting multiple sets and vector, obtaining multiple locks. If we want to do this, this needs some performance testing, I wouldn't want to merge this without knowing the impact. I mean this feature is intended for installations where there are so many log messages that you want to filter them. so if there is a high cost per message, this will add up.
lib/base/dependencygraph.cpp
Outdated
std::set<Object::Ptr> objects, toDo (children.begin(), children.end()); | ||
std::shared_lock<std::shared_mutex> lock (m_Mutex); | ||
|
||
do { | ||
auto current (*toDo.begin()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This assumes that children
is never empty. Just using a regular while (!toDo.empty())
loop would also just handle that case correctly.
48289a4
to
33b1596
Compare
33b1596
to
179e4c5
Compare
179e4c5
to
9eca379
Compare
This attribute is used only by ScheduledDowntime anyway and is a relation declarator such as host_name, service_name.
The cluster tree can't be runtime-altered anyway.
…to it See the currently supported apply rules.
…ally depending on it
…cache recursively from ConfigObject#GetParentsAffectingLogging().
…gObject#m_AllParentsAffectingLogging If Logger#object_filter is set, but doesn't intersect with ConfigObject#m_AllParentsAffectingLogging, drop the message.
9eca379
to
8c3bfd0
Compare
Please improve the PR title and description. It should be a mostly self-contained summary of what this change does (or will do if it's not finished yet) rather than a collection of links to the commits where one has to piece together the information. A good description should at least provide:
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
FYI: information that I would have found useful in the description which I still had to extract from the code myself:
- When the all the config has been loaded, the "logging parent graph" (that's the graph formed from all the config objects and the edges returned by that new
GetParentsAffectingLogging()
function) is searched for all (indirect) parents of that object. The result is stored as astd::set<ConfigObject*>
in every object. - For each logger, if the new
object_filter
attribute is set, the following happens (either when all config is loaded or the attribute is updated at runtime): resolve all object names given in this attribute to pointers and store the results in a sortedstd::vector<ConfigObject*>
. - For each log message and logger, these two structures are checked for common elements using
std::set_intersection()
to check if the message should actually be logged.
std::vector<Ptr> toDo {this}; | ||
|
||
do { | ||
auto current (toDo.back()); | ||
|
||
toDo.pop_back(); | ||
|
||
if (m_AllParentsAffectingLogging.Data.emplace(current.get()).second) { | ||
current->GetParentsAffectingLogging(toDo); | ||
} | ||
} while (!toDo.empty()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So m_AllParentsAffectingLogging.Data
will contain Ptr(this)
, so wouldn't this prevent the object from ever being deleted?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I permanently store only raw pointers, not intrusive ones.
auto filter (logger->GetObjectFilter()); | ||
|
||
if (logger->GetObjectFilter()) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks like some leftover: calling the function again after storing the result of that function in an unused variable?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Fixed it locally for now. No reason for any more GHA excesses, yet. 🙈
@@ -104,6 +116,9 @@ class Logger : public ObjectImpl<Logger> | |||
static LogSeverity m_ConsoleLogSeverity; | |||
static std::mutex m_UpdateMinLogSeverityMutex; | |||
static Atomic<LogSeverity> m_MinLogSeverity; | |||
|
|||
Atomic<bool> m_CalledOnAllConfigLoaded {false}; | |||
std::vector<ConfigObject*> m_ObjectFilterCache; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
As these are raw pointer, is there anything preventing them from becoming dangling? (For those in ConfigObject.m_AllParentsAffectingLogging.Data
one might argue with that they should only be removed in a safe order, but even that should be double checked and here, I don't see anything like that.)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nothing at all and I see no problems as they're only intersected anyway.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It looks like the behavior of that is implementation-defined (see https://stackoverflow.com/a/30694084, and even undefined in C++11) and even in the best-case scenario, this could result in some object randomly being logged if is allocated at the same address as some previous object that was included in the filter.
Apart from that, leaving dangling pointers is always dangerous, better hope nobody will ever have an idea that involves dereferencing the pointers in this vector.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Seriously, a raw pointer is just a number. Not more, not less. In Log#~Log(🪵) I'm only comparing numbers. Change my mind.
this could result in some object randomly being logged if is allocated at the same address as some previous object that was included in the filter.
Yes, in case someone who explicitly included an object in a filter removes that object. Again, explicitly. Would you feel better if I maintain an additional vector with Ptr, just for keep alive?
Apart from that, leaving dangling pointers is always dangerous, better hope nobody will ever have an idea that involves dereferencing the pointers in this vector.
DependencyGraph has the same problem.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Seriously, a raw pointer is just a number. Not more, not less. In Log#~Log(🪵) I'm only comparing numbers. Change my mind.
That's probably what most people expect, but compilers may see an opportunity for optimization that could go wrong.
this could result in some object randomly being logged if is allocated at the same address as some previous object that was included in the filter.
Yes, in case someone who explicitly included an object in a filter removes that object. Again, explicitly. Would you feel better if I maintain an additional vector with Ptr, just for keep alive?
Which would then just prevent the object from ever being freed?
Apart from that, leaving dangling pointers is always dangerous, better hope nobody will ever have an idea that involves dereferencing the pointers in this vector.
DependencyGraph has the same
problem.
I hope it doesn't. DependencyGraph
will even dereference the pointers itself in DependencyGraph::GetParents()
so there better be no dangling pointers. Objects should do DependencyGraph::RemoveDependency()
before they die, if they don't, it's a bug.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Seriously, a raw pointer is just a number. Not more, not less. In Log#~Log(🪵) I'm only comparing numbers. Change my mind.
That's probably what most people expect, but compilers may see an opportunity for optimization that could go wrong.
Suggestion:
I assert std::is_trivial_v on the pointer type I use.
this could result in some object randomly being logged if is allocated at the same address as some previous object that was included in the filter.
Yes, in case someone who explicitly included an object in a filter removes that object. Again, explicitly. Would you feel better if I maintain an additional vector with Ptr, just for keep alive?
Which would then just prevent the object from ever being freed?
Exactly. (Especially with my recursive relationship feature) one shouldn't list every single object in the config.
Apart from that, leaving dangling pointers is always dangerous, better hope nobody will ever have an idea that involves dereferencing the pointers in this vector.
DependencyGraph has the same
problem.I hope it doesn't.
DependencyGraph
will even dereference the pointers itself inDependencyGraph::GetParents()
so there better be no dangling pointers. Objects should doDependencyGraph::RemoveDependency()
before they die, if they don't, it's a bug.
+1.
All in all, have I ever mentioned I'd like the classic std::shared_ptr back? We'd have std::weak_ptr which enables having not dangling, but not leaking pointers.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Suggestion:
I assert std::is_trivial_v on the pointer type I use.
Ah, nice! Pointer types are scalar types (https://en.cppreference.com/w/cpp/named_req/ScalarType) which are trivial types (https://en.cppreference.com/w/cpp/named_req/TrivialType).
compilers may see an opportunity for optimization that could go wrong.
Shall I make my just-numbers volatile
then?
fixes #7912
This is the planThere's a filter saying which objects along with their children are affected by a logger: f59082d 9693663Apropos, too bad children (dis)appear dynamically during parent object lifetime, but parents are static per-child, so the relationship rules point from child to parent: 1ce044c 06ea999 67fb214 d98bb31(Well, static is relative, I had to tweak a few things: a3f8d84 53f881b)Those rules are so simple that one can even understand them by just reading the individual commits – at the cost of a little infrastructure hosting them: 7914d8eEverything's cached of course: 27413d5 2a14803The latter makes this algorithm especially performant where filter meets family tree: 8c3bfd0To do
Edit
User POV
This adds the ability to do the following with every single logger type:
object FileLogger "main-log" { severity = "information" path = LogDir + "/icinga2.log" + object_filter = { "HostGroup" = [ "NETWAYS" ] } }
All config types are supported, not just HostGroup.
Not existing objects will trigger warnings (as not matching apply rules do).
The line inserted above would cause main-log not to log messages not referring to the HostGroup NETWAYS.
This is useful for (runtime) creating a debug logger, but only for some config objects.
What does "referring" mean?
A log message refers (has to be done in the code) explicitly to either the specific object given in object_filter or any of its children as below, recursively:
Rationale
UX, intuitivity. Even if a user doesn't know the above table, if they include parent in object_filter, they likely expect all children to be logged as well.
Dev POV
(aka
git log --oneline
with comments)Logger#object_filter
The first two ones should be self-explanatory.
The third one simply looks up the strings given in object_filter (initially and on change) and caches object pointers to ease comparison later.
Relationship rules
This is the base.
On its own it would only generate the exact method as named above doing nothing.
Not to be too boring it also adds a new .ti field attribute parent_affecting_logging causing the type to have a own GetParentsAffectingLogging method yielding the object named by the field.
E.g. putting parent_affecting_logging on Comment's host_name and service_name creates
Comment#GetParentsAffectingLogging()
which returns the comment's host and service.Apropos:
These define the What does "referring" mean? part from above.
The relationships point from child to parent simply because new children can appear, but -as in real life- one's parents always stay the same.
Due to that fact every child can look up its parents recursively once and cache the pointers for a lifetime:
Just to be sure that the parents really always stay the same:
Putting hydrogen and oxygen together
With all the above and an object pointer in every Log🪵 instance Log#~Log() just intersects the two caches, ConfigObject#m_AllParentsAffectingLogging and Logger#m_ObjectFilterCache, and passes the message through if successful.