Repository: canonical/operator (language: python)

Issue:
Temper the chattiness of DEBUG logs
## Motivation

As a charm builder I want to have valuable DEBUG logs to expose to admins, and valuable INFO logs for users.

Please feel free to close this as a wont-fix if the existing DEBUG logs are thought to be useful.

## Issue

Currently DEBUG logs are very noisy, making it nigh impossible to parse. Workarounds include logging only at the INFO level, but that necessitates replicating valuable DEBUG logs already present (e.g `logger.info("CREATED EVENT FIRED")`).

The main culprits seems to be around `Operator Framework up`, `Legacy hooks`, `yaml` and `storage`. Is there a way that we can reduce the noise?

## Example

Below is my current debug log during a few defers over the course of a few seconds. The only part I expect an admin/user would WANT to see would be `Emitting Juju event XYZ`.

```
unit-zookeeper-1: 17:46:31 DEBUG unit.zookeeper/1.juju-log cluster:0: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:31 DEBUG unit.zookeeper/1.juju-log cluster:0: Legacy hooks/cluster-relation-changed does not exist.
unit-zookeeper-1: 17:46:31 DEBUG unit.zookeeper/1.juju-log cluster:0: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:31 DEBUG unit.zookeeper/1.juju-log cluster:0: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-2: 17:46:31 DEBUG unit.zookeeper/2.juju-log cluster:0: Operator Framework 1.5.0 up and running.
unit-zookeeper-2: 17:46:31 DEBUG unit.zookeeper/2.juju-log cluster:0: Legacy hooks/cluster-relation-changed does not exist.
unit-zookeeper-2: 17:46:31 DEBUG unit.zookeeper/2.juju-log cluster:0: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:31 DEBUG unit.zookeeper/1.juju-log cluster:0: Emitting Juju event cluster_relation_changed.
unit-zookeeper-2: 17:46:31 DEBUG unit.zookeeper/2.juju-log cluster:0: Using local storage: /var/lib/juju/agents/unit-zookeeper-2/charm/.unit-state.db already exists
unit-zookeeper-0: 17:46:31 DEBUG unit.zookeeper/0.juju-log cluster:0: Operator Framework 1.5.0 up and running.
unit-zookeeper-0: 17:46:31 DEBUG unit.zookeeper/0.juju-log cluster:0: Legacy hooks/cluster-relation-changed does not exist.
unit-zookeeper-0: 17:46:31 DEBUG unit.zookeeper/0.juju-log cluster:0: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-2: 17:46:31 DEBUG unit.zookeeper/2.juju-log cluster:0: Emitting Juju event cluster_relation_changed.
unit-zookeeper-0: 17:46:31 DEBUG unit.zookeeper/0.juju-log cluster:0: Using local storage: /var/lib/juju/agents/unit-zookeeper-0/charm/.unit-state.db already exists
unit-zookeeper-0: 17:46:31 DEBUG unit.zookeeper/0.juju-log cluster:0: Emitting Juju event cluster_relation_changed.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Legacy hooks/restart-relation-joined does not exist.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Emitting Juju event restart_relation_joined.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Legacy hooks/restart-relation-changed does not exist.
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-1: 17:46:32 DEBUG unit.zookeeper/1.juju-log restart:1: Emitting Juju event restart_relation_changed.
unit-zookeeper-1: 17:46:33 DEBUG unit.zookeeper/1.juju-log restart:1: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:33 DEBUG unit.zookeeper/1.juju-log restart:1: Legacy hooks/restart-relation-joined does not exist.
unit-zookeeper-1: 17:46:33 DEBUG unit.zookeeper/1.juju-log restart:1: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:33 DEBUG unit.zookeeper/1.juju-log restart:1: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-1: 17:46:33 DEBUG unit.zookeeper/1.juju-log restart:1: Emitting Juju event restart_relation_joined.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log restart:1: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log restart:1: Legacy hooks/restart-relation-changed does not exist.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log restart:1: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log restart:1: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log restart:1: Emitting Juju event restart_relation_changed.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log cluster:0: Operator Framework 1.5.0 up and running.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log cluster:0: Legacy hooks/cluster-relation-changed does not exist.
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log cluster:0: yaml does not have libyaml extensions, using slower pure Python yaml loader
unit-zookeeper-1: 17:46:34 DEBUG unit.zookeeper/1.juju-log cluster:0: Using local storage: /var/lib/juju/agents/unit-zookeeper-1/charm/.unit-state.db already exists
unit-zookeeper-1: 17:46:35 DEBUG unit.zookeeper/1.juju-log cluster:0: Emitting Juju event cluster_relation_changed.
```


Discussion / hints:
It feels like we can do a lot here to make life better. 

The "legacy hook does not exist" isn't really necessary to log. We encourage folks to write events that depart from the legacy hook names, such as the namespaces relation event here. We should skip logging about it. 

And the messages about local storage dbs already existing seems rude. We should let that pass without comment, because we expect that to be the case.

We should also squelch the message about Libyaml using the slower Python parser, if there's a good way to do it. (I think that the message comes from the library.) It's a choice that we made not to use c libs, and we don't need to chat about that choice in the logs. 

The "emitting" and "up and running" messages do feel more useful to me. For the former, you want to know that an event is running. And the latter acts as a sort of marker between instantions of the framework.

In summary: there's some useful stuff in there, but we're logging about situations, like namespaced relation handlers, that we really don't need to be logging about. 
Yeh, I agree with most of this. We should probably invert some of these messages - I.e. log when there _is_ a legacy hook or when the db _doesn't_ exist?
> Yeh, I agree with most of this. We should probably invert some of these messages - I.e. log when there _is_ a legacy hook or when the db _doesn't_ exist?

That seems like a more sensible approach: log the exception, not the 'all is good'

Fix patch:
diff --git a/ops/jujuversion.py b/ops/jujuversion.py
index d95cba0bc..e1f83d3a3 100755
--- a/ops/jujuversion.py
+++ b/ops/jujuversion.py
@@ -17,6 +17,7 @@
 import os
 import re
 from functools import total_ordering
+from typing import Union
 
 
 @total_ordering
@@ -55,12 +56,12 @@ def __repr__(self):
             s += '.{}'.format(self.build)
         return s
 
-    def __eq__(self, other: 'JujuVersion') -> bool:
+    def __eq__(self, other: Union[str, 'JujuVersion']) -> bool:
         if self is other:
             return True
         if isinstance(other, str):
             other = type(self)(other)
-        elif not isinstance(other, JujuVersion):
+        elif not isinstance(other, JujuVersion):  # pyright: reportUnnecessaryIsInstance=false
             raise RuntimeError('cannot compare Juju version "{}" with "{}"'.format(self, other))
         return (
             self.major == other.major
diff --git a/ops/main.py b/ops/main.py
index 691f7b324..56eb264cc 100755
--- a/ops/main.py
+++ b/ops/main.py
@@ -24,8 +24,6 @@
 import warnings
 from pathlib import Path
 
-import yaml
-
 import ops.charm
 import ops.framework
 import ops.model
@@ -251,7 +249,6 @@ def run_any_legacy_hook(self):
 
         dispatch_path = _exe_path(self._charm_dir / self._dispatch_path)
         if dispatch_path is None:
-            logger.debug("Legacy %s does not exist.", self._dispatch_path)
             return
 
         # super strange that there isn't an is_executable
@@ -326,7 +323,6 @@ def _should_use_controller_storage(db_path: Path, meta: ops.charm.CharmMeta) ->
     """Figure out whether we want to use controller storage or not."""
     # if you've previously used local state, carry on using that
     if db_path.exists():
-        logger.debug("Using local storage: %s already exists", db_path)
         return False
 
     # if you're not in k8s you don't need controller storage
@@ -374,8 +370,6 @@ def main(charm_class: typing.Type[ops.charm.CharmBase], use_juju_for_storage: bo
     else:
         actions_metadata = None
 
-    if not yaml.__with_libyaml__:
-        logger.debug('yaml does not have libyaml extensions, using slower pure Python yaml loader')
     meta = ops.charm.CharmMeta.from_yaml(metadata, actions_metadata)
     model = ops.model.Model(meta, model_backend)
 
diff --git a/ops/storage.py b/ops/storage.py
index 52f2ec50c..693c130e3 100755
--- a/ops/storage.py
+++ b/ops/storage.py
@@ -13,20 +13,23 @@
 # limitations under the License.
 
 """Structures to offer storage to the charm (through Juju or locally)."""
-
+import logging
+import os
 import pickle
 import shutil
 import sqlite3
 import subprocess
 import typing
 from datetime import timedelta
+from pathlib import Path
 from typing import Any, Callable, Generator, List, Optional, Tuple, Type, Union
 
 import yaml
 
-if typing.TYPE_CHECKING:
-    from pathlib import Path
+logger = logging.getLogger()
+
 
+if typing.TYPE_CHECKING:
     # _Notice = Tuple[event_path, observer_path, method_name]
     _Notice = Tuple[str, str, str]
     _Notices = List[_Notice]
@@ -53,6 +56,11 @@ class SQLiteStorage:
     def __init__(self, filename: Union['Path', str]):
         # The isolation_level argument is set to None such that the implicit
         # transaction management behavior of the sqlite3 module is disabled.
+
+        if not os.path.exists(str(filename)):
+            # sqlite3.connect creates the file silently if it does not exist
+            logger.debug("Initializing SQLite local storage: {}.".format(filename))
+
         self._db = sqlite3.connect(str(filename),
                                    isolation_level=None,
                                    timeout=self.DB_LOCK_TIMEOUT.total_seconds())
diff --git a/requirements-dev.txt b/requirements-dev.txt
index c96490f29..45f23037f 100644
--- a/requirements-dev.txt
+++ b/requirements-dev.txt
@@ -1,2 +1,3 @@
 PyYAML
-typing_extensions==4.2.0
\ No newline at end of file
+typing_extensions==4.2.0
+pyright==1.1.257
\ No newline at end of file
diff --git a/tox.ini b/tox.ini
index bffc674cb..8d8ab60f0 100644
--- a/tox.ini
+++ b/tox.ini
@@ -57,7 +57,7 @@ commands =
 [testenv:static]
 description = Run static type checker
 deps =
-    pyright
+    pyright==1.1.257
 commands =
     pyright {posargs}
 


Test patch:
diff --git a/test/test_main.py b/test/test_main.py
index e8a73a234..f109c15c5 100755
--- a/test/test_main.py
+++ b/test/test_main.py
@@ -28,7 +28,6 @@
 from unittest.mock import patch
 
 import logassert
-import yaml
 
 from ops.charm import (
     ActionEvent,
@@ -69,10 +68,6 @@
     'juju-log', '--log-level', 'DEBUG', '--',
     'Operator Framework {} up and running.'.format(version),
 ]
-SLOW_YAML_LOGLINE = [
-    'juju-log', '--log-level', 'DEBUG', '--',
-    'yaml does not have libyaml extensions, using slower pure Python yaml loader',
-]
 
 logger = logging.getLogger(__name__)
 
@@ -604,20 +599,11 @@ def test_collect_metrics(self):
 
         expected = [
             VERSION_LOGLINE,
-            ['juju-log', '--log-level', 'DEBUG', '--',
-             'Using local storage: {} already exists'.format(self.CHARM_STATE_FILE)],
             ['juju-log', '--log-level', 'DEBUG', '--', 'Emitting Juju event collect_metrics.'],
             ['add-metric', '--labels', 'bar=4.2', 'foo=42'],
         ]
-        if not yaml.__with_libyaml__:
-            expected.insert(1, SLOW_YAML_LOGLINE)
         calls = fake_script_calls(self)
 
-        if self.has_dispatch:
-            expected.insert(1, [
-                'juju-log', '--log-level', 'DEBUG', '--',
-                'Legacy {} does not exist.'.format(Path('hooks/collect-metrics'))])
-
         self.assertEqual(calls, expected)
 
     def test_logger(self):
@@ -656,17 +642,8 @@ def test_excepthook(self):
         calls = [' '.join(i) for i in fake_script_calls(self)]
 
         self.assertEqual(calls.pop(0), ' '.join(VERSION_LOGLINE))
-
-        if self.has_dispatch:
-            self.assertEqual(
-                calls.pop(0),
-                'juju-log --log-level DEBUG -- Legacy {} does not exist.'.format(
-                    Path("hooks/install")))
-
-        if not yaml.__with_libyaml__:
-            self.assertEqual(calls.pop(0), ' '.join(SLOW_YAML_LOGLINE))
-
         self.assertRegex(calls.pop(0), 'Using local storage: not a kubernetes charm')
+        self.assertRegex(calls.pop(0), 'Initializing SQLite local storage: ')
 
         self.maxDiff = None
         self.assertRegex(
@@ -888,9 +865,9 @@ def test_hook_and_dispatch(self):
             ['juju-log', '--log-level', 'DEBUG', '--',
              'Emitting Juju event install.'],
         ]
-        if not yaml.__with_libyaml__:
-            expected.insert(3, SLOW_YAML_LOGLINE)
-        self.assertEqual(fake_script_calls(self), expected)
+        calls = fake_script_calls(self)
+        self.assertRegex(' '.join(calls.pop(-2)), 'Initializing SQLite local storage: ')
+        self.assertEqual(calls, expected)
 
     @unittest.skipIf(is_windows, "this is UNIXish; TODO: write equivalent windows test")
     def test_non_executable_hook_and_dispatch(self):
@@ -908,9 +885,9 @@ def test_non_executable_hook_and_dispatch(self):
             ['juju-log', '--log-level', 'DEBUG', '--',
              'Emitting Juju event install.'],
         ]
-        if not yaml.__with_libyaml__:
-            expected.insert(2, SLOW_YAML_LOGLINE)
-        self.assertEqual(fake_script_calls(self), expected)
+        calls = fake_script_calls(self)
+        self.assertRegex(' '.join(calls.pop(-2)), 'Initializing SQLite local storage: ')
+        self.assertEqual(calls, expected)
 
     def test_hook_and_dispatch_with_failing_hook(self):
         self.stdout = self.stderr = tempfile.TemporaryFile()
@@ -995,9 +972,10 @@ def test_hook_and_dispatch_but_hook_is_dispatch_copy(self):
             ['juju-log', '--log-level', 'DEBUG', '--',
              'Emitting Juju event install.'],
         ]
-        if not yaml.__with_libyaml__:
-            expected.insert(5, SLOW_YAML_LOGLINE)
-        self.assertEqual(fake_script_calls(self), expected)
+        calls = fake_script_calls(self)
+        self.assertRegex(' '.join(calls.pop(-2)), 'Initializing SQLite local storage: ')
+
+        self.assertEqual(calls, expected)
 
 
 # NOTE
@@ -1154,4 +1132,3 @@ def test_not_if_already_local(self):
         meta = CharmMeta.from_yaml("series: [kubernetes]")
         with patch.dict(os.environ, {"JUJU_VERSION": "2.8"}), tempfile.NamedTemporaryFile() as fd:
             self.assertFalse(_should_use_controller_storage(Path(fd.name), meta))
-            self.assertLogged('Using local storage: {} already exists'.format(fd.name))