Unify chanserv logging (2020-07)

[aquesnel]

Merging pull request #792 with the most recent commit of devel.

I've created this pull request since pull request #792 seems to have been abandoned, and I am working on similar debug logging changes. Please let me know if there are still reasons why pull request #792 was not merged, so that I can address them.

[matt335672]

Great work @aquesnel !

I've got a few comments for you, all related to debugging:-

• The log_xxx() macros in some of the files used __func__ . This is a C99 feature (section 6.4.2.2 of the C99 standard). Without it, it's pretty hard to trace some of the debug messages back to their source. I think you can take it that __func__ is available on all current platforms as otherwise the compilers we use would be complaining.
• A lot of the LOG_LEVEL_DEBUG messages probably need to be LOG_LEVEL_TRACE, or even removed - running with LOG_LEVEL_DEBUG makes file redirection in particular slow to a crawl.

A relatively simple to run with LOG_LEVEL_DEBUG is:

• Create a session as normal.
• In a session terminal, pkill xrdp-sesman and sudo umount ~/thinclient_drives
• Restart chansrv in an ssh window from the same user with DISPLAY=:<num> CHANSRV_LOG_LEVEL=LOG_LEVEL_DEBUG /path/to/xrdp-chansrv
• Disconnect and reconnect the RDP client so that XRDP reconnects to chansrv.

The above isn't perfect but it gives you an idea of what's going on.

How important it is to solve this all right now is probably a question for @metalefty. It's pretty tricky for normal users to run with log level debug anyway.

Hope this is useful.

[aquesnel]

Thanks for the feedback @matt335672 . I'll likely have an update for this pull request based on your feedback next week (2020-07-20).

I'm thinking of adding the function and line numbers to the existing logging macro with something like what is described here:
http://www.decompile.com/cpp/faq/file_and_line_error_string.htm

I'm also thinking of adding the function and line numbers to the logs for all log statements when XRDP_DEBUG=true Is this a good idea?

I'm going to assume that all of the logging that used to go to the console should be at the TRACE level. I'll update the logging statements setting the level based on: DEBUG is for the sys admin to debug xrdp and TRACE is for the devs to debug xrdp. Is there any other guidance for the logging levels you want in the pull request?

next actions

• add a new logging macro that will no-op for XRDP_DEBUG=false and takes in the log level
• add function name and line numbers to existing log macros if XRDP_DEBUG=true
• reduce the log level to TRACE for log statements that are meant for the devs to debug a server
• verify logging is correct with the CHANSRV_LOG_LEVEL=LOG_LEVEL_DEBUG environment variable set (possibly set the variable based on config or from sesman logging level)

[matt335672]

Hi @aquesnel

I think your suggested approach to move existing console output to TRACE level is exactly right. We could spend ages debating exactly what and what not should be moved around here, but I think the pragmatic thing to do is sort out the general case first and get the developer output sorted out later, maybe when we're working on a particular feature.

I don't completely understand what you're proposing with the new logging macro based on XRDP_DEBUG. Can you illustrate with an example?

I've got some other more general comments which you may find useful:-

• log_message() is currently very slow. The reason is that the log file is opened with O_SYNC. This is done for good reasons, but it means there's a huge difference between writing to the unbuffered log file and writing to stdout which will be buffered.
• I've found myself that when you're working on chansrv, you tend to be working on a particular feature like file redirection or cut/paste. Turning on full logging in these situations is not helpful. It's handy to be able to turn the debugging output up for a particular module, by maybe adding #define XRDP_DEBUG at the top of a file and removing it when you're done. That's a use case that would be useful to cover somehow, although there may well be better mechanisms to do it.
• I apologise if you're aware of this already, but there's a bit of a complication with __func__.
  It's not a macro (unlike __FILE__ and __LINE__) - it's a static const char * the compiler generates if it's asked to do so. That can restrict your options when using macros - the STRINGIFY example from your link won't work with this variable.

I hope that's useful - let me know if you've any queries.

[aquesnel]

Hi @matt335672,

I'm a Java programmer in my day job and it's been a long time since I've worked in C, so letting me know that __func__ is not like __FILE__ just saved me a lot of debugging, thanks.

My plan for adding function and line number when XRDP_DEBUG=true is to do something like:

#ifdef XRDP_DEBUG
#define LOG(args...) log_message_with_location(__func__, __LINE__, args); 
#else
#define LOG(args...) log_message(args); 
#endif

For logging from a single module, I'd normally think of filtering the logging with a config value (like the log4j logger config) but that's too complex for what's here. I'll brainstorm something and get back to you with a simpler solution. Maybe I'll add a macro like FORCE_LOGGING that can be defined in any file that to have logging enabled, or maybe add some simple config in the existing ini file.

[matt335672]

OK - that's clearer thanks.

You might also find it useful when retro-fitting the TRACE stuff to add a LOG_LOC() macro (or whatever name suits. LOGT()?) which unconditionally calls log_message_with_location(). It might make your job a little easier.

As regards reading the config file, I've just put in a PR #1635 which adds a config module to chansrv. If @metalefty 's happy with it it might make parsing the config file easier to do.

[aquesnel]

Hi @matt335672,

I think I've addressed all of your feedback, please let me know if there is anything that I missed or there is any feedback for my modifications.

Also, I've been having a hard time reproducing the errors that are causing the travisci builds to fail when I build on my dev machine. When I run with following config I get an error in code that I haven't touched, and the travisci builds don't seem to build the common/pixman-region.c file.

./configure --prefix=/home/aquesnel/xrdp-install --enable-strict-locations=yes --with-systemdsystemunitdir=no --enable-xrdpdebug --disable-pam --enable-fuse && make clean && make CFLAGS="$CFLAGS -Wall -Wwrite-strings -Werror"

...
Making all in common
make[2]: Entering directory '/home/aquesnel/xrdp-dev/xrdp/common'
...
  CC       pixman-region16.lo
pixman-region.c: In function ‘pixman_region_fini’:
pixman-region16.c:62:19: error: implicit declaration of function ‘pixman_region_selfcheck’ [-Werror=implicit-function-declaration]
 #define PREFIX(x) pixman_region##x
                   ^
pixman-region.c:97:14: note: in expansion of macro ‘PREFIX’
         if (!PREFIX (_selfcheck (reg)))                                 \
              ^~~~~~

I've been trying to work around this issue by building only the chansrv with the warnings as errors flags, but it's a pain.

make clean && make && touch sesman/chansrv/chansrv.h && make CFLAGS="$CFLAGS -Wall -Wwrite-strings -Werror"

Please let me know if there is a better way to reproduce the travisci builds on my dev machine.

progress report

• DONE add a LOG_DBG macro that will no-op for XRDP_DEBUG=false and takes in the log level
• DONE add function name and line numbers to existing log macros if XRDP_DEBUG=true
• DONE migrate all LOGM, and log_xxx in chansrv to use the common LOG or LOG_DBG macros
• SKIPPED reduce the log level to TRACE for log statements that are meant for the devs to debug a server
  • I left the log levels as is since when I went to change the log levels it there was a lot of inconsistency and the log levels looked fine as is
• DONE verify logging is correct with the CHANSRV_LOG_LEVEL=LOG_LEVEL_TRACE environment variable set
• SKIPPED logging from a single module
  • adding #define XRDP_DEBUG at the top of a file will enable all of the log macros in that file as suggested by @matt335672 or grep'ing the log file by module's file name will also filter the logging so I'm not planning to add another mechanizm to filter the logs in this pull request

[matt335672]

Hi @aquesnel,

The compile error you're seeing is being caused by the odd way that pixman-region.c and pixman-region16.c are related and are compiled. I came across it myself a couple of weeks ago when I was getting the cppcheck 2.x stuff sorted out. It's not at all intuitive and probably needs to be fixed.

The way it currently works is:-

• pixman-region.c is not a separately compilable file.
• pixman-region16.c defines the PREFIX macro amongst other things, and then includes pixman-region.c. This composite file is what the compiler sees.
• The PREFIX macro simply replaces its argument x with the string pixman_regionx

I hope that's clear enough - it wasn't to me for some time!

The error you're seeing is a consequence of XRDP_DEBUG being defined which in turn causes the GOOD macro to be defined. This invokes PREFIX(_selfcheck(reg)) which expands to pixman_region_selfcheck(reg). The warning results as the pixman_region_selfcheck function isn't defined.

A simple fix is to add the function prototype to the affected codepath:-

--- a/common/pixman-region.c
+++ b/common/pixman-region.c
@@ -91,6 +91,8 @@
 
 #ifdef XRDP_DEBUG
 
+pixman_bool_t PREFIX(_selfcheck) (region_type_t *reg);
+
 #define GOOD(reg)                                                       \
     do                                                                  \
     {                                                                   \

The compilation then generates further warnings I'm afraid in the sesman directory but they look pretty trivial.

Replicating Travis CI on a local machine is quite tricky. Another way is register your own github repo with travis-ci.org directly and then any private branches you push to it with get scanned for you.

Hope that's useful.

[matt335672]

I've had a quick run of your changes, and that's certainly fixed the performance issues with setting a DEBUG level.

One comment so far - there's a bit or a name clash between LOG_DBG() and LOG_LEVEL_DEBUG. We've got a long-term goal (as yet unvoiced) to make the code more readable to non-English developers, so we're trying to avoid (and remove) things like double-negatives and unnecessary confusion.

Could I suggest replacing LOG_DBG with something like LOG_DEVEL? I like your idea of splitting debug logging between something a sysadmin might enable and something a developer might enable and I think this makes the intention more explicit.

Thanks.

[aquesnel]

@matt335672 I like the name LOG_DEVEL I'll make that change next.

[aquesnel]

Hi @matt335672,

I've registered my repo with travisci and that helped make a clean build. I didn't realize that I could register my repo for builds too, so thanks for the pointer.

I'm all for making code easier to understand. One of my first team leads had a rule for making code easier to understand that I live by now: "an acronym or abbreviation is only allowed in the code if it is commonly used by a layman (eg. 'id' is allowed, but ODSL is disallowed)"

I've implemented the renaming from LOG_DBG to LOG_DEVEL, and I think it's a lot clearer when each macro should be used. When I was madding LOG_DBG in the previous commits I was asking myself "should this debug log message be LOG_DBG or LEVEL_DEBUG" and this renaming bypasses the question quite clearly. I've added some documentation to the logging macros to try and make this usage of the macros consistent in the future. This past weekend I'd made a script to make the log renaming the changes for the various log methods, so once this pull request is merged, I plan on making another pull request for unifying the logging in the rest of the code.

Please let me know if there is any other feedback before this pull request is ready to be merged.

[matt335672]

Hi @aquesnel

Thanks again for all your work on this - it's been outstanding for a while,

I've had a quick look at the comments and that helps a lot. One thing you could do is make then Doxygen compatible (if you're familiar with the tool). I'm hoping to move in that direction eventually so we can get some better generated docs. If you're not familiar I wouldn't worry too much as we're going to need to do a bit of a retro-fit anyway to all sorts of things.

@metalefty will need to review this before it's merged, and I know he's not available for a week or two. He'll probably want you to squash your commits, but it's probably worth holding off on that until he's had a look at the history.

[aquesnel]

Hi @matt335672 ,

I've updated the documentation for the LOG and LOG_DEVEL macros so they should work with doxygen.

I've also added additional logging config options:

• enable console logging
• console logging level
• enable pid and thread in in the logs
• enable per source file log level overrides

Please let me know if there is any other feedback before this pull request is ready to be merged.

progress report

• DONE logging config for logging from a single module/source file
• DONE logging documentation in the doxygen format

[matt335672]

Nothing from me - @metalefty will need to take a look at this before the merge happens.

Thanks again for all your work on this.

[metalefty]

Thanks, I'll have a look within a few days.

[metalefty]

I haven't tested your work yet however it seems a big update. So I'm thinking of merging this after the August release.
0.9.14 will be released this month.

[aquesnel]

Hi @metalefty ,

That sounds reasonable to merge this change after this month's release.

I didn't see any tests in the repo, so I've just been verifying my changes by compiling and manually running the code. Do you have another way to test changes?

When you have time, could you please let me know if these changes are ok, since these changes are different than the logging clean up that you outlined in the Reworking logs wiki page.

If the changes are ok, then I'll go ahead and work on migrating the logs in the rest of the repo to these new unified log macros while the merge is pending.

Also, as you mentioned the change being large, and I'm proposing making more large changes to migrate the other log statements, do you have a preference on how i organize the pull requests? I'm planning on submitting one pull request for the log migration of each directory in the repo. Let know if there is another way that I can make your review of the changes easier.

Thanks

[matt335672]

@metalefty - I've got another (small) fix identified in #1658 which conflicts with this one and I think this one should go in first.

@aquesnel - could you add a quick summary of where your changes are at odds with the Reworking logs wiki page? We can then agree how to work through the differences.

Thanks both.

[aquesnel]

@matt335672

The difference between this pull request and the Reworking logs page is:

• All alias macros are removed and only the log_message(log_level, message) remain
• added LOG_DEVEL() which is enabled only for XRDP_DEBUG
• log_trace_verbose() is replaced by LOG_DEVEL(LOG_LEVEL_TRACE, ...)
• Converting table changed:

before	after
g_writeln()	LOG_DEVEL(LOG_LEVEL_TRACE, ...)
DEBUG()	LOG_DEVEL(LOG_LEVEL_TRACE, ...)
LLOGLN(0, )	LOG_DEVEL(LOG_LEVEL_INFO, ...)
LLOGLN(10, )	LOG_DEVEL(LOG_LEVEL_DEBUG, ...)
LOG_DBG()	LOG_DEVEL()
LOGM()	LOG_DEVEL()
DLOG()	LOG_DEVEL(LOG_LEVEL_TRACE, ...)
log_message()	LOG()
HEXDUMP()	LOG_DEVEL_HEXDUMP()

Also I've added a few logging features which are not conflicting with the Reworking logs page:

• Added file name, line number, and function name to all log messages only when XRDP_DEBUG is enabled
• Added filtering log messages with log level on a per function or file name basis from config file only when XRDP_DEBUG is enabled
• Added console logging enable/disable option in the config file

[aquesnel]

Hi @metalefty

Now that 0.9.14 has been released, can you please take a look at this pull request and let me know if you have any feedback for this change to get merged?

Thanks

[metalefty]

Sure. There's some pending pull requests. We'll process one by one. Thank you very much for your great work.

[metalefty]

@matt335672 anything else from you?

[matt335672]

I'm just running through some additional testing, and I can see I'll have a few minor questions/queries. I'm a bit strapped for time today sadly, so I'll report back tomorrow.

[matt335672]

The only significant comments I have are around the new comment at the top of log.h:-

 * Note: when the build is configured with --disable-xrdpdebug, then 
 *      the source file name and log level can be added to the [Logging_PerLogger]
 *      section of xrdp.ini to change the logging level for logs in that source file.
 * 
 *      For example in xrdp.ini:
 *      ```     
 *      [Logging_PerLogger]
 *      xrdp.c=DEBUG
 *      ```

Two minor comments:-

• Shouldn't --disable-xrdpdebug be --enable-xrdpdebug?
• The ini file isn't always xrdp.ini

A more major question is that this looks like a useful feature, but it's not going to be available to chansrv, because this doesn't use log_start(). I couldn't see a simple fix for this. We could either accept this as a limitation at this stage, or look for another way to provide the feature, like parsing environ to find suitably formatted environment variables.

[aquesnel]

hi @matt335672

That's a good point that I've added log filtering, but it's not usable for the chansrv. I've fixed this up so that chansrv can initialize the logs just like sesman, from the sesman config.

fixed

• fixed logging docs
• refactored the logging initialization so that chansrv can initialize the logging config from the sesman.ini config

TODO

• fixup the chansrv log init code so that it's backwards compatible with using the CHANSRV_LOG_LEVEL environment variable
• update the docs for the CHANSRV_LOG_LEVEL variable and chansrv logging
• check if sesman can stop setting the CHANSRV_LOG_LEVEL environment variable

[aquesnel]

I think I've made the chansrv logging behaviour backwards compatible with the log level environment variable and syslog. I've also added the [Chansrv_Logging] section to the sesman.ini file to enable independent logging configuration of sesman and chansrv.

[aquesnel]

Hi @matt335672 and @metalefty ,
I've squashed the commits on top of devel.

[metalefty]

Hi, I'm been away for a while. I'll do a quick test today.

[metalefty]

I don't like _ (underscore) here. SessionVariables is spelled camel case.

[aquesnel]

Fixed in commit 65347e4 to use camel case for the config names.

[metalefty]

It breaks login screen.

xrdp_wm.c also needs to be cared.

[aquesnel]

Sorry, I've been testing with auto login enabled, I'll make sure to test with the login screen.

I should have time this weekend to fix this.

[aquesnel]

Hi @metalefty ,

I've fixed the login screen issue and I've squashed the fix and rebased on top of devel. Please let me know if there are any other issues that I need to fix before merging.

[aquesnel]

Hi @metalefty ,
Sorry, I missed your comment about the _ in the config variable name when I submitted the previous rebase. I've updated the code to follow the camel case naming convention as you suggested and resubmitted the squash and rebased on top of devel.

Please let me know if there are any other issues that I need to fix before merging.

[metalefty]

LGTM. Let's merge it. If we found some additinal things needs to be fixed, it can be done later.

[metalefty]

@aquesnel Thank you very much for your work and spending a lot of time on xrdp!