feat: downgrade logging level when AppMap recording is enabled #183

symwell · 2022-10-19T20:18:34Z

Don't show noise in the console.

Show a warning when the agent does something I'm not necessarily expecting, or when I've made a mistake. So, if set APPMAP=true, or APPMAP=false, or one of the APPMAP_RECORD_ variables is set to true or false, log at info.
If any of those variables is set to a value other than true or false, write a message at warning. This is new behavior.
Make the comparison with true or false be case-insensitive. Before it was done with == "true" and == "false".
If there's an environment variable that starts with the prefix APPMAP_RECORD_ but doesn't match one of the supported recording types, log a message at warning. This is also new behavior.
We've gone back and forth about what level to use when recording by default. On balance, we should log this message at info: it's presumably exactly the behavior they were hoping for when they installed the agent, and they'll see all the AppMaps that got generated.

Fixes #182.

Tested with poetry run pytest -s -v appmap/test/test_django.py.

apotterri · 2022-10-20T14:32:12Z

Can you add something (Loom, asciinema, copy-and-paste terminal session, whatever) that shows the output for each of the new cases, please?

symwell · 2022-10-20T14:56:54Z

I would like to check this with testcases.

I changed the testcases to assert the logger output. I found that WARNING output gets produced as expected but INFO output isn't. I thought the logger was configured to not show INFO output but after changing that in both testcases and in detect_enabled.py I don't see any INFO output even though code execution gets to the logger.info statement.

symwell · 2022-10-20T16:42:06Z

Not seeing INFO output is a bug in pytest. I reproduced it with the instructions from here.

However, it works with with caplog.at_level(logging.INFO): in the instructions but not in test_detect_enabled.py

apotterri · 2022-10-20T17:47:43Z

I would like to check this with testcases.

I agree that it's important to verify it with testcases. But, I'd also like to see what the user experience is actually going to look like, as seen in a terminal.

symwell · 2022-10-20T17:49:42Z

Tested through this repo https://github.com/symwell/try_appmap_python

APPMAP=true, master (before)

PYTHONPATH=/home/test/src/appmap-python APPMAP=true python3 -m appmap.unittest program_test.py
[2022-10-20 13:07:44,163] WARNING appmap._implementation.detect_enabled: AppMap recording is enabled because APPMAP=true
WARNING:appmap._implementation.detect_enabled:AppMap recording is enabled because APPMAP=true
.
----------------------------------------------------------------------
Ran 1 test in 0.023s

OK

APPMAP=true, sw/dont_show_warning_when_appmap_is_enabled (after)

PYTHONPATH=/home/test/src/appmap-python APPMAP=true python3 -m appmap.unittest program_test.py
.
----------------------------------------------------------------------
Ran 1 test in 0.023s

OK

APPMAP=false, master (before)

PYTHONPATH=/home/test/src/appmap-python APPMAP=false python3 -m appmap.unittest program_test.py
WARNING:__main__:AppMap disabled. Did you forget to set APPMAP=true?
[2022-10-20 13:10:29,134] WARNING appmap.unittest: AppMap disabled. Did you forget to set APPMAP=true?
WARNING:appmap.unittest:AppMap disabled. Did you forget to set APPMAP=true?
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

APPMAP=false, sw/dont_show_warning_when_appmap_is_enabled (after)

PYTHONPATH=/home/test/src/appmap-python APPMAP=false python3 -m appmap.unittest program_test.py
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

APPMAP=invalid, master (before)

PYTHONPATH=/home/test/src/appmap-python APPMAP=invalid python3 -m appmap.unittest program_test.py
[2022-10-20 13:46:11,338] WARNING appmap._implementation.detect_enabled: AppMap recording is enabled because will record by default
WARNING:appmap._implementation.detect_enabled:AppMap recording is enabled because will record by default
.
----------------------------------------------------------------------
Ran 1 test in 0.023s

OK

APPMAP=invalid, sw/dont_show_warning_when_appmap_is_enabled (after)

PYTHONPATH=/home/test/src/appmap-python APPMAP=invalid python3 -m appmap.unittest program_test.py
AppMap recording is not enabled because APPMAP=invalid is an invalid option.
AppMap recording is not enabled because APPMAP=invalid is an invalid option.
AppMap recording is not enabled because APPMAP=invalid is an invalid option.
AppMap recording is not enabled because APPMAP=invalid is an invalid option.
[2022-10-20 13:43:02,650] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP=invalid is an invalid option.
[2022-10-20 13:43:02,650] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP=invalid is an invalid option.
[2022-10-20 13:43:02,650] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP=invalid is an invalid option.
[2022-10-20 13:43:02,650] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP=invalid is an invalid option.
[2022-10-20 13:43:02,753] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP=invalid is an invalid option.
WARNING:appmap._implementation.detect_enabled:AppMap recording is not enabled because APPMAP=invalid is an invalid option.
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

APPMAP_RECORD_INVALID=true, master (before)

PYTHONPATH=/home/test/src/appmap-python APPMAP_RECORD_INVALID=true python3 -m appmap.unittest program_test.py
[2022-10-20 13:48:59,467] WARNING appmap._implementation.detect_enabled: AppMap recording is enabled because will record by default
WARNING:appmap._implementation.detect_enabled:AppMap recording is enabled because will record by default
.
----------------------------------------------------------------------
Ran 1 test in 0.023s

OK

APPMAP_RECORD_INVALID=true, sw/dont_show_warning_when_appmap_is_enabled (after)

PYTHONPATH=/home/test/src/appmap-python APPMAP_RECORD_INVALID=true python3 -m appmap.unittest program_test.py
AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
[2022-10-20 13:49:24,044] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
[2022-10-20 13:49:24,044] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
[2022-10-20 13:49:24,044] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
[2022-10-20 13:49:24,044] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
[2022-10-20 13:49:24,147] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
WARNING:appmap._implementation.detect_enabled:AppMap recording is not enabled because APPMAP_RECORD_INVALID is an invalid recording method.
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

I think after the latest change stuff gets printed 5 times.

symwell · 2022-10-20T20:10:57Z

Added screenshots and changed one more testcase now that a warning isn't printed.

apotterri · 2022-10-20T22:18:28Z

It doesn't seem ideal to print the same message multiple times. Can we do something about that?

symwell · 2022-10-21T12:45:23Z

It also prints the warning without WARNING in front of it. Looking into this part.

Got it to print the warning only once.

symwell · 2022-10-21T16:27:05Z

Screenshot diffs.
Top is master
Bottom is sw/dont_show_warning_when_appmap_is_enabled

APPMAP=true

APPMAP=false

APPMAP=invalid

APPMAP_RECORD_INVALID=true

APPMAP_RECORD_REQUESTS=true

APPMAP_RECORD_REQUESTS=false

symwell · 2022-10-21T17:08:03Z

APPMAP_RECORD_UNITTEST shows a duplicate log on stdout without the formatted datetime.

PYTHONPATH=/home/test/src/appmap-python APPMAP_RECORD_UNITTEST=invalid python3 -m appmap.unittest program_test.py
[2022-10-21 13:04:24,539] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_UNITTEST=invalid is an invalid option.
WARNING:appmap._implementation.detect_enabled:AppMap recording is not enabled because APPMAP_RECORD_UNITTEST=invalid is an invalid option.
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK

APPMAP_RECORD_PYTEST doesn't.

test@o[2022-10-21_14:43:02]:~/src/try_appmap_python$ PYTHONPATH=/home/test/src/appmap-python APPMAP_RECORD_PYTEST=invalid python3 -m appmap.unittest program_test.py
[2022-10-21 14:43:17,670] WARNING appmap._implementation.detect_enabled: AppMap recording is not enabled because APPMAP_RECORD_PYTEST=invalid is an invalid option.
.
----------------------------------------------------------------------
Ran 1 test in 0.023s

OK

Interesting: if the call to logger.isEnabledFor(log_level) is removed then no warning is shown.

APPMAP_RECORD_UNITTEST enters _configure_logging twice before logging its warning.
APPMAP_RECORD_PYTEST enters _configure_logging once before logging its warning and once after.

In either case why is _configure_logging called twice? I'm looking into this.
update: After turning Env into a singleton, which gets _configure_logging called only once, the warning issue persisted.

appmap/_implementation/configuration.py

symwell · 2022-10-21T21:06:28Z

Created separate issue to address configuring logging for APPMAP_RECORD_UNITTEST.

apotterri

Please fix the body of the comment on the comment so it describes the change you made.

Show a warning when the agent does something the user is not necessarily expecting, or when the user made a mistake. So, if APPMAP=true or APPMAP=false or one of the APPMAP_RECORD_ variables is set to true or false, log at "info". If any of those variables is set to a value other than true or false, log at "warning". This is new behavior. Make the comparison with true or false be case-insensitive. Before it was done with '== "true"' and '== "false"'. If there's an environment variable that starts with the prefix APPMAP_RECORD_ but doesn't match one of the supported recording types, log a message at "warning". This is also new behavior. When recording by default log at "info": it's presumably exactly the behavior the user was hoping for when they installed the agent, and they'll see all the AppMaps that got generated.

apotterri

Looks good, thanks for making this update.

symwell requested a review from apotterri October 19, 2022 20:18

symwell force-pushed the sw/dont_show_warning_when_appmap_is_enabled branch from 7ff3b12 to ed511f8 Compare October 20, 2022 19:40

apotterri reviewed Oct 21, 2022

View reviewed changes

appmap/_implementation/configuration.py Show resolved Hide resolved

symwell mentioned this pull request Oct 21, 2022

Fix logging configuration to not print logs twice (one with datetime, one without) #185

Closed

symwell force-pushed the sw/dont_show_warning_when_appmap_is_enabled branch 2 times, most recently from a092023 to 7f37bbb Compare October 24, 2022 15:04

symwell requested a review from apotterri October 25, 2022 13:44

apotterri suggested changes Oct 25, 2022

View reviewed changes

symwell force-pushed the sw/dont_show_warning_when_appmap_is_enabled branch from 7f37bbb to f763eb6 Compare October 25, 2022 18:10

apotterri approved these changes Oct 25, 2022

View reviewed changes

symwell merged commit 40690e6 into master Oct 25, 2022

symwell deleted the sw/dont_show_warning_when_appmap_is_enabled branch October 25, 2022 19:24

feat: downgrade logging level when AppMap recording is enabled #183

feat: downgrade logging level when AppMap recording is enabled #183

Uh oh!

Conversation

symwell commented Oct 19, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

apotterri commented Oct 20, 2022

Uh oh!

symwell commented Oct 20, 2022

Uh oh!

symwell commented Oct 20, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

apotterri commented Oct 20, 2022

Uh oh!

symwell commented Oct 20, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

symwell commented Oct 20, 2022

Uh oh!

apotterri commented Oct 20, 2022

Uh oh!

symwell commented Oct 21, 2022

Uh oh!

symwell commented Oct 21, 2022

Uh oh!

symwell commented Oct 21, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

symwell commented Oct 21, 2022

Uh oh!

apotterri left a comment

Choose a reason for hiding this comment

Uh oh!

apotterri left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

symwell commented Oct 19, 2022 •

edited

Loading

symwell commented Oct 20, 2022 •

edited

Loading

symwell commented Oct 20, 2022 •

edited

Loading

symwell commented Oct 21, 2022 •

edited

Loading