Logging reduction changes

[Aleksander Morgado]

Hey!

On Mon, Jul 26, 2021 at 3:10 PM Peter Naulls <peter at chocky.org> wrote:
>
> On 7/26/21 4:20 AM, Aleksander Morgado wrote:
> > Hey,
>
> >
> > My question here would be, how is it possible that this message is
> > bothering you so much? It's a debug log that is generated only on
> > client allocation. Are you allocating and releasing new clients in a
> > loop or something? This should only happen on program startup or when
> > operation specific clients are allocated (e.g. a new WDS client during
> > a connection attempt).
>
> "Bothering you so much" are your words, not mine.

Well, yes, those are my words. Please don't take them in a bad way, I
didn't imply anything negative with that comment, I'm sorry if felt
otherwise. I just assumed, maybe wrongly, that those logs would be
happening multiple times, which is why you suggested to remove them.
Logs that happen multiple times without much information in them
bother me a lot, and I'm extremely fine to remove those :)

> Most of what I do
> is dealing with system logs and dis/reconnets, which can get quite lengthy,
> hence these changes.  This is small, but it happens several times so it
> can add up if there's a failure or whatever.

But, it's a debug log, it's definitely going to get quite lengthy. If
it were a log that happens continuously over and over, I would be
worried, but given it's a one time message saying that a new client is
going to be allocated, I wouldn't worry much really.

> Superfluous messages
> are also a distraction to those who are less familiar with the system
> who might be providing me logs.
>

I'm sure we can find many more superfluous messages apart from that one...

> > Instead of removing it, I think we could improve it adding more
> > information about what type of QMI client is being allocated for
> > example.
>
> As I think I mentioned, there's already a following message which does
> exactly that.

The following message would report the failure or success; but what if
there were no such message? If for any reason we fail to chain up the
async methods correctly (a NULL callback in
qmi_device_allocate_client() is perfectly fine API wise, although it
doesn't make much sense), we could miss that following message
completely. That's why I said that improving the debug log (to make it
add some valuable information like the service being allocated)
instead of removing it completely could be a better option here.

>
> >>
> >> --- a/src/libqmi-glib/qmi-device.c      2021-06-03 12:06:40.442931910 -0400
> >> +++ b/src/libqmi-glib/qmi-device.c      2021-06-03 12:07:05.435047942 -0400
> >> @@ -346,7 +346,7 @@
> >>        /* If the command is not abortable, we'll return the error right away
> >>         * to the user. */
> >>        if (!__qmi_message_is_abortable (tr->message, tr->message_context)) {
> >> -        g_debug ("transaction 0x%x aborted, but message is not abortable",
> >> transaction_id);
> >> +        //g_debug ("transaction 0x%x aborted, but message is not abortable",
> >> transaction_id);
> >>            device_release_transaction (self, tr->wait_ctx->key);
> >>            transaction_complete_and_free (tr, NULL, abort_error_take);
> >>            g_error_free (abort_error_take);
> >>
> >> I had to suppress this.  In my testing, this would happen every 30 seconds. I
> >> don't know if it was some side effect or other code we were running or what.
> >> Sure, it's maybe interesting once, but not hundreds of times in a log:
> >>
> >
> > I've seen this message some times, especially when unplugging a
> > device, as the ongoing request gets aborted because the port is gone.
> > Not sure why you would see this every 30s; is this maybe something
> > related to what you do? I think we should definitely try to understand
> > the root cause of the message.
>
> Yes, probably. I don't have a lot of time to do so, but if there's experiments
> you want me to run, I can.

Well, if you can gather a MM debug log where this "but message is not
abortable" log happens every 30s, please post it here for review, and
we can try to see why it happens.

Anyway, maybe we can also rework that logging logic, because there are
exactly only 2 QMI messages that may be aborted, not sure if it makes
much sense to log that for every other message; or maybe we could
change it so that we don't attempt to run as an abortable message all
the messages that we know are not abortable.

-- 
Aleksander
https://aleksander.es