0
Under review

Request Identifier on log entries

Adrian Corston 1 month ago • updated 4 weeks ago 4

When looking through the logs in UNIFYBroker, I find it difficult to associate all log messages that relate to one request that has been executed.  This is particularly difficult on a busy live system where multiple operations are happening in parallel and log entries are interleaved.

It would be very beneficial to include a request identifier on every log entry, to indicate which request the log entry relates to.  That way all the log entries for one request could be extracted and viewed separately, to give a convenient and complete picture of all of the logged outcomes of that request.  It would also make it possible to generate a high level request list summary, by extracting just the first log entry for each request.  This would be incredibly useful when investigating problems and logging voice tickets.

e.g.

TimestampRequest DescriptionRequest ID
2019-07-20 01:39:49Request to manually queue a baseline synchronization job on link started. Request to manually queue a baseline synchronization job on link Chris21 DET started.ae4dffd3-f857-4074-957b-5be0a10b201b
2019-07-20 01:47:40Request to sync adapter to locker started. Synchronization job started syncing 42942 changes on the 'Chris21 DET' link from the adapter to locker.017f4072-470e-47fd-83cb-13b9c9d03c90
There is a Job ID on some types of log entries, but most don't have it, which means it isn't really suitable for this purpose.

Affected Versions:
Fixed by Version:
Under review

As I'm sure you've seen, some of our call stacks are very nested, and often with multiple branches underneath - CSV is a pretty poor format to try to convey this information. Our other log writers have much more flexibility with what they can do and are often much better suited for displaying this type of information (JSON allowing the entire call stack to be represented and correlate between all the log entries). With this in mind, would you deem it still essential to make improvements to the CSV log writer? If so, how much additional information would be necessary? Thanks.

Hi Adam,

I understand that some of the things I ask for are likely to be difficult to implement.  My aim here is to let the Engineering Group know what PS find difficult about using UNIFYBroker, and suggest the sort of feature that would help reduce our difficulties.  I know that it has been said that Professional Services doesn't communicate their needs, so I am addressing that by doing so now.  I have created quite a few tickets talking about our pain points and suggesting ways that these could be addressed to make UNIFYBroker more palatable for end users.

Specifically relating to this ticket though - if I had to implement it then I would add a "Request ID" variable to the logger object, along with methods to set and clear that ID.  When writing log entries then if the Request ID were set on the logger object then I would include it in every log entry written. Finally I'd update the UNIFYBroker code to set the Request ID on the logger object when starting up the processing of a Request, and clear it when I finished up on this Request.  That way there would be no need to update every Log* call to the logger (which is obviously not practical).

The caller stack that you mention is not related to what I'm asking for here - that's something that I would expect to be useful to the UNIFYBroker developers, but not to users of the software.

Your feedback is very much valued. My response was aimed at getting to the core value of your request and try to come up with a suitable workaround if one existed.

With regards to the call stack, it does relate to what you've asked as we have numerous things going on inside the service, a lot of them without having been initiated by a user or external action by an identity management platform.

We already capture this sort of information (it's used by the other log writers). I'll have a chat with the others about this. Thank you.

That looks like it would be a useful feature as well.

That said, the main reason for this ticket is for something that provides better visibility into the current activities of UNIFYBroker, as well as historical.  Canonical log lines would help with the latter somewhat, but not the former.

Having a request ID on every log line means the log can be filtered to indicate what actions a particular request is performing as well as what it has done beforehand.  Also to identify all the logging that is likely to relate to a particular error condition, in order to look for earlier signs of what has gone wrong (important in identifying root cause).

If that doesn't make sense then it might be easier to talk through a use case/demo in person.