fix: logging verbosity now actually applies + per-service log levels

Root causes fixed:
- Dead LOG_LEVEL globals() lookup pinned root logger at INFO regardless of
  PIC_LOG_LEVEL env or config; replaced with _resolve_root_log_level() +
  apply_root_log_level() which sets both root logger and all attached handlers
  at startup and on runtime re-apply.
- set_service_level() only set the named 'pic.<service>' logger; bare module
  loggers (e.g. 'caddy_manager') were never reached, so per-service log files
  stayed 0 bytes. Fixed via _SERVICE_MODULE_LOGGERS map covering all managers.
- Log viewer GET /api/logs had no level filter; added ?level= query param.
- Per-service log levels lived in an out-of-band config/api/log_levels.json
  side-file with no validation; migrated into ConfigManager under a new
  'logging' section ({python:{root,services}, containers:{caddy,coredns,
  wireguard,mailserver,api}}) with get/set helpers, invalid-level rejection,
  and one-time migration from the old file on first load.

New capabilities:
- Container log levels: Caddy (injects global log { level X } + hot reload),
  CoreDNS (DEBUG enables log plugin, else errors-only), WireGuard/mailserver
  via pending_restart path.
- PUT /api/logs/verbosity accepts {python, containers} dict; returns per-entry
  applied:hot|pending_restart status.
- Webui Logs page gains two-section Verbosity tab (Python services + Container
  services) with needs-restart badges.
- managers.py wires per-service loggers before manager instantiation and
  re-applies persisted levels from ConfigManager; legacy log_levels.json read
  removed.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

tests/test_caddy_manager.py

@@ -735,5 +735,34 @@ class TestDdnsApiStripsLegacySuffix(unittest.TestCase):
         self.assertIn('api_base_url https://ddns.pic.ngo', out)
 
 
+class TestCaddyLogLevel(unittest.TestCase):
+    """Container log level injects a global `log { level <X> }` block."""
+
+    def _mgr_with_level(self, level):
+        cm = MagicMock()
+        cm.get_identity.return_value = {}
+        cm.get_logging_config.return_value = {
+            'python': {'root': 'INFO', 'services': {}},
+            'containers': {'caddy': level},
+        }
+        return CaddyManager(config_manager=cm, data_dir='/tmp/pic-t', config_dir='/tmp/pic-t')
+
+    def test_debug_emits_global_log_block_lan(self):
+        mgr = self._mgr_with_level('DEBUG')
+        out = mgr.generate_caddyfile({'cell_name': 'c', 'domain_mode': 'lan'}, [])
+        self.assertIn('log {', out)
+        self.assertIn('level DEBUG', out)
+
+    def test_info_emits_no_log_block(self):
+        mgr = self._mgr_with_level('INFO')
+        out = mgr.generate_caddyfile({'cell_name': 'c', 'domain_mode': 'lan'}, [])
+        self.assertNotIn('log {', out)
+
+    def test_warning_maps_to_caddy_warn(self):
+        mgr = self._mgr_with_level('WARNING')
+        out = mgr.generate_caddyfile({'cell_name': 'c', 'domain_mode': 'lan'}, [])
+        self.assertIn('level WARN', out)
+
+
 if __name__ == '__main__':
     unittest.main()

tests/test_cell_link_dns.py

@@ -61,8 +61,17 @@ class TestGenerateCorefileOneLink(unittest.TestCase):
         self.assertIn('cache', content[idx_primary:])
 
     def test_log_directive_present_in_forwarding_block(self):
+        # At default INFO the forwarding block carries the `errors` directive;
+        # at DEBUG it carries the verbose `log` plugin.
         cell_links = [{'domain': 'remote.cell', 'dns_ip': '10.5.0.1'}]
-        firewall_manager.generate_corefile([], self.path, cell_links=cell_links)
+        firewall_manager.generate_corefile([], self.path, cell_links=cell_links,
+                                           coredns_level='INFO')
+        content = self._read()
+        idx_primary = content.index('remote.cell {')
+        self.assertIn('errors', content[idx_primary:])
+
+        firewall_manager.generate_corefile([], self.path, cell_links=cell_links,
+                                           coredns_level='DEBUG')
         content = self._read()
         idx_primary = content.index('remote.cell {')
         self.assertIn('log', content[idx_primary:])

tests/test_firewall_manager.py

@@ -132,6 +132,20 @@ class TestGenerateCorefile(unittest.TestCase):
         content = open(self.path).read()
         self.assertIn('reload', content)
 
+    def test_debug_level_includes_log_plugin(self):
+        firewall_manager.generate_corefile([], self.path, coredns_level='DEBUG')
+        content = open(self.path).read()
+        # The verbose query-logging `log` plugin is present at DEBUG.
+        self.assertIn('\n    log\n', content)
+        self.assertNotIn('errors', content)
+
+    def test_info_level_uses_errors_only(self):
+        firewall_manager.generate_corefile([], self.path, coredns_level='INFO')
+        content = open(self.path).read()
+        self.assertIn('errors', content)
+        # No verbose query logging at INFO.
+        self.assertNotIn('\n    log\n', content)
+
     def test_rewrite_preserves_inode(self):
         # Regression: the Corefile is a Docker FILE bind-mount, so it must be
         # rewritten in place. os.replace() would swap the inode and the

tests/test_log_manager_extra.py

@@ -356,6 +356,23 @@ class TestSetServiceLevel(unittest.TestCase):
         self.assertIsInstance(levels, dict)
         self.assertIn('svc', levels)
 
+    def test_set_level_also_sets_bare_module_logger(self):
+        """A verbosity change for 'network' must reach BOTH picell.network and
+        the network_manager module logger so per-service files capture every
+        record (the core bug)."""
+        import logging
+        self.lm.add_service_logger('network', {'level': 'INFO'})
+        self.lm.set_service_level('network', 'DEBUG')
+        self.assertEqual(self.lm.service_loggers['network'].level, logging.DEBUG)
+        self.assertEqual(logging.getLogger('network_manager').level, logging.DEBUG)
+
+    def test_set_level_for_routing_covers_firewall_module_logger(self):
+        import logging
+        self.lm.add_service_logger('routing', {'level': 'INFO'})
+        self.lm.set_service_level('routing', 'DEBUG')
+        self.assertEqual(logging.getLogger('routing_manager').level, logging.DEBUG)
+        self.assertEqual(logging.getLogger('firewall_manager').level, logging.DEBUG)
+
 
 class TestGetAllLogFileInfos(unittest.TestCase):
     def setUp(self):

tests/test_logging_config.py

@@ -0,0 +1,97 @@
+#!/usr/bin/env python3
+"""
+Tests for the `logging` section of cell_config (ConfigManager):
+- default schema present after first load
+- round-trip persistence of python + container levels
+- migration from the legacy config/api/log_levels.json side-file
+- invalid-level rejection
+- inclusion in the backed-up cell_config
+"""
+
+import sys
+import os
+import json
+import tempfile
+import shutil
+import unittest
+from pathlib import Path
+
+api_dir = Path(__file__).parent.parent / 'api'
+sys.path.insert(0, str(api_dir))
+
+from config_manager import ConfigManager
+
+
+def _make_cm(tmp):
+    config_file = os.path.join(tmp, 'cell_config.json')
+    data_dir = os.path.join(tmp, 'data')
+    os.makedirs(data_dir, exist_ok=True)
+    return ConfigManager(config_file, data_dir)
+
+
+class TestLoggingSchema(unittest.TestCase):
+    def setUp(self):
+        self.tmp = tempfile.mkdtemp()
+
+    def tearDown(self):
+        shutil.rmtree(self.tmp, ignore_errors=True)
+
+    def test_default_logging_config_present(self):
+        cm = _make_cm(self.tmp)
+        cfg = cm.get_logging_config()
+        self.assertEqual(cfg['python']['root'], 'INFO')
+        self.assertEqual(cfg['python']['services']['network'], 'INFO')
+        self.assertEqual(cfg['containers']['caddy'], 'INFO')
+        self.assertEqual(cfg['containers']['coredns'], 'INFO')
+
+    def test_set_and_get_python_level_round_trip(self):
+        cm = _make_cm(self.tmp)
+        cm.set_python_log_level('network', 'DEBUG')
+        cm.set_python_log_level('root', 'WARNING')
+        # Re-load from disk to prove persistence.
+        cm2 = _make_cm(self.tmp)
+        cfg = cm2.get_logging_config()
+        self.assertEqual(cfg['python']['services']['network'], 'DEBUG')
+        self.assertEqual(cfg['python']['root'], 'WARNING')
+
+    def test_set_and_get_container_level_round_trip(self):
+        cm = _make_cm(self.tmp)
+        cm.set_container_log_level('coredns', 'DEBUG')
+        cm2 = _make_cm(self.tmp)
+        self.assertEqual(cm2.get_logging_config()['containers']['coredns'], 'DEBUG')
+
+    def test_invalid_python_level_rejected(self):
+        cm = _make_cm(self.tmp)
+        with self.assertRaises(ValueError):
+            cm.set_python_log_level('network', 'LOUD')
+
+    def test_invalid_container_level_rejected(self):
+        cm = _make_cm(self.tmp)
+        with self.assertRaises(ValueError):
+            cm.set_container_log_level('caddy', 'chatty')
+
+    def test_migration_from_legacy_log_levels_json(self):
+        # Legacy side-file lived at config/api/log_levels.json (next to cell_config).
+        api_cfg_dir = os.path.join(self.tmp, 'api')
+        os.makedirs(api_cfg_dir, exist_ok=True)
+        with open(os.path.join(api_cfg_dir, 'log_levels.json'), 'w') as f:
+            json.dump({'network': 'DEBUG', 'email': 'WARNING', 'bogus': 'INFO'}, f)
+        cm = _make_cm(self.tmp)
+        cfg = cm.get_logging_config()
+        self.assertEqual(cfg['python']['services']['network'], 'DEBUG')
+        self.assertEqual(cfg['python']['services']['email'], 'WARNING')
+        # Unknown service names from the legacy file are ignored.
+        self.assertNotIn('bogus', cfg['python']['services'])
+
+    def test_logging_section_is_part_of_persisted_config(self):
+        """The logging section lives in cell_config (already in the backup set)."""
+        cm = _make_cm(self.tmp)
+        cm.set_python_log_level('vault', 'ERROR')
+        with open(cm.config_file) as f:
+            on_disk = json.load(f)
+        self.assertIn('logging', on_disk)
+        self.assertEqual(on_disk['logging']['python']['services']['vault'], 'ERROR')
+
+
+if __name__ == '__main__':
+    unittest.main()

tests/test_logs_endpoints.py

@@ -79,6 +79,26 @@ class TestGetBackendLogs(unittest.TestCase):
         self.assertEqual(r.status_code, 500)
         self.assertIn('error', json.loads(r.data))
 
+    def test_get_logs_level_filter_returns_only_matching(self):
+        lines = [
+            json.dumps({'level': 'INFO', 'message': 'started'}) + '\n',
+            json.dumps({'level': 'ERROR', 'message': 'boom'}) + '\n',
+            json.dumps({'level': 'INFO', 'message': 'ok'}) + '\n',
+            json.dumps({'level': 'ERROR', 'message': 'kaboom'}) + '\n',
+        ]
+        m = mock_open(read_data=''.join(lines))
+        m.return_value.readlines = lambda: lines
+        with patch('app.auth_manager', MagicMock(spec=object)), \
+             patch('app.os.path.exists', return_value=True), \
+             patch('builtins.open', m):
+            r = self.client.get('/api/logs?level=ERROR')
+        self.assertEqual(r.status_code, 200)
+        out = json.loads(r.data)['log']
+        self.assertIn('boom', out)
+        self.assertIn('kaboom', out)
+        self.assertNotIn('started', out)
+        self.assertNotIn('"message": "ok"', out)
+
 
 class TestGetServiceLogs(unittest.TestCase):
     """GET /api/logs/services/<service>"""
@@ -309,49 +329,86 @@ class TestLogVerbosity(unittest.TestCase):
         app.config['TESTING'] = True
         self.client = app.test_client()
 
-    @patch('app.log_manager')
-    def test_get_verbosity_returns_200_with_levels_map(self, mock_lm):
-        mock_lm.get_service_levels.return_value = {
-            'dns': 'INFO',
-            'email': 'DEBUG',
-            'wireguard': 'WARNING',
+    @patch('app.config_manager')
+    def test_get_verbosity_returns_200_with_python_and_containers(self, mock_cm):
+        mock_cm.get_logging_config.return_value = {
+            'python': {'root': 'INFO', 'services': {'email': 'DEBUG', 'wireguard': 'WARNING'}},
+            'containers': {'caddy': 'INFO', 'coredns': 'DEBUG'},
         }
         r = self.client.get('/api/logs/verbosity')
         self.assertEqual(r.status_code, 200)
         data = json.loads(r.data)
-        self.assertIn('dns', data)
-        self.assertEqual(data['email'], 'DEBUG')
+        self.assertEqual(data['python']['services']['email'], 'DEBUG')
+        self.assertEqual(data['containers']['coredns'], 'DEBUG')
 
-    @patch('app.log_manager')
-    def test_get_verbosity_returns_500_on_exception(self, mock_lm):
-        mock_lm.get_service_levels.side_effect = Exception('config missing')
+    @patch('app.config_manager')
+    def test_get_verbosity_returns_500_on_exception(self, mock_cm):
+        mock_cm.get_logging_config.side_effect = Exception('config missing')
         r = self.client.get('/api/logs/verbosity')
         self.assertEqual(r.status_code, 500)
         self.assertIn('error', json.loads(r.data))
 
+    @patch('app.apply_root_log_level')
     @patch('app.log_manager')
-    def test_put_verbosity_returns_200_and_calls_set_level(self, mock_lm):
-        mock_lm.get_service_levels.return_value = {'dns': 'DEBUG'}
-        with tempfile.TemporaryDirectory() as tmpdir:
-            with patch('app.auth_manager', MagicMock(spec=object)), \
-                 patch.dict('os.environ', {'CONFIG_DIR': tmpdir}):
-                r = self.client.put(
-                    '/api/logs/verbosity',
-                    data=json.dumps({'dns': 'DEBUG'}),
-                    content_type='application/json',
-                )
+    @patch('app.config_manager')
+    def test_put_verbosity_python_applies_hot(self, mock_cm, mock_lm, mock_apply):
+        mock_cm.get_logging_config.return_value = {
+            'python': {'root': 'DEBUG', 'services': {'network': 'DEBUG'}},
+            'containers': {},
+        }
+        with patch('app.auth_manager', MagicMock(spec=object)):
+            r = self.client.put(
+                '/api/logs/verbosity',
+                data=json.dumps({'python': {'root': 'DEBUG', 'services': {'network': 'DEBUG'}}}),
+                content_type='application/json',
+            )
         self.assertEqual(r.status_code, 200)
-        mock_lm.set_service_level.assert_called_with('dns', 'DEBUG')
+        mock_cm.set_python_log_level.assert_any_call('network', 'DEBUG')
+        mock_cm.set_python_log_level.assert_any_call('root', 'DEBUG')
+        mock_lm.set_service_level.assert_called_with('network', 'DEBUG')
+        mock_apply.assert_called_with('DEBUG')
 
-    @patch('app.log_manager')
-    def test_put_verbosity_returns_500_on_exception(self, mock_lm):
-        mock_lm.set_service_level.side_effect = Exception('unknown service')
-        r = self.client.put(
-            '/api/logs/verbosity',
-            data=json.dumps({'unknown_svc': 'DEBUG'}),
-            content_type='application/json',
-        )
-        self.assertEqual(r.status_code, 500)
+    @patch('app.firewall_manager')
+    @patch('app.config_manager')
+    def test_put_verbosity_coredns_applies_hot(self, mock_cm, mock_fw):
+        mock_cm.get_logging_config.return_value = {'python': {}, 'containers': {'coredns': 'DEBUG'}}
+        mock_cm.get_internal_domain.return_value = 'cell'
+        with patch('app.auth_manager', MagicMock(spec=object)), \
+             patch('app.peer_registry', MagicMock(list_peers=lambda: [])), \
+             patch('app.cell_link_manager', MagicMock(list_connections=lambda: None)):
+            r = self.client.put(
+                '/api/logs/verbosity',
+                data=json.dumps({'containers': {'coredns': 'DEBUG'}}),
+                content_type='application/json',
+            )
+        self.assertEqual(r.status_code, 200)
+        data = json.loads(r.data)
+        self.assertEqual(data['applied']['coredns'], 'hot')
+        mock_fw.generate_corefile.assert_called_once()
+        mock_fw.reload_coredns.assert_called_once()
+
+    @patch('app.config_manager')
+    def test_put_verbosity_wireguard_returns_pending_restart(self, mock_cm):
+        mock_cm.get_logging_config.return_value = {'python': {}, 'containers': {'wireguard': 'DEBUG'}}
+        with patch('app.auth_manager', MagicMock(spec=object)):
+            r = self.client.put(
+                '/api/logs/verbosity',
+                data=json.dumps({'containers': {'wireguard': 'DEBUG'}}),
+                content_type='application/json',
+            )
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(json.loads(r.data)['applied']['wireguard'], 'pending_restart')
+
+    @patch('app.config_manager')
+    def test_put_verbosity_invalid_level_returns_400(self, mock_cm):
+        mock_cm.set_python_log_level.side_effect = ValueError('Invalid log level')
+        with patch('app.auth_manager', MagicMock(spec=object)):
+            r = self.client.put(
+                '/api/logs/verbosity',
+                data=json.dumps({'python': {'services': {'network': 'LOUD'}}}),
+                content_type='application/json',
+            )
+        self.assertEqual(r.status_code, 400)
         self.assertIn('error', json.loads(r.data))
 
 

tests/test_routes_services_catalog.py

@@ -616,25 +616,31 @@ class TestGetLogFiles:
 
 class TestGetLogVerbosity:
     def test_returns_200(self, client):
-        mock_lm = MagicMock()
-        mock_lm.get_service_levels.return_value = {'network': 'INFO'}
-        with patch.object(app_module, 'log_manager', mock_lm):
+        mock_cm = MagicMock()
+        mock_cm.get_logging_config.return_value = {
+            'python': {'root': 'INFO', 'services': {'network': 'INFO'}},
+            'containers': {'caddy': 'INFO'},
+        }
+        with patch.object(app_module, 'config_manager', mock_cm):
             resp = client.get('/api/logs/verbosity')
         assert resp.status_code == 200
 
-    def test_returns_service_levels(self, client):
-        mock_lm = MagicMock()
-        mock_lm.get_service_levels.return_value = {'network': 'DEBUG', 'email': 'INFO'}
-        with patch.object(app_module, 'log_manager', mock_lm):
+    def test_returns_python_and_container_sections(self, client):
+        mock_cm = MagicMock()
+        mock_cm.get_logging_config.return_value = {
+            'python': {'root': 'INFO', 'services': {'network': 'DEBUG', 'email': 'INFO'}},
+            'containers': {'caddy': 'WARNING'},
+        }
+        with patch.object(app_module, 'config_manager', mock_cm):
             resp = client.get('/api/logs/verbosity')
         data = json.loads(resp.data)
-        assert data['network'] == 'DEBUG'
-        assert data['email'] == 'INFO'
+        assert data['python']['services']['network'] == 'DEBUG'
+        assert data['containers']['caddy'] == 'WARNING'
 
     def test_500_on_exception(self, client):
-        mock_lm = MagicMock()
-        mock_lm.get_service_levels.side_effect = Exception('fail')
-        with patch.object(app_module, 'log_manager', mock_lm):
+        mock_cm = MagicMock()
+        mock_cm.get_logging_config.side_effect = Exception('fail')
+        with patch.object(app_module, 'config_manager', mock_cm):
             resp = client.get('/api/logs/verbosity')
         assert resp.status_code == 500
 
@@ -645,36 +651,37 @@ class TestGetLogVerbosity:
 
 class TestSetLogVerbosity:
     def test_returns_200(self, client):
-        import tempfile, os
-        mock_lm = MagicMock()
-        mock_lm.set_service_level.return_value = None
-        mock_lm.get_service_levels.return_value = {'network': 'DEBUG'}
-        with patch.object(app_module, 'log_manager', mock_lm):
-            with tempfile.TemporaryDirectory() as tmpdir:
-                with patch.dict(os.environ, {'CONFIG_DIR': tmpdir}):
-                    resp = client.put('/api/logs/verbosity',
-                                      data=json.dumps({'network': 'DEBUG'}),
-                                      content_type='application/json')
+        mock_cm = MagicMock()
+        mock_cm.get_logging_config.return_value = {
+            'python': {'root': 'INFO', 'services': {'network': 'DEBUG'}},
+            'containers': {},
+        }
+        with patch.object(app_module, 'config_manager', mock_cm), \
+             patch.object(app_module, 'log_manager', MagicMock()):
+            resp = client.put('/api/logs/verbosity',
+                              data=json.dumps({'python': {'services': {'network': 'DEBUG'}}}),
+                              content_type='application/json')
         assert resp.status_code == 200
 
-    def test_calls_set_service_level(self, client):
-        import tempfile, os
+    def test_persists_via_config_manager_and_applies_hot(self, client):
+        mock_cm = MagicMock()
+        mock_cm.get_logging_config.return_value = {'python': {}, 'containers': {}}
         mock_lm = MagicMock()
-        mock_lm.get_service_levels.return_value = {}
-        with patch.object(app_module, 'log_manager', mock_lm):
-            with tempfile.TemporaryDirectory() as tmpdir:
-                with patch.dict(os.environ, {'CONFIG_DIR': tmpdir}):
-                    client.put('/api/logs/verbosity',
-                               data=json.dumps({'network': 'DEBUG'}),
-                               content_type='application/json')
+        with patch.object(app_module, 'config_manager', mock_cm), \
+             patch.object(app_module, 'log_manager', mock_lm):
+            client.put('/api/logs/verbosity',
+                       data=json.dumps({'python': {'services': {'network': 'DEBUG'}}}),
+                       content_type='application/json')
+        mock_cm.set_python_log_level.assert_called_with('network', 'DEBUG')
         mock_lm.set_service_level.assert_called_with('network', 'DEBUG')
 
     def test_500_on_exception(self, client):
-        mock_lm = MagicMock()
-        mock_lm.set_service_level.side_effect = Exception('fail')
-        with patch.object(app_module, 'log_manager', mock_lm):
+        mock_cm = MagicMock()
+        mock_cm.set_python_log_level.side_effect = Exception('fail')
+        with patch.object(app_module, 'config_manager', mock_cm), \
+             patch.object(app_module, 'log_manager', MagicMock()):
             resp = client.put('/api/logs/verbosity',
-                              data=json.dumps({'network': 'DEBUG'}),
+                              data=json.dumps({'python': {'services': {'network': 'DEBUG'}}}),
                               content_type='application/json')
         assert resp.status_code == 500