Repository: RasaHQ/rasa
Pull request: Fix duplicate logs
**Proposed changes**:
Fixes https://github.com/RasaHQ/rasa/issues/3900
- remove duplicated logs (any level)
- remove duplicated warnings: `UserWarnings`, `DeprecatedWarnings` and `FutureWarnings`

_Caveat: it doesn't work when same warning / log are fired in different processes_

**Status (please check what you already did)**:
- [x] added some tests for the functionality
- [ ] updated the documentation
- [x] updated the changelog (please check [changelog](https://github.com/RasaHQ/rasa/tree/master/changelog) for instructions)
- [x] reformat files using `black` (please check [Readme](https://github.com/RasaHQ/rasa#code-style) for instructions)


Problem statement:
clean up duplicated errors during training
There are certain errors while training that get processed per line, and the repeat a ton when the error shows up a lot: 
```
2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
Processed Story Blocks:   0%|                                                                               | 0/17 [00:00<?, ?it/s, # trackers=1]2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
Processed Story Blocks:   0%|                                                                               | 0/17 [00:00<?, ?it/s, # trackers=2]2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
Processed Story Blocks: 100%|████████████████████████████████████████████████████████████████████| 17/17 [00:00<00:00, 1048.34it/s, # trackers=1]
Processed Story Blocks: 100%|████████████████████████████████████████████████████████████████████████████████| 17/17 [00:00<00:00, 115005.11it/s]
Processed Story Blocks:   0%|                                                                               | 0/17 [00:00<?, ?it/s, # trackers=2]2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
2019-06-28 17:49:21 WARNING  rasa.core.domain  - Failed to use action 'action_thank_feedback' in history. Please make sure all actions are listed in the domains action list. If you recently removed an action, don't worry about this warning. It should stop appearing after a while.
```
It would be good if we, for example in this case, stored a set of actions for which this error occurs, and then after training dumped all of the warnings (but only one for each action). This also applies to other warnings like "tried to set non-existent slot XXX"

Hints from issue discussion:
check if this is still the case
I havent been able to get the earlier warning because it only happens after you remove an action from everywhere. However for example in 1.7.0, if you remove a categorical slot that is in your stories from your domain and then try to train (scroll to the right):
```
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
Processed Story Blocks:  88%|████████████████████████████████████████████████████████████████████████████████████████████████████▎             | 1864/2118 [00:03<00:00, 493.74it/s, # trackers=1]2020-02-11 10:31:45 ERROR    rasa.core.trackers  - Tried to set non existent slot 'feedback_value'. Make sure you added all your slots to your domain file.
```
```
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 6. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 8. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 21. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 23. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 36. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 38. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
/Users/ella/rasa/rasa/core/training/dsl.py:422: UserWarning: Found unknown intent 'inform' on line 49. Please, make sure that all intents are listed in your domain yaml.
  docs=DOCS_URL_DOMAINS,
```
@erohmensing @wochinge this sounds super low priority to me. How bothering is this? Are the warnings valid?
The warnings are valid, it just throws every time it sees the slot/intent which is kind of annoying. I agree that it's very low, definitely a "nice to have". We can put it on the "help wanted" project instead if you like.
ok 👍 added the labels. Thanks @erohmensing !
I removed it from the project board and the priority label because there's a separate board for contributors, does that make sense?
ahhhh, I thought the label `help wanted` was enough. Yes it does! 🙏 
taking a look at this now. They seem to be different kinds of warnings:
- some are sent with `logging.warning` or even `logging.error`: for those we need a specific kind of filter to remove duplicates but it won't be perfect, it will only filter duplicates that come one after the other
- some are send using `warnings.warn`: Python has built-in deduplication for those, it should work

Commit message: Merge branch '1.10.x' into fix-duplicate-logs

Patch to review:
diff --git a/changelog/3900.improvement.rst b/changelog/3900.improvement.rst
new file mode 100644
index 000000000000..1a6b17f37139
--- /dev/null
+++ b/changelog/3900.improvement.rst
@@ -0,0 +1 @@
+Removed duplicate logs and warnings when running ``rasa train``.
diff --git a/rasa/__main__.py b/rasa/__main__.py
index 6f3ca4df0b7e..d56f3dcd2640 100644
--- a/rasa/__main__.py
+++ b/rasa/__main__.py
@@ -18,7 +18,7 @@
 )
 from rasa.cli.arguments.default_arguments import add_logging_options
 from rasa.cli.utils import parse_last_positional_argument_as_model_path
-from rasa.utils.common import set_log_level
+from rasa.utils.common import set_log_level, set_log_and_warnings_filters
 import rasa.utils.tensorflow.environment as tf_env
 
 logger = logging.getLogger(__name__)
@@ -88,6 +88,7 @@ def main() -> None:
 
     if hasattr(cmdline_arguments, "func"):
         rasa.utils.io.configure_colored_logging(log_level)
+        set_log_and_warnings_filters()
         cmdline_arguments.func(cmdline_arguments)
     elif hasattr(cmdline_arguments, "version"):
         print_version()
diff --git a/rasa/utils/common.py b/rasa/utils/common.py
index 904158dfeb28..bbb79c023381 100644
--- a/rasa/utils/common.py
+++ b/rasa/utils/common.py
@@ -158,6 +158,20 @@ def update_asyncio_log_level() -> None:
     logging.getLogger("asyncio").setLevel(log_level)
 
 
+def set_log_and_warnings_filters() -> None:
+    """
+    Set log filters on the root logger, and duplicate filters for warnings.
+
+    Filters only propagate on handlers, not loggers.
+    """
+    for handler in logging.getLogger().handlers:
+        handler.addFilter(RepeatedLogFilter())
+
+    warnings.filterwarnings("once", category=UserWarning)
+    warnings.filterwarnings("once", category=DeprecationWarning)
+    warnings.filterwarnings("once", category=FutureWarning)
+
+
 def obtain_verbosity() -> int:
     """Returns a verbosity level according to the set log level."""
     log_level = os.environ.get(ENV_LOG_LEVEL, DEFAULT_LOG_LEVEL)
@@ -350,3 +364,24 @@ def formatwarning(
     warnings.formatwarning = formatwarning
     warnings.warn(message, category=category, **kwargs)
     warnings.formatwarning = original_formatter
+
+
+class RepeatedLogFilter(logging.Filter):
+    """
+    Filter repeated log records.
+    """
+
+    last_log = None
+
+    def filter(self, record):
+        current_log = (
+            record.levelno,
+            record.pathname,
+            record.lineno,
+            record.msg,
+            record.args,
+        )
+        if current_log != self.last_log:
+            self.last_log = current_log
+            return True
+        return False
diff --git a/tests/utils/test_common.py b/tests/utils/test_common.py
index c7daa80ee83b..3518916cc45c 100644
--- a/tests/utils/test_common.py
+++ b/tests/utils/test_common.py
@@ -1,6 +1,12 @@
+import logging
+
 import pytest
 
-from rasa.utils.common import raise_warning, sort_list_of_dicts_by_first_key
+from rasa.utils.common import (
+    raise_warning,
+    sort_list_of_dicts_by_first_key,
+    RepeatedLogFilter,
+)
 
 
 def test_sort_dicts_by_keys():
@@ -27,3 +33,24 @@ def test_raise_deprecation():
     assert len(record) == 1
     assert record[0].message.args[0] == "My warning."
     assert isinstance(record[0].message, DeprecationWarning)
+
+
+def test_repeated_log_filter():
+    log_filter = RepeatedLogFilter()
+    record1 = logging.LogRecord(
+        "rasa", logging.INFO, "/some/path.py", 42, "Super msg: %s", ("yes",), None
+    )
+    record1_same = logging.LogRecord(
+        "rasa", logging.INFO, "/some/path.py", 42, "Super msg: %s", ("yes",), None
+    )
+    record2_other_args = logging.LogRecord(
+        "rasa", logging.INFO, "/some/path.py", 42, "Super msg: %s", ("no",), None
+    )
+    record3_other = logging.LogRecord(
+        "rasa", logging.INFO, "/some/path.py", 42, "Other msg", (), None
+    )
+    assert log_filter.filter(record1) is True
+    assert log_filter.filter(record1_same) is False  # same log
+    assert log_filter.filter(record2_other_args) is True
+    assert log_filter.filter(record3_other) is True
+    assert log_filter.filter(record1) is True  # same as before, but not repeated


Code review comments:
diff_hunk: @@ -0,0 +1 @@
+Removed duplicate logs and warnings when running ``rasa train``.
path: changelog/3900.improvement.rst
text: @user1:
Maybe `Reduce` instead of `Remove`? As you mentioned, we get rid only of two consecutive log messages. 

@author:
makes sense

diff_hunk: @@ -158,6 +158,20 @@ def update_asyncio_log_level() -> None:
     logging.getLogger("asyncio").setLevel(log_level)
 
 
+def set_log_and_warnings_filters() -> None:
+    """
+    Set log filters on the root logger, and duplicate filters for warnings.
+
+    Filters only propagate on handlers, not loggers.
+    """
+    for handler in logging.getLogger().handlers:
+        handler.addFilter(RepeatedLogFilter())
+
+    warnings.filterwarnings("once", category=UserWarning)
+    warnings.filterwarnings("once", category=DeprecationWarning)
path: rasa/utils/common.py
text: @user1:
Note about `DeprecationWarning` and `FutureWarning`:

According to the docs `"once" print only the first occurrence of matching warnings, regardless of location`.

IMO it makes sense to always print the warnings for calls of deprecated functions, the more "annoying" it is, the faster user will switch to a new implementation.

@author:
that's a great point!