| Message ID | 20231128230847.1224497-2-gerickson@nuovations.com (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
| Series | connection: Improve Connection Gateway Debugging and Documentation | expand |
Hi Grant, > This refactors the debugging / debug log preprocessor-related > macros. In particular, it: > > * Introduces CONNMAN_DEBUG_DESC_INSTANTIATE which declares and > instantiates an instance of 'connmand_debug_desc'. > > * Replaces CONNMAN_DEBUG_DEFINE with CONNMAN_DEBUG_ALIAS which > declares and instantiates an alias (that is, asserts the > CONNMAN_DEBUG_FLAG_ALIAS flag) instance of > 'connmand_debug_desc', using CONNMAN_DEBUG_DESC_INSTANTIATE. > > * Introduces CONNMAN_DEBUG which declares and instantiates > an instance of 'connmand_debug_desc', again using > CONNMAN_DEBUG_DESC_INSTANTIATE, for controlling an invocation of > 'connman_debug' with it that includes both the file and function > name the macro was invoked in or attributed to. > > - The key difference between this and 'DBG' is that this allows > the caller to specify the function string rather than relying on > '__FUNCTION__' (or __func__). > > * Redefines 'DBG' against 'CONNMAN_DEBUG' with '__func__' as the > function parameter. > --- > include/log.h | 34 +++++++++++++++++++++------------- > src/log.c | 2 +- > 2 files changed, 22 insertions(+), 14 deletions(-) I don’t like this since it ends up bloating the DBG part of it and you spent more time making debug look pretty than making the code look good. The kernel has a nice concept with pr_fmt where you can overwrite pr_debug on a per file basis. I rather prefer that we adopt such a scheme. It will make things a lot simpler and have less boilerplate. Long term this needs to get all into ELL and we need to use ELL debug functionality instead of having separate ones in each project. Regards Marcel
On Nov 29, 2023, at 5:15 AM, Marcel Holtmann <marcel@holtmann.org> wrote: >> This refactors the debugging / debug log preprocessor-related >> macros. In particular, it: >> >> * Introduces CONNMAN_DEBUG_DESC_INSTANTIATE which declares and >> instantiates an instance of 'connmand_debug_desc'. >> >> * Replaces CONNMAN_DEBUG_DEFINE with CONNMAN_DEBUG_ALIAS which >> declares and instantiates an alias (that is, asserts the >> CONNMAN_DEBUG_FLAG_ALIAS flag) instance of >> 'connmand_debug_desc', using CONNMAN_DEBUG_DESC_INSTANTIATE. >> >> * Introduces CONNMAN_DEBUG which declares and instantiates >> an instance of 'connmand_debug_desc', again using >> CONNMAN_DEBUG_DESC_INSTANTIATE, for controlling an invocation of >> 'connman_debug' with it that includes both the file and function >> name the macro was invoked in or attributed to. >> >> - The key difference between this and 'DBG' is that this allows >> the caller to specify the function string rather than relying on >> '__FUNCTION__' (or __func__). >> >> * Redefines 'DBG' against 'CONNMAN_DEBUG' with '__func__' as the >> function parameter. >> --- >> include/log.h | 34 +++++++++++++++++++++------------- >> src/log.c | 2 +- >> 2 files changed, 22 insertions(+), 14 deletions(-) > > I don’t like this since it ends up bloating the DBG part of it... Can you clarify? Beyond eliminating the bit of copy-and-paste that was previously in log.h prior to this patch, the emitted and compiled code is identical. > and you spent more time making debug look pretty than making the code look good. These are both laudable goals and ends and I don’t see a barrier to trading off one for the other. Making the code look good and function well and correctly is absolutely the top priority. However, at the end of the day, software is software and humans are humans and getting to perfect can be asymptotically expensive and, perhaps, is never attainable. Moreover, when extending the envelope of functionality on a base of software, particular in the face of limited internals documentation and little to no spatial or temporal access to the original authors of the code to clarify intent, having code that is easily debugged (and well documented) is at least as important. That said, I think the DBG and -d facilities in connman are both useful and quite ingenious. They are very effective and work and scale far better than sections/modules, etc and other schemes I’ve encountered and used in the past. But, having spent the last week (and, before that, debugging WISPr/online check) trying to build an understanding of how and where connection.c fits into the overall system, the content and efficacy of the debug output is important. The end goal for this particular patch was, “How do I achieve a single place for debug-logging the contents of a gateway_config and/or gateway_debug structure (which happens at many places in connection.c), attribute the output to the appropriate call site and function, without copying-and-pasting the DBG to do so in every call site?” Absent the approach I took, the other alternative is to include a “from %s” in the format such that the log output ends up being: connmand[16689]: src/connection.c:gateway_data_debug() from __connman_connection_gateway_add() new_gateway 0x7471c060: { index: 4 (eth0), service: 0x72503240 (ethernet_0004f31a5ee0_cable), ipv4_config: 0x7471c030, ipv6_config: (nil), default_checked: 0 } connmand[16689]: src/connection.c:gateway_config_debug() from __connman_connection_gateway_add() ipv4_config 0x7471c030: { flags: 0x0 (), gateway: 0x7511d7f0 (192.168.2.1), vpn_ip: (nil) (<null>), vpn_phy_index: -1 (<null>), vpn_phy_ip: (nil) (<null>) } which adds an extraneous bit of information which, since it doesn’t aid in debug or understanding, ends up being mental and visual “noise” and doesn’t further the debug goals. However, if that’s preferable to the approach I took, I’m happy to go that direction and recast the patches toward that end. Let me know if that’s an acceptable alternative. > The kernel has a nice concept with pr_fmt where you can overwrite pr_debug on a per file basis. I rather prefer that we adopt such a scheme. It will make things a lot simpler and have less boilerplate. I’d be happy to learn more and take a look. Do you have a link from the kernel git that demonstrates this? > Long term this needs to get all into ELL and we need to use ELL debug functionality instead of having separate ones in each project. That seems like a great outcome and seems like it would work well with or without these patches: connman_debug_desc becomes ell_debug_desc, and generally anything connman_ or CONNMAN_ namespaced in log.h becomes ell_ or ELL_ namespaced and sourced from ell/log.h (or some such) rather than connman/log.h. CONNMAN_DEBUG aside, are you otherwise OK with the clean ups and documentation to log.h embodied in this patch? Best, Grant
Hi Grant, >>> This refactors the debugging / debug log preprocessor-related >>> macros. In particular, it: >>> >>> * Introduces CONNMAN_DEBUG_DESC_INSTANTIATE which declares and >>> instantiates an instance of 'connmand_debug_desc'. >>> >>> * Replaces CONNMAN_DEBUG_DEFINE with CONNMAN_DEBUG_ALIAS which >>> declares and instantiates an alias (that is, asserts the >>> CONNMAN_DEBUG_FLAG_ALIAS flag) instance of >>> 'connmand_debug_desc', using CONNMAN_DEBUG_DESC_INSTANTIATE. >>> >>> * Introduces CONNMAN_DEBUG which declares and instantiates >>> an instance of 'connmand_debug_desc', again using >>> CONNMAN_DEBUG_DESC_INSTANTIATE, for controlling an invocation of >>> 'connman_debug' with it that includes both the file and function >>> name the macro was invoked in or attributed to. >>> >>> - The key difference between this and 'DBG' is that this allows >>> the caller to specify the function string rather than relying on >>> '__FUNCTION__' (or __func__). >>> >>> * Redefines 'DBG' against 'CONNMAN_DEBUG' with '__func__' as the >>> function parameter. >>> --- >>> include/log.h | 34 +++++++++++++++++++++------------- >>> src/log.c | 2 +- >>> 2 files changed, 22 insertions(+), 14 deletions(-) >> >> I don’t like this since it ends up bloating the DBG part of it... > > Can you clarify? Beyond eliminating the bit of copy-and-paste that was previously in log.h prior to this patch, the emitted and compiled code is identical. my presence is that you use DBG() and only that in your code to have debug prints. It is easy to spot and easy to grep for and you can compile it into a nop if you want to. If you need anything else, it should be a one time thing at the top of your *.c file. My main model is what the kernel called dynamic_debug. >> and you spent more time making debug look pretty than making the code look good. > > These are both laudable goals and ends and I don’t see a barrier to trading off one for the other. > > Making the code look good and function well and correctly is absolutely the top priority. > > However, at the end of the day, software is software and humans are humans and getting to perfect can be asymptotically expensive and, perhaps, is never attainable. Moreover, when extending the envelope of functionality on a base of software, particular in the face of limited internals documentation and little to no spatial or temporal access to the original authors of the code to clarify intent, having code that is easily debugged (and well documented) is at least as important. > > That said, I think the DBG and -d facilities in connman are both useful and quite ingenious. They are very effective and work and scale far better than sections/modules, etc and other schemes I’ve encountered and used in the past. > > But, having spent the last week (and, before that, debugging WISPr/online check) trying to build an understanding of how and where connection.c fits into the overall system, the content and efficacy of the debug output is important. > > The end goal for this particular patch was, “How do I achieve a single place for debug-logging the contents of a gateway_config and/or gateway_debug structure (which happens at many places in connection.c), attribute the output to the appropriate call site and function, without copying-and-pasting the DBG to do so in every call site?” > > Absent the approach I took, the other alternative is to include a “from %s” in the format such that the log output ends up being: > > connmand[16689]: src/connection.c:gateway_data_debug() from __connman_connection_gateway_add() new_gateway 0x7471c060: { index: 4 (eth0), service: 0x72503240 (ethernet_0004f31a5ee0_cable), ipv4_config: 0x7471c030, ipv6_config: (nil), default_checked: 0 } > connmand[16689]: src/connection.c:gateway_config_debug() from __connman_connection_gateway_add() ipv4_config 0x7471c030: { flags: 0x0 (), gateway: 0x7511d7f0 (192.168.2.1), vpn_ip: (nil) (<null>), vpn_phy_index: -1 (<null>), vpn_phy_ip: (nil) (<null>) } > > which adds an extraneous bit of information which, since it doesn’t aid in debug or understanding, ends up being mental and visual “noise” and doesn’t further the debug goals. However, if that’s preferable to the approach I took, I’m happy to go that direction and recast the patches toward that end. Let me know if that’s an acceptable alternative. We currently only have the PRINT flag (and so does ELL btw), but the kernel has a lot more flags that define on how the output looks like and what information are printed. I would thing that is the way to go. Have a generic DBG statement and then decide from command line or some external input what gets printed in the debug logs. That said, I never thought about printing the call of the current function. That is a nice idea and in indeed really useful at times. So yes, we should have an option for that. >> The kernel has a nice concept with pr_fmt where you can overwrite pr_debug on a per file basis. I rather prefer that we adopt such a scheme. It will make things a lot simpler and have less boilerplate. > > I’d be happy to learn more and take a look. Do you have a link from the kernel git that demonstrates this? https://www.kernel.org/doc/html/next/core-api/printk-basics.html This would be a starting point. Essentially you define pr_fmt(fmt) and that modifies you pr_* type of functions. If you grep for pr_fmt than you see how different subsystems, drivers etc. define it and have specific information for their needs. For example for Bluetooth we did a real simple one: #define pr_fmt(fmt) "Bluetooth: “ fmt And that ends up providing the string Bluetooth: as prefix for every message printed. Was properly a bad idea, but this way we didn’t have to change any log messages we had. Some add KBUILD_NAME or the DRVNAME or other details in there. If you look at include/linux/dynamic_debug.h you see all the flags the kernel currently supports. #define _DPRINTK_FLAGS_NONE 0 #define _DPRINTK_FLAGS_PRINT (1<<0) /* printk() a message using the format */ #define _DPRINTK_FLAGS_INCL_MODNAME (1<<1) #define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2) #define _DPRINTK_FLAGS_INCL_LINENO (1<<3) #define _DPRINTK_FLAGS_INCL_TID (1<<4) #define _DPRINTK_FLAGS_INCL_SOURCENAME (1<<5) So I prefer to do something similar and then just modify these via a command line switch. Right now we basically just do a BLOB pattern, but we could do more. >> Long term this needs to get all into ELL and we need to use ELL debug functionality instead of having separate ones in each project. > > That seems like a great outcome and seems like it would work well with or without these patches: connman_debug_desc becomes ell_debug_desc, and generally anything connman_ or CONNMAN_ namespaced in log.h becomes ell_ or ELL_ namespaced and sourced from ell/log.h (or some such) rather than connman/log.h. > > CONNMAN_DEBUG aside, are you otherwise OK with the clean ups and documentation to log.h embodied in this patch? I am fine with all the cleanups, but I prefer you don’t introduce CONNMAN_DEBUG and stick with DBG instead and we try to figure out on how to make DBG work the way you want to use it. Regards Marcel
On Nov 29, 2023, at 10:18 AM, Marcel Holtmann <marcel@holtmann.org> wrote: >>>> This refactors the debugging / debug log preprocessor-related >>>> macros. In particular, it: >>>> >>>> * Introduces CONNMAN_DEBUG_DESC_INSTANTIATE which declares and >>>> instantiates an instance of 'connmand_debug_desc'. >>>> >>>> * Replaces CONNMAN_DEBUG_DEFINE with CONNMAN_DEBUG_ALIAS which >>>> declares and instantiates an alias (that is, asserts the >>>> CONNMAN_DEBUG_FLAG_ALIAS flag) instance of >>>> 'connmand_debug_desc', using CONNMAN_DEBUG_DESC_INSTANTIATE. >>>> >>>> * Introduces CONNMAN_DEBUG which declares and instantiates >>>> an instance of 'connmand_debug_desc', again using >>>> CONNMAN_DEBUG_DESC_INSTANTIATE, for controlling an invocation of >>>> 'connman_debug' with it that includes both the file and function >>>> name the macro was invoked in or attributed to. >>>> >>>> - The key difference between this and 'DBG' is that this allows >>>> the caller to specify the function string rather than relying on >>>> '__FUNCTION__' (or __func__). >>>> >>>> * Redefines 'DBG' against 'CONNMAN_DEBUG' with '__func__' as the >>>> function parameter. >>>> --- >>>> include/log.h | 34 +++++++++++++++++++++------------- >>>> src/log.c | 2 +- >>>> 2 files changed, 22 insertions(+), 14 deletions(-) >>> >>> I don’t like this since it ends up bloating the DBG part of it... >> >> CONNMAN_DEBUG aside, are you otherwise OK with the clean ups and documentation to log.h embodied in this patch? > > I am fine with all the cleanups, but I prefer you don’t introduce CONNMAN_DEBUG and stick with DBG instead and we try to figure out on how to make DBG work the way you want to use it. Resubmitted as a v2 patch with the suggested revisions. Best, Grant
diff --git a/include/log.h b/include/log.h index 8b00e9dc979c..fd47c8d53c9b 100644 --- a/include/log.h +++ b/include/log.h @@ -58,11 +58,27 @@ struct connman_debug_desc { unsigned int flags; } __attribute__((aligned(8))); -#define CONNMAN_DEBUG_DEFINE(name) \ - static struct connman_debug_desc __debug_alias_ ## name \ +#define CONNMAN_DEBUG_DESC_INSTANTIATE(symbol, _name, _file, _flags) \ + static struct connman_debug_desc symbol \ __attribute__((used, section("__debug"), aligned(8))) = { \ - #name, __FILE__, CONNMAN_DEBUG_FLAG_ALIAS \ - }; + .name = _name, .file = _file, .flags = _flags \ + } + +#define CONNMAN_DEBUG_ALIAS(suffix) \ + CONNMAN_DEBUG_DESC_INSTANTIATE(__debug_alias_##suffix, \ + #suffix, \ + __FILE__, \ + CONNMAN_DEBUG_FLAG_ALIAS) + +#define CONNMAN_DEBUG(function, fmt, args...) do { \ + CONNMAN_DEBUG_DESC_INSTANTIATE(__connman_debug_desc, \ + 0, \ + __FILE__, \ + CONNMAN_DEBUG_FLAG_DEFAULT); \ + if (__connman_debug_desc.flags & CONNMAN_DEBUG_FLAG_PRINT) \ + connman_debug("%s:%s() " fmt, \ + __FILE__, function, ##args); \ + } while (0) /** * DBG: @@ -72,15 +88,7 @@ struct connman_debug_desc { * Simple macro around connman_debug() which also include the function * name it is called in. */ -#define DBG(fmt, arg...) do { \ - static struct connman_debug_desc __connman_debug_desc \ - __attribute__((used, section("__debug"), aligned(8))) = { \ - .file = __FILE__, .flags = CONNMAN_DEBUG_FLAG_DEFAULT, \ - }; \ - if (__connman_debug_desc.flags & CONNMAN_DEBUG_FLAG_PRINT) \ - connman_debug("%s:%s() " fmt, \ - __FILE__, __FUNCTION__ , ## arg); \ -} while (0) +#define DBG(fmt, args...) CONNMAN_DEBUG(__func__, fmt, ##args) #ifdef __cplusplus } diff --git a/src/log.c b/src/log.c index 554b046b07fa..f7483194b230 100644 --- a/src/log.c +++ b/src/log.c @@ -38,7 +38,7 @@ static const char *program_exec; static const char *program_path; /* This makes sure we always have a __debug section. */ -CONNMAN_DEBUG_DEFINE(dummy); +CONNMAN_DEBUG_ALIAS(dummy); /** * connman_info:
This refactors the debugging / debug log preprocessor-related macros. In particular, it: * Introduces CONNMAN_DEBUG_DESC_INSTANTIATE which declares and instantiates an instance of 'connmand_debug_desc'. * Replaces CONNMAN_DEBUG_DEFINE with CONNMAN_DEBUG_ALIAS which declares and instantiates an alias (that is, asserts the CONNMAN_DEBUG_FLAG_ALIAS flag) instance of 'connmand_debug_desc', using CONNMAN_DEBUG_DESC_INSTANTIATE. * Introduces CONNMAN_DEBUG which declares and instantiates an instance of 'connmand_debug_desc', again using CONNMAN_DEBUG_DESC_INSTANTIATE, for controlling an invocation of 'connman_debug' with it that includes both the file and function name the macro was invoked in or attributed to. - The key difference between this and 'DBG' is that this allows the caller to specify the function string rather than relying on '__FUNCTION__' (or __func__). * Redefines 'DBG' against 'CONNMAN_DEBUG' with '__func__' as the function parameter. --- include/log.h | 34 +++++++++++++++++++++------------- src/log.c | 2 +- 2 files changed, 22 insertions(+), 14 deletions(-)