#49996 Ticket 49995 - Fix issues with internal op logging
Closed by spichugi. Opened by mreynolds.
mreynolds/389-ds-base ticket49995  into  master

Download 49996.patch

Bug Description:

At server startup the server's internal operations performed by bootstrapping
occurred before the thread data was initialized. This caused random values in
the logging counters [1].

It was also observed that nested operations(and nested-nested operations, etc)
were not properly logged [2].

Fix Description:

[1] Move the thread initialization higher up in main()

[2] Changed the way we log nested internal operations. Instead, we keep the
internal op number the same for nested ops but also now display the nested level.

See the ticket for examples of the new logging format

https://pagure.io/389-ds-base/issue/49995

Reviewed by: ?

rebased onto 9d69ac828b5bb731b145b10624d7baeb91b90a94

They should really have always been part of the op struct, not a thread local I think. Perhaps we should just fix it correctly? It seems a bit hacky in the current form.

Said better, I think the current form is too complex, relies on lots of assumptions, and can easily be broken. What we should do is when we create a new internal op, we should access the PB, get the current op out, and then inspect that as the parent to build the child/nested op data and id's. We can also then have the ops actually chain in the op structure, so we know "where we are up to" and can walk over the tree of operations. Long term this will help with our logging for performance code as we can again, stash all the timings in the op struct, and then at the end pull them out.

They should really have always been part of the op struct, not a thread local I think. Perhaps we should just fix it correctly? It seems a bit hacky in the current form.

Actually this PR is significantly simplified from the previous version. I take great exception to your use of "hacky". I don't think you have thought this through when it comes to nested nested nested operations. We do NOT use the same pblock when plugins get nested. Plugin's create new pblocks all the time when they do their own internal ops - which in turn can trigger other plugins which again can create their own pblocks, etc, etc, etc. This is why using local thread storage is the best solution. Personally I'm not going to refactor all the internal op code (and the thousands of code blocks that use it) to add a parent pblock parameter, but if you want to then by all means please file a PR. But to me that feels really "hacky".

Also, you said my design can easily be broken. If you can find a way to break the current design then please file a new ticket with a reproducer, but in my testing it works fine when plugin's start getting nested and they do their own internal ops. I'm not sure what other scenario I could be missing.

You're right. Hacky was the wrong word, I apologise.

To me, it is a layering violation to use threads storage for contextual data. We should be providing that context in the chain as we create and nest the pblocks and operation structures. This means at the time we create "slapi_internal_search" (or whatever it is), we need to provide our current pb.

This way on the front end we get a new op and we set NULL parent op.
When we create the internal search we provide our op. The child op says "my parent is op_parent and I'm X". Then we have all the internal flags an internal op ids there. When the op_child spawns a new op, it too can then say "hey, the root parent of all this is op_parent, your parent is op_child, okay, your internal op id is allocated by parent.".

This way we get a tree of operations like:

     op_parent
    /               \
op_child     op_child2
  |
op_inner

Op_parents tracks all the id allocs, we know what operation spawned what (great for future auditing and profiling which I want to embed to the operation struct). It means that we don't need thread local storage, and it's easier for us to test with something like cmocka to construct this and generate id's etc.

Okay, today we may not refactor it: my point is that I want to do this in the future and if we have an issue, now is a good time. If it's hard to debug in the current form, that probably indicates some level of complexity of the interaction that is a problem. I also want to stop thinking "like C" in our code. C is not sustainable long term, and if we want to test with cmocka, integrate other languages, or continue to improve our own readability and analysis, we need to use context structs in an almost functional style.

I hope that helps as a better justification of my comment, and I apologise for my words. It was not meant to say that you didn't do good work. I think that you and I often approach and solve problems differently and I should have been sensitive to that.

This means at the time we create "slapi_internal_search" (or whatever it is), we need to provide our current pb.
<<<

but this is something we do not and cannot enforce curently, nothing prevents a plugin to create a new pblock and pass it to another internal op. What you would need to have is pblocj creation only at the begin of an external op or with an existing pblock.
But we have own plugins and probably custom plugins which do not respect your request. It is a bit like nesting transactions, since we cannot rely on plugins for properly nesting we have a txn stack in the thread local storage.

I do see a great benefit in Mark's work on better logging of internal operation and I do not want to delay it for a future clean implementation.

Ack from me

@firstyear thanks for the explanation, and I think we should pursue it. Maybe write a new slapi api (part of your v4 work)? But there are the pitfalls that both Ludwig and I mentioned. Unfortunately this needs to be fixed "yesterday" because it's part of a released feature and it has already passed development deadlines. However, I am not opposed to "reverting" this in the future when something else is ready and the timing is right. Maybe in 2.0.0 (aka 1.5.0 or maybe in 1.4.2) we start adding these major rewrites (and rust?).

rebased onto da7d932055596be4f53c3b46ba098d5828f5752f

rebased onto a7dfa383d103944dfd27fff98152138c1b0fd0f7

Pull-Request has been merged by mreynolds

@mreynolds Let's keep this in the future bucket and talk about it then :) I agree to ack the fix.

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/3055

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi

Metadata