Parallel log spew for events which are also reported back to the SDK user

[QuintinWillison]

We have very little depth of detail in the features spec around what should (or should not) be logged by SDKs.

We cover where under TO3c logHandler and RSC2.
We offer classic, coarse granularity of choice under TO3b logLevel and RSC3.

There are lots of scenarios where there is an event which might be interesting to someone debugging an application reliant upon our SDK, especially one of our support team looking at logs received from a customer, that it is helpful for us to emit that event to the log handler (whether that log handler was explicitly supplied by the customer, or is the default log handler - e.g. STDOUT).

Our default SDK behaviour, albeit not formally documented (as far as I can tell), is to log key events (whether indicative of success or failure) even when we then go on to tell the application code via formal API as well. Hence why I describe this as 'parallel log spew'.

Application developers (our users) will often have strong opinions about how they handle events and in what manner they are logged or reported elsewhere. There are many reasons why such strong opinions may exist - both relating to debugging in development and how their application runs in production on their customer devices (e.g. Android LogCat volume/noise). We should consider these strong opinions from our users in situations where the event that our SDK is emitting to the log is also being reported back to the application code via formal API (e.g. via either synchronous method throw or error return value; or callback of some sort). If the application developer takes the natural choice to write their own log messages as a result of handling those formal APIs they they are very likely to get event reported twice in their logs - which can be just as confusing when debugging (for the user and us in receipt of logs).

I equally recognise that there are also plenty of application developers who do not have such strong opinions or are perhaps less strong at debugging their own code, let alone taking into account SDK issues. For those developers it is perhaps helpful, in respect of how we can support them remotely, that our SDKs default to over/parallel logging. Sometimes it's as simple as the application developer not having used our formal API correctly and perhaps not listening to thrown exceptions, logging them to void or not handling callbacks. Let's not forget the ever faithful customer support first port of call: "switch logs to verbose". 🤓

The outcome of working on this issue could be as simple as documenting what our default SDK behaviour is, accepting this as a behaviour exhibited by Ably SDKs and moving on... However, I think we can do better here and would like to explore whether we can offer an API via client options that would allow the application developer to disable parallel log spew emissions from the SDK, if they are confident that their code is correctly and sufficiently using the formal APIs. This would be a new SDK feature.

Creation of this issue was triggered by ably/ably-asset-tracking-android#813 (review). There is also this Slack thread (internal).

Relates to:

• Revisit default log handler behaviour #14
• Document and conform log levels to assist customers in understanding the severity of different error codes #40
• Crash dump feature for client libraries #60

[sync-by-unito]

➤ Automation for Jira commented:

The link to the corresponding Jira issue is https://ably.atlassian.net/browse/SDK-2951

[paddybyers]

Application developers (our users) will often have strong opinions about how they handle events and in what manner they are logged or reported elsewhere. There are many reasons why such strong opinions may exist - both relating to debugging in development and how their application runs in production on their customer devices (e.g. Android LogCat volume/noise). We should consider these strong opinions from our users in situations where the event that our SDK is emitting to the log is also being reported back to the application code via formal API

I agree with this. Ultimately, if they want to exercise control over what happens to the logs, then they can do this via logHandler etc. However, there are equally situations where the application developer consuming our library isn't actually the same party who has an opinion about the management of logs - especially for server code for example (where the developer who wrote the code isn't the same as the SRE who now has to operate it, or where the developer writing the code can't anticipate what issues might arise in the future, and so can't realistically make reliable filtering decisions on what gets logged and what doesn't). The other situation that we see is where the code that consumes our code is itself a library, and some other party eventually is the one that wants to control the log output. So the recipient of an error indication from an API is definitely not always exclusively the party who wants to observe those issues in fielded systems.

We are expected, and commonly asked, to help users of the service to help work out what is happening when they encounter an anomaly. For this, we really need to see relevant logs, and we have a right to decide what those contain, and these need to be consistent and comprehensive, so that we can provide that support. Of course ultimately the developer consuming the library is free to discard the logs, and the level of support that they can expect in that case is lower.

So I agree a more overt and explicit policy should be stated. But logging is there for a reason, and we (and others) legitimately have a need to be able to observe relevant events (errors and others), aside from the immediate needs of the direct consumer of the API.