Unify logging in sesman #1708

aquesnel · 2020-10-24T18:15:21Z

Follow-on pull request to #1633 which migrates all logging in sesman to use the LOG() and LOG_DEVEL() macros.

matt335672 · 2020-10-26T09:46:24Z

Thanks very much for this. I was half expecting it it show up soon!

I've just run a few textual modifications, and I'm pretty sure that the vast majority of this PR, with the exception of chansrv/smartcard_pcsc.c is just replacing log_message function calls with LOG macro invocations. Is that correct?

Assuming it is, we can focus the discussion on chansrv/smartcard_pcsc.c. Comments are:-

The majority of the LLOGLN(0, calls you've replaced (rather than the 10, variety) are generally reporting errors, and so should probably be replaced with LOG(LOG_LEVEL_ERROR,. Exceptions are the calls at lines 1703, 1747, 1751, 1755, 1842 and 1885 which look like they should be LOG_DEVEL.
There's a call to g_hexdump() at line 491 which is part of the error reporting / debugging mechanism. We could add similar functionality to the logging module, but given this won't be needed a lot, the simplest thing might be to comment out this line for now (as as been done elsewhere, I've just noticed).

aquesnel · 2020-10-26T10:01:10Z

@matt335672 ,

Yes you are correct, this commit was created by running a find and replace over the code. I created a shell script to handle the weirdness of the double parenthesis of some of the old macros. I can post this script or add it to the pull request if you think it's worth it.

For this change I assumed that the previous log levels were correct, and I'm happy to fix them up.

For the hex dump, I've already written a log hex dump function and macro, but I didn't include it in pull request since I hadn't seen a hex dump used in any of the files. I'll just include the function in this pull request.

matt335672 · 2020-10-26T10:29:27Z

I don't think we need the script - this particular file is easy enough to review manually in any case.

The hex dump was a surprise to me too - I've not seen it before but I can see where it would be useful.

aquesnel · 2020-11-01T05:20:52Z

Hi @matt335672 ,

I've updated the code to include the LOG_DEVEL_HEXDUMP function and I've fixed up the log levels for chansrv/smartcard_pcsc.c. Please let me know if you have more feedback.

matt335672 · 2020-11-02T10:37:10Z

Hi @aquesnel,

That's great - thanks.

A couple of general points:-

I like where you're going with this. think it makes sense to concentrate on your changes here and leave some other sesman changes (Add -c/--config option to sesman #1650 Add log_config_init_for_console() for utilities #1711) until we've got this one merged - they'll probably need tweaking to fit in with this one.
Predating your involvement in this project, there's a lot of private stuff in log.h which could be moved to log.c. I'd like to get this fixed at some stage, but I think it should be done as a separate PR later on. I'd be happy to work with you on getting that done. Does that sound reasonable to you?

Also, with reference to log.c, could I ask you to look at the astyle utility? It's mentioned in the XRDP [coding standard] (/neutrinolabs/xrdp/wiki/Coding-Style) and it's very useful at tidying up shared code. As part of this PR, it would be good to get log.c formatted with it. The way it could be used here is:-

define ARTISTIC_STYLE_PROJECT_OPTIONS=astyle_config.as
astyle log.c\*

The wildcard looks a bit odd, but is necessary with a single file. One hint I'll give is around line 729 where you've got dump_line_length =, you might need to add braces () around the expression or it will line everything up on the left.

I'll get on with a review of the code now. I might be a bit pressed for time over the next couple of days with family duties.

matt335672

Looking good. I'll run some tests when changes are done. Thanks again.

matt335672 · 2020-11-02T11:02:40Z

common/log.c

+            if(logger->log_level < log_level)
+            {
+                return 0;
+            }
+            else
+            {
+                return 1;
+            }


Wouldn't return (log_level <= logger->log_level) be a simpler way to express this?

agreed, fixed

matt335672 · 2020-11-02T11:03:51Z

common/log.c

+    }
+
+    dump_line_length = 4 + 3             /* = 4 offset + 3 space */
+                       + ((2 + 1) * 16)  /* + (2 hex + 1 space) per byte for 16 bytes */


Suggest making the 16 a macro as it's used a lot.

agreed, fixed

matt335672 · 2020-11-02T11:18:55Z

sesman/chansrv/smartcard_pcsc.c

    if (uds_client_id == 0)
    {
-        LLOGLN(10, ("get_uds_client_by_id: uds_client_id zero"));
+        LOG_DEVEL(LOG_LEVEL_ERROR, "get_uds_client_by_id: uds_client_id zero");


Replace LOG_DEVEL with LOG in all places where LOG_LEVEL_ERROR is used in this file.

I'm not sure what a sysadmin will do with the log messages like "ERROR: uds_client_id is zero", since this seems more like a bug than a misconfiguration.
I'm deferring to you that having these messages in the release version's log makes sense.

Fair point! It's a poor message, but probably better than nothing at all.

matt335672 · 2020-11-02T11:25:20Z

common/log.c

+       aligned to the first column instead of to after the log message 
+       preamble (eg. time, log level, ...)
+    */
+    g_sprintf(dump_buffer, "%%s Hex Dump:");


Extra comment which I managed to lose in the review:-

Suggest making "%s Hex Dump:\n" a macro like this:-

#ifdef _WIN32 #define HEX_DUMP_HEADER "%s Hex Dump:\r\n" #else #ifdef _MACOS #define HEX_DUMP_HEADER "%s Hex Dump:\r" #else #define HEX_DUMP_HEADER "%s Hex Dump:\n" #endif #endif #define HEX_DUMP_HEADER_SIZE (sizeof(HEX_DUMP_HEADER) - 1)

I'm sure you get the idea. You can them remove the magic number 12.

agreed, fixed

aquesnel · 2020-11-13T06:50:42Z

Hi @matt335672 ,

I've been trying to get astyle to format the log.c file nicely but I haven't figured out a non-hacky way to get the split dump_line_length = line to line up indented.

Diff pre- vs post- astyle formatting:

     dump_line_length = 4 + 3             /* = 4 offset + 3 space */
-                       + ((2 + 1) * 16)  /* + (2 hex + 1 space) per byte for 16 bytes */
-                       + 2 + 16 + 1;     /* + 2 space + 16 bytes as chars + 1 newline */
+    + ((2 + 1) * 16)  /* + (2 hex + 1 space) per byte for 16 bytes */
+    + 2 + 16 + 1;     /* + 2 space + 16 bytes as chars + 1 newline */

My problem is similar to this stack overflow question but the links to the astyle bug report is broken.

I've done my own debugging and been able to trace this down to having the word "enum" in the return type of the function that is being formatted. When I replace the enum with a typedef or macro for that enum, then astyle formats the split line with the expected indentation. This looks like a bug in astyle mis-identifying the function as an enum or something. The only thing I have found in the is a reference in the astyle release notes for 2.05.1 for "Fix error in identifying an enum return type as an enumeration"

I've tried running with astyle version 2.06 and with 3.1. The 3.1 version does a better formatting job overall, but it still lines up the split dump_line_length line to the left.

My plan is to make a typedef for enum log_config then just use that everywhere. I'll also add a note to the Coding-Style wiki page about this issue.

Do you have a different suggestion for how to workaround this astyle issue?

matt335672 · 2020-11-13T10:49:56Z

Hi @aquesnel

Yes I do. I'd mentioned it above but re-reading my comment I could have been clearer. If you add parentheses around the whole expression astyle will behave differently.

Try this (adjust to taste):-

    dump_line_length = (4 + 3 +           /* = 4 offset + 3 space */
                        ((2 + 1) * 16) + /* + (2 hex + 1 space) per byte for 16 bytes */
                        2 + 16 + 1);     /* + 2 space + 16 bytes as chars + 1 newline */

I'm using astyle 3.1.

Try that and let me know how you get on.

aquesnel · 2020-11-14T16:53:38Z

Hi @matt335672 ,

I had originally tried adding braces as you suggested around the dump_line_length line, but apparently astyle 2.06 has a bug that causes it to not indent the braced split line when a function returns an enum. This bug is fixed in astyle 3.1 so I'll add a note to the Coding-Style wiki page to say that astyle 3.1 or above should be used.

I've also run astyle on all of the .c files in sesman/* since most of the formatting errors are caused by the logging changes. I skipped the following files because:

sesman/chansrv/chansrv_fuse.c: the non-logging formatting changes were non-trivial and you have recently been working on fuse, so I didn't want to introduce a bunch of changes.
sesman/chansrv/pcsc/wrapper/winscard.c: no logging changes were made to this file
sesman/chansrv/pcsc/xrdp_pcsc.c: no logging changes were made to this file

Please let me know if you have any concerns with the additional code formatting.

matt335672 · 2020-11-16T10:07:24Z

Hi @aquesnel

Thanks for that.

I've approved the changes I've requested, and I've run your hexdump code through a test rig. It all looks fine to me.

One small change you might like to consider is adding a call for the g_malloc() failing. We had a security advisory CVE-2020-4044 last year which exposed a number of ways in which sesman could be caused to crash. This can then be exploited to harvest passwords.

As it stands, an attacker managing to get a large value into the log_hexdump_with_location() could cause a memory overflow and a crash. That's not a major consideration at the moment as your code is currently for debugging only. However, since it's clearly a useful function, I can see it over time being used for non-debug logging purposes, and then we might have a problem.

Personally I'm happy that you've run the rest of the sesman code through astyle. It's a good time to do it as all the logging macros are changing too, so I can't see it causing any more upheaval than this PR would anyway. It makes checking code before commit a lot easier in the future,

@metalefty - are you happy with asyle being run on sesman in this way?

aquesnel · 2020-11-24T04:58:11Z

Hi @metalefty ,

Do you have any concerns or feedback for this pull request that you think should be addressed before this can be merged?

metalefty · 2020-11-30T02:47:11Z

Let's merge.

aquesnel mentioned this pull request Nov 1, 2020

Add log_config_init_for_console() for utilities #1711

Merged

matt335672 requested changes Nov 2, 2020

View reviewed changes

matt335672 reviewed Nov 2, 2020

View reviewed changes

matt335672 approved these changes Nov 16, 2020

View reviewed changes

Migrating logging to LOG() and LOG_DEVEL() in sesman/*

0c61a15

aquesnel force-pushed the unify_sesman_logging branch from 42923b0 to 0c61a15 Compare November 30, 2020 00:40

metalefty merged commit 28c35f9 into neutrinolabs:devel Nov 30, 2020

aquesnel deleted the unify_sesman_logging branch November 30, 2020 03:12

aquesnel mentioned this pull request Dec 15, 2020

Fixing code location log level filtering #1753

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unify logging in sesman #1708

Unify logging in sesman #1708

aquesnel commented Oct 24, 2020

matt335672 commented Oct 26, 2020

aquesnel commented Oct 26, 2020

matt335672 commented Oct 26, 2020

aquesnel commented Nov 1, 2020

matt335672 commented Nov 2, 2020

matt335672 left a comment

matt335672 Nov 2, 2020

aquesnel Nov 14, 2020

matt335672 Nov 2, 2020

aquesnel Nov 14, 2020

matt335672 Nov 2, 2020

aquesnel Nov 14, 2020

matt335672 Nov 16, 2020

matt335672 Nov 2, 2020

aquesnel Nov 14, 2020

aquesnel commented Nov 13, 2020 •

edited

Loading

matt335672 commented Nov 13, 2020

aquesnel commented Nov 14, 2020

matt335672 commented Nov 16, 2020

aquesnel commented Nov 24, 2020

metalefty commented Nov 30, 2020

Unify logging in sesman #1708

Unify logging in sesman #1708

Conversation

aquesnel commented Oct 24, 2020

matt335672 commented Oct 26, 2020

aquesnel commented Oct 26, 2020

matt335672 commented Oct 26, 2020

aquesnel commented Nov 1, 2020

matt335672 commented Nov 2, 2020

matt335672 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aquesnel commented Nov 13, 2020 • edited Loading

matt335672 commented Nov 13, 2020

aquesnel commented Nov 14, 2020

matt335672 commented Nov 16, 2020

aquesnel commented Nov 24, 2020

metalefty commented Nov 30, 2020

aquesnel commented Nov 13, 2020 •

edited

Loading