This command is used to by higher level applications to dynamically
control the debug logging level of the kernel module. This is
particularly useful to collect debug information from customers filing
feedback reports for issues that are difficult to reproduce outside of a
customer's particular environement.
---
doc/mgmt-api.txt | 25 +++++++++++++++++++++++++
1 file changed, 25 insertions(+)
diff --git a/doc/mgmt-api.txt b/doc/mgmt-api.txt
index 1e59acc54..f2dba64d1 100644
--- a/doc/mgmt-api.txt
+++ b/doc/mgmt-api.txt
@@ -3047,6 +3047,31 @@ Load Blocked Keys Command
Possible errors: Invalid Parameters
Invalid Index
+Set Kernel Debug Logging Level Command
+=======================
+
+ Command Code: 0x0047
+ Controller Index: <controller id>
+ Command Parameters : Debug_Logging_Level (1 octet)
+
+ This command is used to set the kernel debug logging level. This
+ can be by higher level applications to facilitate dynamically
+ controlling the logging level produced by the Bluez kernel module.
+
+ Supported Debug_Logging_Level values:
+ 0 : No Logging
+ 1 : All debug information.
+ All other values are reserved for future use.
+
+ When the kernel receives a value higher than the maximum supported
+ value, the kernel module shall set it's logging level to the highest
+ value it supports.
+
+ This command generates a Command Complete event on success or
+ a Command Status event on failure.
+
+ Possible errors: Invalid Parameters
+ Invalid Index
Command Complete Event
======================
--
2.25.0.341.g760bfbb309-goog
Hi Alain,
> This command is used to by higher level applications to dynamically
> control the debug logging level of the kernel module. This is
> particularly useful to collect debug information from customers filing
> feedback reports for issues that are difficult to reproduce outside of a
> customer's particular environement.
>
> ---
>
> doc/mgmt-api.txt | 25 +++++++++++++++++++++++++
> 1 file changed, 25 insertions(+)
>
> diff --git a/doc/mgmt-api.txt b/doc/mgmt-api.txt
> index 1e59acc54..f2dba64d1 100644
> --- a/doc/mgmt-api.txt
> +++ b/doc/mgmt-api.txt
> @@ -3047,6 +3047,31 @@ Load Blocked Keys Command
> Possible errors: Invalid Parameters
> Invalid Index
>
> +Set Kernel Debug Logging Level Command
> +=======================
> +
> + Command Code: 0x0047
> + Controller Index: <controller id>
> + Command Parameters : Debug_Logging_Level (1 octet)
> +
> + This command is used to set the kernel debug logging level. This
> + can be by higher level applications to facilitate dynamically
> + controlling the logging level produced by the Bluez kernel module.
> +
> + Supported Debug_Logging_Level values:
> + 0 : No Logging
> + 1 : All debug information.
> + All other values are reserved for future use.
> +
> + When the kernel receives a value higher than the maximum supported
> + value, the kernel module shall set it's logging level to the highest
> + value it supports.
> +
> + This command generates a Command Complete event on success or
> + a Command Status event on failure.
> +
> + Possible errors: Invalid Parameters
> + Invalid Index
I need a bit more explanation on how this is suppose to work and why the current dynamic_debug feature is not enough.
Regards
Marcel
Hi Marcel,
I'm not familiar with the dynamic_debug feature.
On ChromiumOS, the interface proposed here is used by the user
feedback system to allow the collection of BT_DBG output when the user
is trying to send us feedback. If there is a better way to do this,
we can certainly use that. but may need to be pointed in the right
direction.
Thanks,
Alain
On Tue, Jan 21, 2020 at 11:20 AM Marcel Holtmann <[email protected]> wrote:
>
> Hi Alain,
>
> > This command is used to by higher level applications to dynamically
> > control the debug logging level of the kernel module. This is
> > particularly useful to collect debug information from customers filing
> > feedback reports for issues that are difficult to reproduce outside of a
> > customer's particular environement.
> >
> > ---
> >
> > doc/mgmt-api.txt | 25 +++++++++++++++++++++++++
> > 1 file changed, 25 insertions(+)
> >
> > diff --git a/doc/mgmt-api.txt b/doc/mgmt-api.txt
> > index 1e59acc54..f2dba64d1 100644
> > --- a/doc/mgmt-api.txt
> > +++ b/doc/mgmt-api.txt
> > @@ -3047,6 +3047,31 @@ Load Blocked Keys Command
> > Possible errors: Invalid Parameters
> > Invalid Index
> >
> > +Set Kernel Debug Logging Level Command
> > +=======================
> > +
> > + Command Code: 0x0047
> > + Controller Index: <controller id>
> > + Command Parameters : Debug_Logging_Level (1 octet)
> > +
> > + This command is used to set the kernel debug logging level. This
> > + can be by higher level applications to facilitate dynamically
> > + controlling the logging level produced by the Bluez kernel module.
> > +
> > + Supported Debug_Logging_Level values:
> > + 0 : No Logging
> > + 1 : All debug information.
> > + All other values are reserved for future use.
> > +
> > + When the kernel receives a value higher than the maximum supported
> > + value, the kernel module shall set it's logging level to the highest
> > + value it supports.
> > +
> > + This command generates a Command Complete event on success or
> > + a Command Status event on failure.
> > +
> > + Possible errors: Invalid Parameters
> > + Invalid Index
>
> I need a bit more explanation on how this is suppose to work and why the current dynamic_debug feature is not enough.
>
> Regards
>
> Marcel
>
Hi Alain,
On 21. Jan 2020, at 20.25, Alain Michaud <[email protected]> wrote:
> I'm not familiar with the dynamic_debug feature.
>
> On ChromiumOS, the interface proposed here is used by the user
> feedback system to allow the collection of BT_DBG output when the user
> is trying to send us feedback. If there is a better way to do this,
> we can certainly use that. but may need to be pointed in the right
> direction.
I think Marcel is referring to this:
https://www.kernel.org/doc/html/latest/admin-guide/dynamic-debug-howto.html
Johan
Thanks, we'll check it out, please consider this patch as abandoned for now.
On Tue, Jan 21, 2020 at 1:33 PM Johan Hedberg <[email protected]> wrote:
>
> Hi Alain,
>
> On 21. Jan 2020, at 20.25, Alain Michaud <[email protected]> wrote:
> > I'm not familiar with the dynamic_debug feature.
> >
> > On ChromiumOS, the interface proposed here is used by the user
> > feedback system to allow the collection of BT_DBG output when the user
> > is trying to send us feedback. If there is a better way to do this,
> > we can certainly use that. but may need to be pointed in the right
> > direction.
>
> I think Marcel is referring to this:
>
> https://www.kernel.org/doc/html/latest/admin-guide/dynamic-debug-howto.html
>
> Johan
Thanks for your patience. After further research dynamic_debug is not
available on retail chromium os user systems for a variety of reasons,
some of which you can find in this trail:
https://bugs.chromium.org/p/chromium/issues/detail?id=188825.
Given we need to be able to diagnose things in the field, this is not
a good option for this.
I hope this helps explain or justify the need for this interface.
Thanks!
Alain
On Tue, Jan 21, 2020 at 1:37 PM Alain Michaud <[email protected]> wrote:
>
> Thanks, we'll check it out, please consider this patch as abandoned for now.
>
> On Tue, Jan 21, 2020 at 1:33 PM Johan Hedberg <[email protected]> wrote:
> >
> > Hi Alain,
> >
> > On 21. Jan 2020, at 20.25, Alain Michaud <[email protected]> wrote:
> > > I'm not familiar with the dynamic_debug feature.
> > >
> > > On ChromiumOS, the interface proposed here is used by the user
> > > feedback system to allow the collection of BT_DBG output when the user
> > > is trying to send us feedback. If there is a better way to do this,
> > > we can certainly use that. but may need to be pointed in the right
> > > direction.
> >
> > I think Marcel is referring to this:
> >
> > https://www.kernel.org/doc/html/latest/admin-guide/dynamic-debug-howto.html
> >
> > Johan
Hi Alain,
> Thanks for your patience. After further research dynamic_debug is not
> available on retail chromium os user systems for a variety of reasons,
> some of which you can find in this trail:
> https://bugs.chromium.org/p/chromium/issues/detail?id=188825.
>
> Given we need to be able to diagnose things in the field, this is not
> a good option for this.
>
> I hope this helps explain or justify the need for this interface.
the reasoning from Kees is 6 years old. Are his issues still valid?
So I have been looking into pushing bt_{info,warn,err} into the btmon traces. That is why we have bt_dev_* etc. error macro and have changed a lot of code to use them. This will hopefully allow us to have errors and warnings directly in the btmon traces. For bluetoothd errors and warnings this already works btw.
I don’t believe that I want to duplicate the dynamic_debug functionality and push even more info into dmesg ring buffer that then needs to be collected and aligned with btmon traces. The big advantage is if you get a btmon trace and that has the actual message right in it at the right place with the right timestamp.
If we push bt_{info,warn,err} into btmon, it might be simpler to do the same for BT_DBG, but it will of course require extra work since our BT_DBG statements are meant to be compiled out if dynamic_debug is disabled.
Regards
Marcel
Hi Marcel,
On Thu, Jan 23, 2020 at 12:52 AM Marcel Holtmann <[email protected]> wrote:
>
> Hi Alain,
>
> > Thanks for your patience. After further research dynamic_debug is not
> > available on retail chromium os user systems for a variety of reasons,
> > some of which you can find in this trail:
> > https://bugs.chromium.org/p/chromium/issues/detail?id=188825.
> >
> > Given we need to be able to diagnose things in the field, this is not
> > a good option for this.
> >
> > I hope this helps explain or justify the need for this interface.
>
> the reasoning from Kees is 6 years old. Are his issues still valid?
>
> So I have been looking into pushing bt_{info,warn,err} into the btmon traces. That is why we have bt_dev_* etc. error macro and have changed a lot of code to use them. This will hopefully allow us to have errors and warnings directly in the btmon traces. For bluetoothd errors and warnings this already works btw.
>
> I don’t believe that I want to duplicate the dynamic_debug functionality and push even more info into dmesg ring buffer that then needs to be collected and aligned with btmon traces. The big advantage is if you get a btmon trace and that has the actual message right in it at the right place with the right timestamp.
>
> If we push bt_{info,warn,err} into btmon, it might be simpler to do the same for BT_DBG, but it will of course require extra work since our BT_DBG statements are meant to be compiled out if dynamic_debug is disabled.
The rational is all still relevant today. To give you some additional
background, here's how a version of this is currently used:
https://chromium-review.googlesource.com/c/chromiumos/third_party/kernel/+/1697851
Note that I don't expect us to upstream this as is, in particular,
it'd expect we'd also want to forward to pr_debug to support
dynamic_debug for systems where it makes sense to use.
>
> Regards
>
> Marcel
>
Hi Alain,
>>> Thanks for your patience. After further research dynamic_debug is not
>>> available on retail chromium os user systems for a variety of reasons,
>>> some of which you can find in this trail:
>>> https://bugs.chromium.org/p/chromium/issues/detail?id=188825.
>>>
>>> Given we need to be able to diagnose things in the field, this is not
>>> a good option for this.
>>>
>>> I hope this helps explain or justify the need for this interface.
>>
>> the reasoning from Kees is 6 years old. Are his issues still valid?
>>
>> So I have been looking into pushing bt_{info,warn,err} into the btmon traces. That is why we have bt_dev_* etc. error macro and have changed a lot of code to use them. This will hopefully allow us to have errors and warnings directly in the btmon traces. For bluetoothd errors and warnings this already works btw.
>>
>> I don’t believe that I want to duplicate the dynamic_debug functionality and push even more info into dmesg ring buffer that then needs to be collected and aligned with btmon traces. The big advantage is if you get a btmon trace and that has the actual message right in it at the right place with the right timestamp.
>>
>> If we push bt_{info,warn,err} into btmon, it might be simpler to do the same for BT_DBG, but it will of course require extra work since our BT_DBG statements are meant to be compiled out if dynamic_debug is disabled.
>
> The rational is all still relevant today. To give you some additional
> background, here's how a version of this is currently used:
>
> https://chromium-review.googlesource.com/c/chromiumos/third_party/kernel/+/1697851
>
> Note that I don't expect us to upstream this as is, in particular,
> it'd expect we'd also want to forward to pr_debug to support
> dynamic_debug for systems where it makes sense to use.
if we do something like this, then I want to do it a lot more integrated. So far I came up with this:
1) We want to be able to start btmon -d and btmon-logger -d and then debugging gets enabled in the kernel and bluetoothd and all of them will be included in the btmon trace files. So a customer can just create a log files that includes kernel messages, bluetoothd messages and also HCI traces and if enabled (and supported by the specific hardware) LMP traces.
2) When enabled in the kernel, then bluetoothd should follow the debug level. I think it makes no sense if we end up having to restart bluetoothd. Especially since bluetoothd also has internally “dynamic_debug” like statements that can be switched at runtime (and per statement actually).
3) We need an option to disable this and compile it out. Switching on dynamic_debug and extra debug statements for our own “dynamic_debug” causes an overhead that we can not really accept. We might even go this far as making it mutually exclusive.
4) Wherever possible we want debug statements that can be related to the given hciX interface index.
5) There needs to be an option to limit the scope of the debug messages since otherwise you get lost in the noise.
6) I don’t want to touch every BT_DBG statement or debug statement in bluetoothd. Developers should be able to just add a debug and the rest will be taken care of for them.
This needs a bit more time to be planed out, but I am roughly thinking something like this:
Read Debugging Categories Command
=================================
Command Code: TBD
Controller Index: <controller id>
Command Parameters:
Return Parameters: Num_Supported_Categories (2 Octets)
Num_Enabled_Categories (2 Octets)
Supported_Category1 (2 Octets)
..
Enabled_Category1 (2 Octets)
..
Set Debugging Categories Command
================================
Command Code: TBD
Controller Index: <controller id>
Command Parameters: Category_Count (2 Octets)
Category1 (2 Octets)
..
Debugging Categories Changed Event
==================================
Event Code: TBD
Controller Index: <controller id>
Event Parameters: Category_Count (2 Octets)
Category1 (2 Octets)
..
With this bluetoothd can check the enabled categories and just enable them when it starts, but it can also monitor the change in enabled categories and change the debug statements accordingly.
This would be independent of btmon and btmon-logger, but these two commands could also use the monitor socket to enable additional categories via a socket option. Or maybe this is better done just one way. I need to think about this a bit more.
Anyhow this is just the API that I would look into doing. The heavy lifting has to be done in the kernel and bluetoothd to use it correctly. That is actually a bit more complicated.
Regards
Marcel
Hi Marcel,
From a high level, this looks good for me although I agree, this is an
order of magnitude bigger in terms of scope. Can you suggest perhaps
an interactive way to deliver this over a period of time, perhaps
prioritizing the BT_DEBUG kernel messages first? :)
Thanks,
Alain
On Thu, Jan 23, 2020 at 12:44 PM Marcel Holtmann <[email protected]> wrote:
>
> Hi Alain,
>
> >>> Thanks for your patience. After further research dynamic_debug is not
> >>> available on retail chromium os user systems for a variety of reasons,
> >>> some of which you can find in this trail:
> >>> https://bugs.chromium.org/p/chromium/issues/detail?id=188825.
> >>>
> >>> Given we need to be able to diagnose things in the field, this is not
> >>> a good option for this.
> >>>
> >>> I hope this helps explain or justify the need for this interface.
> >>
> >> the reasoning from Kees is 6 years old. Are his issues still valid?
> >>
> >> So I have been looking into pushing bt_{info,warn,err} into the btmon traces. That is why we have bt_dev_* etc. error macro and have changed a lot of code to use them. This will hopefully allow us to have errors and warnings directly in the btmon traces. For bluetoothd errors and warnings this already works btw.
> >>
> >> I don’t believe that I want to duplicate the dynamic_debug functionality and push even more info into dmesg ring buffer that then needs to be collected and aligned with btmon traces. The big advantage is if you get a btmon trace and that has the actual message right in it at the right place with the right timestamp.
> >>
> >> If we push bt_{info,warn,err} into btmon, it might be simpler to do the same for BT_DBG, but it will of course require extra work since our BT_DBG statements are meant to be compiled out if dynamic_debug is disabled.
> >
> > The rational is all still relevant today. To give you some additional
> > background, here's how a version of this is currently used:
> >
> > https://chromium-review.googlesource.com/c/chromiumos/third_party/kernel/+/1697851
> >
> > Note that I don't expect us to upstream this as is, in particular,
> > it'd expect we'd also want to forward to pr_debug to support
> > dynamic_debug for systems where it makes sense to use.
>
> if we do something like this, then I want to do it a lot more integrated. So far I came up with this:
>
> 1) We want to be able to start btmon -d and btmon-logger -d and then debugging gets enabled in the kernel and bluetoothd and all of them will be included in the btmon trace files. So a customer can just create a log files that includes kernel messages, bluetoothd messages and also HCI traces and if enabled (and supported by the specific hardware) LMP traces.
>
> 2) When enabled in the kernel, then bluetoothd should follow the debug level. I think it makes no sense if we end up having to restart bluetoothd. Especially since bluetoothd also has internally “dynamic_debug” like statements that can be switched at runtime (and per statement actually).
>
> 3) We need an option to disable this and compile it out. Switching on dynamic_debug and extra debug statements for our own “dynamic_debug” causes an overhead that we can not really accept. We might even go this far as making it mutually exclusive.
>
> 4) Wherever possible we want debug statements that can be related to the given hciX interface index.
>
> 5) There needs to be an option to limit the scope of the debug messages since otherwise you get lost in the noise.
>
> 6) I don’t want to touch every BT_DBG statement or debug statement in bluetoothd. Developers should be able to just add a debug and the rest will be taken care of for them.
>
> This needs a bit more time to be planed out, but I am roughly thinking something like this:
>
> Read Debugging Categories Command
> =================================
>
> Command Code: TBD
> Controller Index: <controller id>
> Command Parameters:
> Return Parameters: Num_Supported_Categories (2 Octets)
> Num_Enabled_Categories (2 Octets)
> Supported_Category1 (2 Octets)
> ..
> Enabled_Category1 (2 Octets)
> ..
>
> Set Debugging Categories Command
> ================================
>
> Command Code: TBD
> Controller Index: <controller id>
> Command Parameters: Category_Count (2 Octets)
> Category1 (2 Octets)
> ..
>
> Debugging Categories Changed Event
> ==================================
>
> Event Code: TBD
> Controller Index: <controller id>
> Event Parameters: Category_Count (2 Octets)
> Category1 (2 Octets)
> ..
>
>
> With this bluetoothd can check the enabled categories and just enable them when it starts, but it can also monitor the change in enabled categories and change the debug statements accordingly.
>
> This would be independent of btmon and btmon-logger, but these two commands could also use the monitor socket to enable additional categories via a socket option. Or maybe this is better done just one way. I need to think about this a bit more.
>
> Anyhow this is just the API that I would look into doing. The heavy lifting has to be done in the kernel and bluetoothd to use it correctly. That is actually a bit more complicated.
>
> Regards
>
> Marcel
>
Hi Alain,
> From a high level, this looks good for me although I agree, this is an
> order of magnitude bigger in terms of scope. Can you suggest perhaps
> an interactive way to deliver this over a period of time, perhaps
> prioritizing the BT_DEBUG kernel messages first? :)
I am always in favor of increasing the ability to debug things, but we need to do this in a clean fashion and not some short term hacks (since they will come back and haunt us). I like to get some review on my idea first.
What we could do is work on the BT_DBG etc infrastructure to allow switching when dynamic_debug is not available. Then you would use some debugfs toggle in /sys/kernel/debug/bluetooth since that is no stable API for us (and of course the clear understanding that this toggle is temporary).
Regards
Marcel
Hi Marcel,
That makes sense. Adding +Archie Pusaka as well who may have input into this.
Thanks,
Alain
On Thu, Jan 23, 2020 at 1:16 PM Marcel Holtmann <[email protected]> wrote:
>
> Hi Alain,
>
> > From a high level, this looks good for me although I agree, this is an
> > order of magnitude bigger in terms of scope. Can you suggest perhaps
> > an interactive way to deliver this over a period of time, perhaps
> > prioritizing the BT_DEBUG kernel messages first? :)
>
> I am always in favor of increasing the ability to debug things, but we need to do this in a clean fashion and not some short term hacks (since they will come back and haunt us). I like to get some review on my idea first.
>
> What we could do is work on the BT_DBG etc infrastructure to allow switching when dynamic_debug is not available. Then you would use some debugfs toggle in /sys/kernel/debug/bluetooth since that is no stable API for us (and of course the clear understanding that this toggle is temporary).
>
> Regards
>
> Marcel
>
Hi Alain, Marcel,
On Thu, Jan 23, 2020 at 10:20 AM Alain Michaud <[email protected]> wrote:
>
> Hi Marcel,
>
> That makes sense. Adding +Archie Pusaka as well who may have input into this.
>
> Thanks,
> Alain
>
> On Thu, Jan 23, 2020 at 1:16 PM Marcel Holtmann <[email protected]> wrote:
> >
> > Hi Alain,
> >
> > > From a high level, this looks good for me although I agree, this is an
> > > order of magnitude bigger in terms of scope. Can you suggest perhaps
> > > an interactive way to deliver this over a period of time, perhaps
> > > prioritizing the BT_DEBUG kernel messages first? :)
> >
> > I am always in favor of increasing the ability to debug things, but we need to do this in a clean fashion and not some short term hacks (since they will come back and haunt us). I like to get some review on my idea first.
> >
> > What we could do is work on the BT_DBG etc infrastructure to allow switching when dynamic_debug is not available. Then you would use some debugfs toggle in /sys/kernel/debug/bluetooth since that is no stable API for us (and of course the clear understanding that this toggle is temporary).
> >
Not sure if I fully understood the problem, so I guess we are looking
to a solution to replace dynamic_debug since that is not normally
enabled on production? Not sure if this should be discussed with
kernel community as whole because it does lead to each subsystem
reinventing their own mechanism of logging.
Now logging the kernel message into btmon I thing would be very
useful, regardless on what the mechanism would be used to enable them,
so perhaps we should start with that. I fill that enabling the exact
same granularity as the dynamic_debug has would be a bit overkill so
Id would suggest sticking with the current categories that we have for
the monitor which are:
#define BTSNOOP_PRIORITY_EMERG 0
#define BTSNOOP_PRIORITY_ALERT 1
#define BTSNOOP_PRIORITY_CRIT 2
#define BTSNOOP_PRIORITY_ERR 3
#define BTSNOOP_PRIORITY_WARNING 4
#define BTSNOOP_PRIORITY_NOTICE 5
#define BTSNOOP_PRIORITY_INFO 6
#define BTSNOOP_PRIORITY_DEBUG 7
Though I see Marcel's point that if we go this way enabling DEBUG
level would simple flood the trace, but I believe the problem can be
solved with a minimal change which is to split data (above
L2CAP/RFCOMM) and signalling logs, obviously this would require a spit
on the way BT_DBG works so we can actually say dump the data path or
just the signalling (this should probably be the default), which I
think would benefit us even in case of using dynamic_debug because
depending what files are enabled (hci_core.c, l2cap_core.c, etc) that
logs way too much and it is not uncommon to lose the logs because the
terminal buffer is not big enough just because the data is intermixed
with some signalling, that said I think we would have to prefix data
and signalling with some string and then use format option to match
them.
--
Luiz Augusto von Dentz
Hi Alain,
>> From a high level, this looks good for me although I agree, this is an
>> order of magnitude bigger in terms of scope. Can you suggest perhaps
>> an interactive way to deliver this over a period of time, perhaps
>> prioritizing the BT_DEBUG kernel messages first? :)
>
> I am always in favor of increasing the ability to debug things, but we need to do this in a clean fashion and not some short term hacks (since they will come back and haunt us). I like to get some review on my idea first.
>
> What we could do is work on the BT_DBG etc infrastructure to allow switching when dynamic_debug is not available. Then you would use some debugfs toggle in /sys/kernel/debug/bluetooth since that is no stable API for us (and of course the clear understanding that this toggle is temporary).
I just posted a patch to allow a short term solution. It is similar to the patch you pointed me to with the difference that it is a debugfs entry and limited to the case when dynamic debug is disabled. Is this something that would work until we get a more complete solution worked out and tested?
Regards
Marcel