Add in log filter for pacing logs #497

Ktmi · 2024-08-28T14:53:00Z

Closes #495

Summary

Adds in RepeatMessageFilter which caches a limited number of log messages, and prevents any repeat messages from being sent out for a short period of time. The way I had to implement this is a little janky. Prefarably the logging would be loaded and setup before kytos core is loaded, which is part of the reason why the filter exists in kytos.logging, as I plan to move the logging code to there.

Local Tests

Repeat pacing messages are now suppressed, rather than shown in the logs. Works as expected.

End-to-End Tests

Here are the E2E results:

kytos_1        | Starting enhanced syslogd: rsyslogd.
kytos_1        | /etc/openvswitch/conf.db does not exist ... (warning).
kytos_1        | Creating empty database /etc/openvswitch/conf.db.
kytos_1        | Starting ovsdb-server.
kytos_1        | Configuring Open vSwitch system IDs.
kytos_1        | Starting ovs-vswitchd.
kytos_1        | Enabling remote OVSDB managers.
kytos_1        | + '[' -z '' ']'
kytos_1        | + '[' -z '' ']'
kytos_1        | + echo 'There is no NAPPS_PATH specified. Default will be used.'
kytos_1        | There is no NAPPS_PATH specified. Default will be used.
kytos_1        | + NAPPS_PATH=
kytos_1        | + sed -i 's/STATS_INTERVAL = 60/STATS_INTERVAL = 7/g' /var/lib/kytos/napps/kytos/of_core/settings.py
kytos_1        | + sed -i 's/CONSISTENCY_MIN_VERDICT_INTERVAL =.*/CONSISTENCY_MIN_VERDICT_INTERVAL = 60/g' /var/lib/kytos/napps/kytos/flow_manager/settings.py
kytos_1        | + sed -i 's/LINK_UP_TIMER = 10/LINK_UP_TIMER = 1/g' /var/lib/kytos/napps/kytos/topology/settings.py
kytos_1        | + sed -i 's/DEPLOY_EVCS_INTERVAL = 60/DEPLOY_EVCS_INTERVAL = 5/g' /var/lib/kytos/napps/kytos/mef_eline/settings.py
kytos_1        | + sed -i 's/LLDP_LOOP_ACTIONS = \["log"\]/LLDP_LOOP_ACTIONS = \["disable","log"\]/' /var/lib/kytos/napps/kytos/of_lldp/settings.py
kytos_1        | + sed -i 's/LLDP_IGNORED_LOOPS = {}/LLDP_IGNORED_LOOPS = {"00:00:00:00:00:00:00:01": \[\[4, 5\]\]}/' /var/lib/kytos/napps/kytos/of_lldp/settings.py
kytos_1        | + sed -i 's/CONSISTENCY_COOKIE_IGNORED_RANGE =.*/CONSISTENCY_COOKIE_IGNORED_RANGE = [(0xdd00000000000000, 0xdd00000000000009)]/g' /var/lib/kytos/napps/kytos/flow_manager/settings.py
kytos_1        | + sed -i 's/LIVENESS_DEAD_MULTIPLIER =.*/LIVENESS_DEAD_MULTIPLIER = 3/g' /var/lib/kytos/napps/kytos/of_lldp/settings.py
kytos_1        | + kytosd --help
kytos_1        | + sed -i s/WARNING/INFO/g /etc/kytos/logging.ini
kytos_1        | + test -z ''
kytos_1        | + TESTS=tests/
kytos_1        | + test -z ''
kytos_1        | + RERUNS=2
kytos_1        | + python3 scripts/wait_for_mongo.py
kytos_1        | Trying to run hello command on MongoDB...
kytos_1        | Trying to run 'hello' command on MongoDB...
kytos_1        | Trying to run 'hello' command on MongoDB...
kytos_1        | Ran 'hello' command on MongoDB successfully. It's ready!
kytos_1        | + python3 -m pytest tests/ --reruns 2 -r fEr
kytos_1        | ============================= test session starts ==============================
kytos_1        | platform linux -- Python 3.11.2, pytest-8.1.1, pluggy-1.5.0
kytos_1        | rootdir: /tests
kytos_1        | plugins: timeout-2.2.0, rerunfailures-13.0, anyio-4.3.0
kytos_1        | collected 267 items
kytos_1        | 
kytos_1        | tests/test_e2e_01_kytos_startup.py ..                                    [  0%]
kytos_1        | tests/test_e2e_05_topology.py ..................                         [  7%]
kytos_1        | tests/test_e2e_06_topology.py ....                                       [  8%]
kytos_1        | tests/test_e2e_10_mef_eline.py ..........ss.....x.....x................  [ 23%]
kytos_1        | tests/test_e2e_11_mef_eline.py ......                                    [ 26%]
kytos_1        | tests/test_e2e_12_mef_eline.py .....Xx.                                  [ 29%]
kytos_1        | tests/test_e2e_13_mef_eline.py ....Xs.s.....Xs.s.XXxX.xxxx..X........... [ 44%]
kytos_1        | .                                                                        [ 44%]
kytos_1        | tests/test_e2e_14_mef_eline.py x                                         [ 45%]
kytos_1        | tests/test_e2e_15_mef_eline.py .....                                     [ 47%]
kytos_1        | tests/test_e2e_16_mef_eline.py ..                                        [ 47%]
kytos_1        | tests/test_e2e_20_flow_manager.py ......................                 [ 56%]
kytos_1        | tests/test_e2e_21_flow_manager.py ...                                    [ 57%]
kytos_1        | tests/test_e2e_22_flow_manager.py ...............                        [ 62%]
kytos_1        | tests/test_e2e_23_flow_manager.py ..............                         [ 68%]
kytos_1        | tests/test_e2e_30_of_lldp.py ....                                        [ 69%]
kytos_1        | tests/test_e2e_31_of_lldp.py ...                                         [ 70%]
kytos_1        | tests/test_e2e_32_of_lldp.py ...                                         [ 71%]
kytos_1        | tests/test_e2e_40_sdntrace.py ................                           [ 77%]
kytos_1        | tests/test_e2e_41_kytos_auth.py ........                                 [ 80%]
kytos_1        | tests/test_e2e_42_sdntrace.py ..                                         [ 81%]
kytos_1        | tests/test_e2e_50_maintenance.py ............................            [ 92%]
kytos_1        | tests/test_e2e_60_of_multi_table.py .....                                [ 94%]
kytos_1        | tests/test_e2e_70_kytos_stats.py ........                                [ 97%]
kytos_1        | tests/test_e2e_80_pathfinder.py ss......                                 [100%]
kytos_1        | 
kytos_1        | =============================== warnings summary ===============================
kytos_1        | usr/local/lib/python3.11/dist-packages/kytos/core/config.py:254
kytos_1        |   /usr/local/lib/python3.11/dist-packages/kytos/core/config.py:254: UserWarning: Unknown arguments: ['tests/', '--reruns', '2', '-r', 'fEr']
kytos_1        |     warnings.warn(f"Unknown arguments: {unknown}")
kytos_1        | 
kytos_1        | test_e2e_01_kytos_startup.py: 17 warnings
kytos_1        | test_e2e_05_topology.py: 17 warnings
kytos_1        | test_e2e_06_topology.py: 76 warnings
kytos_1        | test_e2e_10_mef_eline.py: 17 warnings
kytos_1        | test_e2e_11_mef_eline.py: 25 warnings
kytos_1        | test_e2e_12_mef_eline.py: 17 warnings
kytos_1        | test_e2e_13_mef_eline.py: 17 warnings
kytos_1        | test_e2e_14_mef_eline.py: 76 warnings
kytos_1        | test_e2e_15_mef_eline.py: 17 warnings
kytos_1        | test_e2e_16_mef_eline.py: 17 warnings
kytos_1        | test_e2e_20_flow_manager.py: 17 warnings
kytos_1        | test_e2e_21_flow_manager.py: 17 warnings
kytos_1        | test_e2e_22_flow_manager.py: 17 warnings
kytos_1        | test_e2e_23_flow_manager.py: 17 warnings
kytos_1        | test_e2e_30_of_lldp.py: 17 warnings
kytos_1        | test_e2e_31_of_lldp.py: 17 warnings
kytos_1        | test_e2e_32_of_lldp.py: 11 warnings
kytos_1        | test_e2e_40_sdntrace.py: 49 warnings
kytos_1        | test_e2e_41_kytos_auth.py: 17 warnings
kytos_1        | test_e2e_42_sdntrace.py: 84 warnings
kytos_1        | test_e2e_50_maintenance.py: 17 warnings
kytos_1        | test_e2e_60_of_multi_table.py: 17 warnings
kytos_1        | test_e2e_70_kytos_stats.py: 17 warnings
kytos_1        | test_e2e_80_pathfinder.py: 37 warnings
kytos_1        |   /usr/lib/python3/dist-packages/mininet/node.py:1121: DeprecationWarning: distutils Version classes are deprecated. Use packaging.version instead.
kytos_1        |     return ( StrictVersion( cls.OVSVersion ) <
kytos_1        | 
kytos_1        | test_e2e_01_kytos_startup.py: 17 warnings
kytos_1        | test_e2e_05_topology.py: 17 warnings
kytos_1        | test_e2e_06_topology.py: 76 warnings
kytos_1        | test_e2e_10_mef_eline.py: 17 warnings
kytos_1        | test_e2e_11_mef_eline.py: 25 warnings
kytos_1        | test_e2e_12_mef_eline.py: 17 warnings
kytos_1        | test_e2e_13_mef_eline.py: 17 warnings
kytos_1        | test_e2e_14_mef_eline.py: 76 warnings
kytos_1        | test_e2e_15_mef_eline.py: 17 warnings
kytos_1        | test_e2e_16_mef_eline.py: 17 warnings
kytos_1        | test_e2e_20_flow_manager.py: 17 warnings
kytos_1        | test_e2e_21_flow_manager.py: 17 warnings
kytos_1        | test_e2e_22_flow_manager.py: 17 warnings
kytos_1        | test_e2e_23_flow_manager.py: 17 warnings
kytos_1        | test_e2e_30_of_lldp.py: 17 warnings
kytos_1        | test_e2e_31_of_lldp.py: 17 warnings
kytos_1        | test_e2e_32_of_lldp.py: 11 warnings
kytos_1        | test_e2e_40_sdntrace.py: 49 warnings
kytos_1        | test_e2e_41_kytos_auth.py: 17 warnings
kytos_1        | test_e2e_42_sdntrace.py: 84 warnings
kytos_1        | test_e2e_50_maintenance.py: 17 warnings
kytos_1        | test_e2e_60_of_multi_table.py: 17 warnings
kytos_1        | test_e2e_70_kytos_stats.py: 17 warnings
kytos_1        | test_e2e_80_pathfinder.py: 37 warnings
kytos_1        |   /usr/lib/python3/dist-packages/mininet/node.py:1122: DeprecationWarning: distutils Version classes are deprecated. Use packaging.version instead.
kytos_1        |     StrictVersion( '1.10' ) )
kytos_1        | 
kytos_1        | -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
kytos_1        | ------------------------------- start/stop times -------------------------------
kytos_1        | = 243 passed, 8 skipped, 9 xfailed, 7 xpassed, 1295 warnings in 10750.92s (2:59:10) =
kytos-tests_kytos_1 exited with code 0

viniarck

It's great how it integrated well with log filters. I've asked implementation detail changes though. Other than that:

This needs to land as patch, bumping the version
This needs unit test
This needs changelog to be updated

kytos/logging/filters.py

kytos/core/pacing.py

kytos/logging/filters.py

viniarck

Nicely done. Great to have this tightly integrated in the logger @Ktmi.

Overall looks good, I'm waiting to see unit tests, changelog and version being bumped before approving though.

Did you also have the chance to confirm with the latest refactor that 1.0 lockout_time worked as you'd expect? Let's exercise this in the rate limit and seeing if it's being helpful to understand the timeline where it kicked in and then stopped.

Also, final trivial related point, in the log message did you mean "Limited reached" or "Limit reached"?

kytos/logging/filters.py

Ktmi · 2024-09-04T22:48:34Z

@viniarck This one should be good to go now. The lower lockout_time works as expected.

2024-09-04 15:54:18,214 - INFO [kytos.core.pacing] [pacing.py:170:hit] (thread_pool_sb_231) Limited reached: (100 per 1 second, 'flow_manager.send_flow_mod.alien', '00:00:00:00:00:00:01:03')
2024-09-04 15:54:19,214 - INFO [kytos.core.pacing] [pacing.py:170:hit] (thread_pool_sb_231) Limited reached: (100 per 1 second, 'flow_manager.send_flow_mod.alien', '00:00:00:00:00:00:01:03')
2024-09-04 15:54:20,296 - INFO [kytos.core.pacing] [pacing.py:170:hit] (thread_pool_sb_231) Limited reached: (100 per 1 second, 'flow_manager.send_flow_mod.alien', '00:00:00:00:00:00:01:03')

viniarck

Nicely done, David. LGTM.

Let's ship it.

Ktmi added 4 commits August 26, 2024 13:33

Added message filter for removing repeat messages.

7e79bf0

Fix record key generation.

41cb266

Add repeat message filter to pacing logging

e6c5089

Added check if LOG exists

4f383fd

Ktmi requested a review from a team as a code owner August 28, 2024 14:53

linter cleanup

fc11aef

viniarck requested changes Aug 29, 2024

View reviewed changes

kytos/logging/filters.py Outdated Show resolved Hide resolved

kytos/core/pacing.py Outdated Show resolved Hide resolved

kytos/logging/filters.py Outdated Show resolved Hide resolved

kytos/logging/filters.py Show resolved Hide resolved

Ktmi added 3 commits August 30, 2024 20:16

Updtated to use ordered dict

b6fe9e8

linter cleanup

3add3fb

Reduced repeat message timer to 1 second

6cc44d3

viniarck reviewed Sep 3, 2024

View reviewed changes

kytos/logging/filters.py Outdated Show resolved Hide resolved

Ktmi added 5 commits September 3, 2024 21:15

Removed unnecessary move_to_end

13529bc

Fixed pacing log message grammar

507c7fb

Added some basic tests for the message filter

ffe81b3

Updated changelog

af178cd

Bumped up the version number

c917794

viniarck self-requested a review September 5, 2024 14:16

viniarck approved these changes Sep 5, 2024

View reviewed changes

Ktmi merged commit 38fe606 into master Sep 5, 2024
2 checks passed

Ktmi deleted the logging/filters branch September 5, 2024 15:03

viniarck mentioned this pull request Sep 5, 2024

chore: refactor log.info "Limited reached" as "Limit reached" #498

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add in log filter for pacing logs #497

Add in log filter for pacing logs #497

Ktmi commented Aug 28, 2024 •

edited

Loading

viniarck left a comment •

edited

Loading

viniarck left a comment

Ktmi commented Sep 4, 2024 •

edited

Loading

viniarck left a comment

Add in log filter for pacing logs #497

Add in log filter for pacing logs #497

Conversation

Ktmi commented Aug 28, 2024 • edited Loading

Summary

Local Tests

End-to-End Tests

viniarck left a comment • edited Loading

Choose a reason for hiding this comment

viniarck left a comment

Choose a reason for hiding this comment

Ktmi commented Sep 4, 2024 • edited Loading

viniarck left a comment

Choose a reason for hiding this comment

Ktmi commented Aug 28, 2024 •

edited

Loading

viniarck left a comment •

edited

Loading

Ktmi commented Sep 4, 2024 •

edited

Loading