diff --git a/logger_interface.py b/logger_interface.py index 5799302..4cac5f1 100644 --- a/logger_interface.py +++ b/logger_interface.py @@ -1,44 +1,81 @@ import traceback +from contextlib import contextmanager +from contextvars import ContextVar +from uuid import uuid4 + +_ACTIVE_LOG_GROUP = ContextVar('appdaemon_log_group', default=None) + + +@contextmanager +def log_group(kind, label=None, *, inherit=True): + """Tag LoggerInterface messages in this synchronous operation with one group ID.""" + parent = _ACTIVE_LOG_GROUP.get() if inherit else None + group = parent or { + 'id': uuid4().hex[:12], + 'kind': kind, + 'label': str(label) if label is not None else '', + } + token = _ACTIVE_LOG_GROUP.set(group) + try: + yield group + finally: + _ACTIVE_LOG_GROUP.reset(token) + + class LoggerInterface: - def __init__(self): self.initialized = False - def __init__(self,ad_api, default_log = "main_log",mute = False): - self.initialize_logger_interface(ad_api,default_log,mute) + def __init__(self, ad_api, default_log='main_log', mute=False): + self.initialize_logger_interface(ad_api, default_log, mute) - def initialize_logger_interface(self,ad_api, default_log = "main_log",mute = False): + def initialize_logger_interface(self, ad_api, default_log='main_log', mute=False): self.ad_api = ad_api self.default_log = default_log self.mute = False self.initialized = True - def mute_logger(self,mute : bool): + def log_group(self, kind, label=None): + return log_group(kind, label) + + @staticmethod + def _tag_log_message(message): + group = _ACTIVE_LOG_GROUP.get() + if group is None: + return message + marker = f"[group={group['kind']}:{group['id']}]" + if isinstance(message, str) and marker in message: + return message + return f"{message} {marker}" + + def mute_logger(self, mute: bool): if mute: - self.ad_api.log("Muting logger",level = "INFO", log = self.default_log) + self.ad_api.log(self._tag_log_message('Muting logger'), level='INFO', log=self.default_log) self.mute = bool(mute) - def log_info(self,message): + def log_info(self, message): assert self.initialized if not self.mute: - self.ad_api.log(message,level = "INFO", log = self.default_log) + self.ad_api.log(self._tag_log_message(message), level='INFO', log=self.default_log) - def log_warning(self,message): + def log_warning(self, message): assert self.initialized - self.ad_api.log(message,level = "WARNING", log = self.default_log) + self.ad_api.log(self._tag_log_message(message), level='WARNING', log=self.default_log) - def log_error(self,message,stop_app = False,dump_stack = False): + def log_error(self, message, stop_app=False, dump_stack=False): assert self.initialized if dump_stack: - stack = "\n" + stack = '\n' for line in traceback.format_stack()[:-1]: stack += line.strip() + '\n' - else: stack = "" + else: + stack = '' + + message = self._tag_log_message(message) + self.ad_api.log(message, level='ERROR', log=self.default_log) + self.ad_api.log(message + stack, level='ERROR', log='error_log') - self.ad_api.log(message,level = "ERROR", log = self.default_log) - self.ad_api.log(message + stack,level = "ERROR", log = "error_log") - if stop_app: - self.stop_app(self.name) \ No newline at end of file + self.stop_app(self.name) diff --git a/smartcondition.py b/smartcondition.py index 2116aaf..eff2d75 100644 --- a/smartcondition.py +++ b/smartcondition.py @@ -1,6 +1,7 @@ #import appdaemon.plugins.hass.hassapi as hass import enum from datetime import datetime +from contextlib import nullcontext #from pickle import FALSE from adexpressioncontext import ADExpressionContext @@ -56,6 +57,7 @@ class Evaluator(): self.__no_log_prefix = parser.parse_args('no_log_prefix',False) #as no_log_prefix is used to feedback parser error, it need to be defined first condition_name = parser.parse_args('condition_name',None,['log_prefix']) + self.__trace_name = ', '.join(map(str, condition_name)) if isinstance(condition_name, list) else str(condition_name or 'condition') if condition_name: if isinstance(condition_name,list): for name in condition_name: @@ -161,14 +163,24 @@ class Evaluator(): raise e + def __log_group(self): + # SmartObject itself implements LoggerInterface, but many evaluators are + # constructed with only the app as their API and no logger_interface kwarg. + logger = self.__logger_interface or self.__appdaemon_api + group_scope = getattr(logger, 'log_group', None) + if callable(group_scope): + return group_scope('smartcondition', self.__trace_name) + return nullcontext() + def evaluate(self,log = True): - try: result = self.__evaluate() - except EvaluationException as e: - self.__log(f"{e}",level = "ERROR") - return None - if log: - self.log_evaluation_result() - return result + with self.__log_group(): + try: result = self.__evaluate() + except EvaluationException as e: + self.__log(f"{e}",level = "ERROR") + return None + if log: + self.log_evaluation_result() + return result def log_callback_trigger_reason(self): if self.__callback_trigger_reason_log_string: @@ -491,6 +503,10 @@ class Evaluator(): self.__last_evaluation_result = new_result def __trigger_callbacks(self,trigger_reason,triggered_from_activation = False): + with self.__log_group(): + return self.__trigger_callbacks_in_group(trigger_reason, triggered_from_activation) + + def __trigger_callbacks_in_group(self,trigger_reason,triggered_from_activation = False): has_log_trigger_reason = False has_evaluation_result = False diff --git a/smartobject.py b/smartobject.py index ece777a..4cec20f 100644 --- a/smartobject.py +++ b/smartobject.py @@ -183,10 +183,22 @@ class SmartObject(hass.Hass,LoggerInterface): # mute → entity → constants → templates_library → virtual_sensors # → attributes_override → dataset restore → on_initialize_smart_object() def initialize(self): + self.initialize_logger_interface(self.get_ad_api()) + with self.log_group('initialization', self.name) as group: + self.log(f"Initialization started [group=initialization:{group['id']}]") + try: + succeeded = self._initialize_smart_object() + except BaseException: + self.log(f"Initialization failed [group=initialization:{group['id']}]", level='ERROR') + raise + status = 'completed' if succeeded else 'failed' + level = 'INFO' if succeeded else 'ERROR' + self.log(f"Initialization {status} [group=initialization:{group['id']}]", level=level) + + def _initialize_smart_object(self): try: #self.depends_on_module(["smartobject","virtualsensors","logger_interface"]) - self.initialize_logger_interface(self.get_ad_api()) self.log_info(f"Name = {self.name}") # mute: true → suppress all log output for this app try: self.mute_logger(self.args['mute']) @@ -272,8 +284,10 @@ class SmartObject(hass.Hass,LoggerInterface): self.log_info(self.get_dataset_name() + " loaded") except (FileNotFoundError,EOFError): pass #self.log_info("File " + self.get_dataset_name() + " not found (and it's ok)") self.on_initialize_smart_object() - except ParsingException as e: self.log_error(str(e),stop_app = True) - + except ParsingException as e: + self.log_error(str(e), stop_app=True) + return False + return True # AppDaemon shutdown hook. Persists self.dataset to disk (if set). def terminate(self): diff --git a/unit_tests/test_events_forwarder.py b/unit_tests/test_events_forwarder.py index 1ff7f8e..048168d 100644 --- a/unit_tests/test_events_forwarder.py +++ b/unit_tests/test_events_forwarder.py @@ -31,7 +31,11 @@ classes = load_classes(TOOLBOX / 'eventsforwarder.py', { class ForwarderTests(unittest.TestCase): def setUp(self): - self.owner = Mock() + # Do not fabricate optional API methods such as log_group on lookup. + self.owner = Mock(spec=[ + 'entity_exists', 'get_state', 'log', 'log_info', 'log_warning', + 'log_error', 'fire_event', 'call_service', + ]) self.states = {'media_player.bravia_theatre': 'off', 'binary_sensor.is_tv_on': 'off'} self.owner.entity_exists.side_effect = lambda entity: entity in self.states diff --git a/unit_tests/test_logger_interface_grouping.py b/unit_tests/test_logger_interface_grouping.py new file mode 100644 index 0000000..7fb4a78 --- /dev/null +++ b/unit_tests/test_logger_interface_grouping.py @@ -0,0 +1,109 @@ +"""Verify scoped log grouping without replacing AppDaemon API methods.""" +import os +import pickle +import sys +import tempfile +import unittest +from pathlib import Path +from types import SimpleNamespace + +TOOLBOX = Path(__file__).resolve().parents[1] +sys.path.insert(0, str(TOOLBOX)) +from logger_interface import LoggerInterface +import smartcondition + + +def load_smart_object(): + source = (TOOLBOX / 'smartobject.py').read_text() + import ast + tree = ast.parse(source) + smart_object = next(node for node in tree.body + if isinstance(node, ast.ClassDef) and node.name == 'SmartObject') + class FakeHass: + def log(self, message, level='INFO', log=None): + self.rows.append((level, message, log)) + namespace = {'hass': SimpleNamespace(Hass=FakeHass), + 'LoggerInterface': LoggerInterface, 'VirtualSensors': object, + 'ParsingException': type('ParsingException', (Exception,), {}), + 'pickle': pickle, 'os': os} + exec(compile(ast.Module(body=[smart_object], type_ignores=[]), str(TOOLBOX / 'smartobject.py'), 'exec'), namespace) + return namespace['SmartObject'] + + +class FakeApp(LoggerInterface): + name = 'fake_app' + + def __init__(self): + self.rows = [] + super().__init__(self) + + def log(self, message, level='INFO', log=None): + self.rows.append((level, message, log)) + + def initialize(self): + self.log_info('LoggerInterface initialization message') + self.log('Direct app log stays readable') + + +class LoggerGroupingTests(unittest.TestCase): + def test_initialize_is_not_implicitly_wrapped_or_tagged(self): + app = FakeApp() + original_initialize = app.initialize.__func__ + original_log = app.log.__func__ + app.initialize() + self.assertIs(app.initialize.__func__, original_initialize) + self.assertIs(app.log.__func__, original_log) + self.assertEqual(app.rows[0][1], 'LoggerInterface initialization message') + self.assertEqual(app.rows[1][1], 'Direct app log stays readable') + + def test_smart_object_groups_its_own_lifecycle(self): + SmartObject = load_smart_object() + app = SmartObject.__new__(SmartObject) + app.rows = [] + app.name = 'test_smart_object' + app.args = {} + with tempfile.TemporaryDirectory() as folder: + app.AD = SimpleNamespace(app_dir=folder) + app.get_ad_api = lambda: app + app.on_initialize_smart_object = lambda: app.log_info('Subclass initialization hook') + app.initialize() + self.assertIn('Initialization started [group=initialization:', app.rows[0][1]) + group_id = app.rows[0][1].split(':', 1)[1].rstrip(']') + self.assertIn(f'[group=initialization:{group_id}]', app.rows[1][1]) + self.assertIn(f'[group=initialization:{group_id}]', app.rows[2][1]) + self.assertEqual(app.rows[-1][1], f'Initialization completed [group=initialization:{group_id}]') + + def test_smartcondition_uses_smartobject_api_scope_without_logger_interface_argument(self): + app = FakeApp() + evaluator = smartcondition.Evaluator.__new__(smartcondition.Evaluator) + evaluator._Evaluator__logger_interface = None + evaluator._Evaluator__appdaemon_api = app + evaluator._Evaluator__trace_name = 'smart_conditions' + with evaluator._Evaluator__log_group(): + app.log_info('Callback trigger by sensor.example(0 => 1)') + app.log_info('[smart_conditions][Evaluating] Triggered by condition') + marker_a = app.rows[0][1].split('[group=')[1].rstrip(']') + marker_b = app.rows[1][1].split('[group=')[1].rstrip(']') + self.assertEqual(marker_a, marker_b) + self.assertTrue(marker_a.startswith('smartcondition:')) + + def test_nested_scopes_inherit_outer_group_and_reset_after_exception(self): + app = FakeApp() + with app.log_group('value_selector', 'sensor.a') as outer: + app.log_info('candidate rejected') + with app.log_group('smartcondition', 'condition-a') as inner: + self.assertIs(inner, outer) + app.log_info('condition result') + app.log_info('outside group') + self.assertIn(f'[group=value_selector:{outer["id"]}]', app.rows[0][1]) + self.assertIn(f'[group=value_selector:{outer["id"]}]', app.rows[1][1]) + self.assertEqual(app.rows[2][1], 'outside group') + with self.assertRaises(RuntimeError): + with app.log_group('smartcondition'): + raise RuntimeError('expected') + app.log_info('after failure') + self.assertEqual(app.rows[3][1], 'after failure') + + +if __name__ == '__main__': + unittest.main() diff --git a/vscode-appdaemon/media/logExplorer.css b/vscode-appdaemon/media/logExplorer.css index 7066367..a991b56 100644 --- a/vscode-appdaemon/media/logExplorer.css +++ b/vscode-appdaemon/media/logExplorer.css @@ -1,4 +1,8 @@ :root{color-scheme:dark light;--bg:var(--vscode-editor-background,#111820);--fg:var(--vscode-editor-foreground,#dae3ed);--panel:var(--vscode-sideBar-background,#18212c);--border:var(--vscode-panel-border,#334252);--muted:var(--vscode-descriptionForeground,#a0afbf);--accent:var(--vscode-focusBorder,#6caef0)} *{box-sizing:border-box}body{margin:0;background:var(--bg);color:var(--fg);font:13px var(--vscode-font-family,system-ui,sans-serif)}header{padding:22px 24px 16px;display:flex;justify-content:space-between;gap:20px;align-items:center}h1{font-size:21px;margin:0}h1 span{font-weight:400;color:var(--muted);font-size:16px;margin-left:10px}p{color:var(--muted);line-height:1.6}header p{margin:7px 0 0}.actions{display:flex;gap:8px}button,input,select{font:inherit;color:var(--fg);background:var(--panel);border:1px solid var(--border);border-radius:6px;padding:8px 10px}button{cursor:pointer}button:hover{border-color:var(--accent)}button:focus-visible,input:focus-visible,select:focus-visible,summary:focus-visible{outline:2px solid var(--accent);outline-offset:2px}button[aria-pressed=true]{border-color:var(--accent);color:var(--accent)}nav{display:flex;align-items:center;gap:10px;padding:0 24px 18px;flex-wrap:wrap}nav input[type=search]{flex:1;min-width:220px}nav label{display:flex;align-items:center;gap:6px;color:var(--muted)}main{display:grid;grid-template-columns:minmax(350px,1fr) minmax(380px,1fr);border-top:1px solid var(--border);height:calc(100vh - 150px)}section{overflow:auto;padding:18px 20px}.apps{border-right:1px solid var(--border)}.section-title{display:flex;justify-content:space-between;align-items:center;margin-bottom:15px;gap:10px}h2{font-size:14px;margin:0}.section-title>span{color:var(--muted)}details{border:1px solid var(--border);border-radius:8px;margin-bottom:10px;background:var(--panel)}summary{cursor:pointer;padding:12px;display:flex;align-items:center;gap:10px}summary:before{content:'▸';color:var(--muted)}details[open]>summary:before{content:'▾'}summary .name{flex:1;overflow-wrap:anywhere}.badge{border-radius:5px;padding:3px 6px;font-size:11px;font-weight:600;white-space:nowrap}.INFO,.DEBUG{color:#91c5fa;background:#284561}.WARNING{color:#f3cd80;background:#594925}.ERROR,.CRITICAL{color:#ffacac;background:#5b3039}.rows{border-top:1px solid var(--border)}.row{display:block;width:100%;text-align:left;border:0;border-radius:0;background:transparent;padding:11px 13px;border-bottom:1px solid var(--border)}.row:last-child{border-bottom:0}.row.selected{background:var(--vscode-list-activeSelectionBackground,#263f57);box-shadow:inset 3px 0 var(--accent)}.row-meta{display:flex;align-items:center;gap:8px;color:var(--muted);font-size:11px;margin-bottom:5px}.row-message{white-space:pre-wrap;overflow-wrap:anywhere;line-height:1.5}.link-hint{margin-left:auto;color:var(--accent)}.empty{padding:40px 15px;color:var(--muted);line-height:1.6;text-align:center}.selected-message{font-size:15px;line-height:1.5;white-space:pre-wrap;overflow-wrap:anywhere}.metadata{color:var(--muted);font-size:12px;margin:8px 0 15px}.legend{color:var(--muted);font-size:12px;margin:15px 0}.graph{overflow:auto;position:relative;margin:20px 0;min-height:120px}.graph svg{position:absolute;left:0;top:0;pointer-events:none}.graph-stage{position:relative}.node{position:absolute;width:320px;height:115px;overflow:auto;padding:12px;text-align:left;background:var(--panel);font-size:12px;line-height:1.5}.node strong{display:block;color:var(--accent);margin-bottom:5px}.node .text{white-space:pre-wrap;overflow-wrap:anywhere}.node.target{border-color:var(--accent)}.node.missing{border-style:dashed;color:var(--muted)}.tree ul{padding-left:23px;list-style:none;border-left:1px solid var(--border)}.tree li{margin:12px 0}.tree button{text-align:left;line-height:1.5}.tree .probable{color:#f3cd80;font-size:11px}.values{width:100%;border-collapse:collapse;font-size:12px}.values td{padding:8px;border-bottom:1px solid var(--border);overflow-wrap:anywhere}.values td:first-child{color:var(--muted)}#warnings{color:#f3cd80;padding:0 24px}#warnings:empty{display:none}.more{padding:12px;color:var(--muted)}@media(max-width:850px){main{grid-template-columns:1fr;height:auto}.apps{border-right:0;border-bottom:1px solid var(--border)}section{max-height:65vh}header{align-items:flex-start;padding:18px}nav{padding:0 18px 15px}summary{gap:6px}.badge{font-size:10px}} -.app-label{flex:1;min-width:0;display:flex;flex-direction:column;gap:5px}.last-log{color:var(--muted);font-size:11px;font-weight:400;overflow-wrap:anywhere}.row{cursor:pointer;user-select:text;-webkit-user-select:text}.row:hover{background:var(--vscode-list-hoverBackground,#203040)}.selected-message,.row-message,.node,.tree,.values{user-select:text;-webkit-user-select:text}.init-group{margin:10px;background:var(--bg)}.init-summary{font-size:12px;color:var(--muted);flex-wrap:wrap}.init-rows>button{margin:8px 12px}.section-title{flex-wrap:wrap}.section-title select{font-size:12px}.actions{flex-wrap:wrap} +.app-label{flex:1;min-width:0;display:flex;flex-direction:column;gap:5px}.last-log{color:var(--muted);font-size:11px;font-weight:400;overflow-wrap:anywhere}.row{cursor:pointer;user-select:text;-webkit-user-select:text}.row:hover{background:var(--vscode-list-hoverBackground,#203040)}.selected-message,.row-message,.node,.tree,.values{user-select:text;-webkit-user-select:text}.section-title{flex-wrap:wrap}.section-title select{font-size:12px}.actions{flex-wrap:wrap} @keyframes new-log-pulse{0%{box-shadow:inset 0 0 0 0 color-mix(in srgb,var(--accent) 0%,transparent)}25%{box-shadow:inset 0 0 0 2px color-mix(in srgb,var(--accent) 85%,transparent);background-color:color-mix(in srgb,var(--accent) 12%,var(--panel))}100%{box-shadow:inset 0 0 0 0 color-mix(in srgb,var(--accent) 0%,transparent)}}.new-log-app>summary{animation:new-log-pulse 1.8s ease-out}.recent-log{animation:new-log-pulse 1.8s ease-out}@media(prefers-reduced-motion:reduce){.new-log-app>summary,.recent-log{animation:none;outline:2px solid var(--accent);outline-offset:-2px}} + +.log-message.level-WARNING{color:var(--vscode-editorWarning-foreground,#f3cd80)}.log-message.level-ERROR{color:var(--vscode-editorError-foreground,#ffacac)} + +.block-title{font-weight:600;margin-bottom:6px;color:var(--fg);overflow-wrap:anywhere} diff --git a/vscode-appdaemon/media/logExplorer.html b/vscode-appdaemon/media/logExplorer.html index dfbd71b..c1c01da 100644 --- a/vscode-appdaemon/media/logExplorer.html +++ b/vscode-appdaemon/media/logExplorer.html @@ -4,7 +4,7 @@ AppDaemon · Logs

AppDaemon Logs

Reading logs…

- +

Applications

Log details

Select a log to view its details.

The base AppDaemon log format does not include causal links.

diff --git a/vscode-appdaemon/media/logExplorer.js b/vscode-appdaemon/media/logExplorer.js index d2dfcda..9d83da5 100644 --- a/vscode-appdaemon/media/logExplorer.js +++ b/vscode-appdaemon/media/logExplorer.js @@ -15,7 +15,6 @@ const saved = vscode.getState() || {}; let entries = [], latest, appliedMessage, displayZone = 'Europe/Berlin', paused = false, selected = saved.selected, mode = saved.mode || 'graph', origin = saved.origin || saved.selected; const expanded = new Set(saved.expanded || []); - const expandedInit = new Set(saved.expandedInit || []); const visibleEventGroups = new Map(); const recentEvents = new Set(); const recentApps = new Set(); @@ -25,7 +24,7 @@ const $ = id => document.getElementById(id); const node = (tag, text, cls) => { const e = document.createElement(tag); if (text !== undefined) e.textContent = text; if (cls) e.className = cls; return e; }; const normalLevel = e => e.level === 'CRITICAL' ? 'ERROR' : e.level; - function save() { vscode.setState({ selected, mode, origin, expanded: [...expanded], expandedInit: [...expandedInit], sort: $('sort').value, groupInit: $('group-init').checked }); } + function save() { vscode.setState({ selected, mode, origin, expanded: [...expanded], sort: $('sort').value }); } function choose(id, fromList = true) { if (fromList) origin = id; selected = id; save(); renderApps(); renderDetail(); } function filtered() { const q = $('search').value.toLowerCase(), level = $('level').value, minutes = Number($('period').value); @@ -34,7 +33,7 @@ && (level === 'all' || normalLevel(e) === level) && `${e.app} ${e.entity || ''} ${e.message}`.toLowerCase().includes(q)); } - const cleanMessage = e => e.message.replace(/ \[event=[\w-]+ trace=[\w-]+\]/g, '').replace(/ \[init=[\w-]+\]/g, ''); + const cleanMessage = e => e.message.replace(/ \[event=[\w-]+ trace=[\w-]+\]/g, '').replace(/ \[init=[\w-]+\]/g, '').replace(/ \[group=(?:initialization|smartcondition|value_selector):[a-f0-9]{12}\]/gi, ''); const formatTime = (entry, includeYear = false) => { if (!Number.isFinite(entry.time)) return entry.timestamp; try { @@ -57,6 +56,22 @@ return `${years} year${years === 1 ? '' : 's'} ago`; } function copy(text) { if (text) vscode.postMessage({ type: 'copy', text }); } + function logMessages(items, cls) { + const container = node('div', undefined, cls); + items.forEach((entry, index) => { + if (index) container.append(document.createTextNode('\n')); + container.append(node('span', cleanMessage(entry), `log-message level-${normalLevel(entry)}`)); + }); + return container; + } + function blockTitle(items, groupKey) { + const first = items[0]; + const kind = groupKey?.startsWith('initialization:') || first.initialization_id ? 'initialization' : items.find(entry => entry.group_kind)?.group_kind; + const names = { initialization: 'Initialization', smartcondition: 'Smart condition', value_selector: 'Value selector' }; + const name = names[kind] || (items.length > 1 || first.trace_id ? 'Event' : 'Log'); + const label = kind === 'initialization' ? first.app : items.map(entry => entry.group_label || cleanMessage(entry).match(/^\[([^\]]+)\]/)?.[1]).find(Boolean) || first.entity || first.app; + return node('div', `${name} · ${label}`, 'block-title'); + } function row(e) { const item = node('div', undefined, `row${selected === e.event_id ? ' selected' : ''}${recentEvents.has(e.event_id) ? ' recent-log' : ''}`); item.dataset.eventId = e.event_id; item.dataset.eventIds = e.event_id; @@ -67,23 +82,23 @@ relative.title = `${formatTime(e, true)} · Exact: ${e.timestamp}`; meta.append(relative, node('span', e.level, `badge ${normalLevel(e)}`)); if (e.cause_ids.length) meta.append(node('span', 'View causes ↗', 'link-hint')); - item.append(meta, node('div', cleanMessage(e), 'row-message')); + item.append(blockTitle([e]), meta, logMessages([e], 'row-message')); item.onclick = () => { if (!window.getSelection()?.toString()) choose(e.event_id); }; item.onkeydown = event => { if (event.key === 'Enter' || event.key === ' ') { event.preventDefault(); choose(e.event_id); } }; return item; } - function groupedByEvent(items) { + function groupedByEvent(items, groupKey) { const groups = []; items.forEach(e => { - const trace = e.kind === 'log' ? e.trace_id : undefined; + const key = groupKey || (e.group_id ? `group:${e.group_id}` : e.kind === 'log' && e.trace_id ? `trace:${e.trace_id}` : undefined); const previous = groups[groups.length - 1]; - if (trace && previous?.trace === trace) previous.entries.push(e); - else groups.push({ trace, entries: [e] }); + if (key && previous?.key === key) previous.entries.push(e); + else groups.push({ key, entries: [e] }); }); return groups; } - function appendEventRows(parent, items) { - groupedByEvent(items).forEach(unit => { + function appendEventRows(parent, items, groupKey) { + groupedByEvent(items, groupKey).forEach(unit => { if (unit.entries.length === 1) { parent.append(row(unit.entries[0])); return; } const representative = [...unit.entries].reverse().find(e => e.cause_ids?.length) || unit.entries[unit.entries.length - 1]; const ids = unit.entries.map(e => e.event_id); @@ -102,7 +117,7 @@ if (count) meta.append(node('span', count === 1 ? level : `${level} ${count}`, `badge ${level}`)); } if (unit.entries.some(e => e.cause_ids.length)) meta.append(node('span', 'View causes ↗', 'link-hint')); - item.append(meta, node('div', unit.entries.map(cleanMessage).join('\n'), 'row-message')); + item.append(blockTitle(unit.entries, groupKey), meta, logMessages(unit.entries, 'row-message')); item.onclick = () => { if (!window.getSelection()?.toString()) choose(representative.event_id); }; item.onkeydown = event => { if (event.key === 'Enter' || event.key === ' ') { event.preventDefault(); choose(representative.event_id); } }; parent.append(item); @@ -145,14 +160,14 @@ const rows = node('div', undefined, 'rows'); const units = [], initGroups = new Map(); logs.forEach(e => { - if ($('group-init').checked && e.initialization_id) { + if (e.initialization_id) { if (!initGroups.has(e.initialization_id)) { const unit = { id: e.initialization_id, entries: [] }; initGroups.set(e.initialization_id, unit); units.push(unit); } initGroups.get(e.initialization_id).entries.push(e); } else { - const trace = e.kind === 'log' ? e.trace_id : undefined; + const key = e.group_id ? `group:${e.group_id}` : e.kind === 'log' && e.trace_id ? `trace:${e.trace_id}` : undefined; const previous = units[units.length - 1]; - if (trace && previous && !previous.id && previous.trace === trace) previous.entries.push(e); - else units.push({ trace, entries: [e] }); + if (key && previous && !previous.id && previous.key === key) previous.entries.push(e); + else units.push({ key, entries: [e] }); } }); const startTime = unit => unit.id @@ -160,25 +175,7 @@ : unit.entries[0].time; units.sort((a, b) => startTime(a) - startTime(b)); units.slice(-150).forEach(unit => { - if (!unit.id) { appendEventRows(rows, unit.entries); return; } - const group = node('details', undefined, 'init-group'), key = app + ':' + unit.id; - group.open = expandedInit.has(key); - const first = entries.find(e => e.app === app && e.initialization_id === unit.id && e.kind === 'initialization_started') || unit.entries[0], last = unit.entries[unit.entries.length - 1]; - const header = node('summary', undefined, 'init-summary'); - const failed = unit.entries.some(e => normalLevel(e) === 'ERROR' || e.status === 'failed'); - header.append(node('span', `Initialization · ${formatTime(first, true)}`, 'name'), node('span', `${unit.entries.length} entries`)); - if (failed) header.append(node('span', 'ERROR', 'badge ERROR')); - header.title = `Initialization ${unit.id} · Last entry: ${formatTime(last, true)} · Exact: ${last.timestamp}`; - group.append(header); - const body = node('div', undefined, 'init-rows'); - const copyGroup = node('button', 'Copy initialization'); - copyGroup.onclick = () => copy(unit.entries.map(copyText).join('\n')); - body.append(copyGroup); - appendEventRows(body, unit.entries.slice(-150)); - if (unit.entries.length > 150) body.append(node('div', 'Showing the last 150 entries. Copy initialization includes all loaded matches.', 'more')); - group.append(body); - group.addEventListener('toggle', event => { event.stopPropagation(); group.open ? expandedInit.add(key) : expandedInit.delete(key); save(); }); - rows.append(group); + appendEventRows(rows, unit.entries, unit.id ? `initialization:${unit.id}` : undefined); }); if (units.length > 150) rows.append(node('div', `${units.length - 150} older rows/groups: narrow the time range or search.`, 'more')); detail.append(rows); @@ -194,7 +191,7 @@ $('graph-mode').parentElement.hidden = !e || !e.cause_ids.length; if (!e) { container.replaceChildren(node('div', selected ? 'This entry is no longer in the loaded history.' : 'Select a log to view its details.', 'empty')); return; } const selectedGroup = visibleEventGroups.get(e.event_id) || [e]; - container.replaceChildren(node('div', selectedGroup.map(cleanMessage).join('\n'), 'selected-message'), node('div', `${e.app} · ${e.timestamp} · ${selectedGroup.length} log lines`, 'metadata')); + container.replaceChildren(logMessages(selectedGroup, 'selected-message'), node('div', `${e.app} · ${e.timestamp} · ${selectedGroup.length} log lines`, 'metadata')); const raw = node('button', 'Open raw log'); raw.onclick = () => vscode.postMessage({ type: 'open', id: e.event_id }); container.append(raw); if (e.source) { const source = node('button', 'Open source'); source.onclick = () => vscode.postMessage({ type: 'source', id: e.event_id }); container.append(source); } if (origin && origin !== selected) { const back = node('button', 'Back to selected log'); back.onclick = () => choose(origin); container.append(back); } @@ -344,13 +341,12 @@ } }); $('copy').onclick = () => { const e = entries.find(e => e.event_id === selected); copy(window.getSelection()?.toString() || (e ? (visibleEventGroups.get(e.event_id) || [e]).map(copyText).join('\n') : '')); }; - ['search', 'period', 'level', 'group-init', 'sort'].forEach(id => $(id).addEventListener('input', () => { save(); renderApps(); })); + ['search', 'period', 'level', 'sort'].forEach(id => $(id).addEventListener('input', () => { save(); renderApps(); })); $('pause').onclick = () => { paused = !paused; $('pause').textContent = paused ? 'Resume' : 'Pause'; if (!paused && latest) apply(latest); else if (paused) $('status').textContent = 'Display paused · New events are still being collected'; }; $('import').onclick = () => vscode.postMessage({ type: 'import' }); $('graph-mode').onclick = () => { mode = 'graph'; save(); renderDetail(); }; $('tree-mode').onclick = () => { mode = 'tree'; save(); renderDetail(); }; $('sort').value = saved.sort || 'latest'; - $('group-init').checked = saved.groupInit !== false; vscode.postMessage({ type: 'ready' }); if (window.LOG_REVIEW_DATA) { apply({ timezone: 'Europe/Berlin', entries: window.LOG_REVIEW_DATA, warnings: ['Interface preview: sample data, no AppDaemon connection.'], limit: 10000 }); expanded.add('automation'); selected = 'review-5'; renderApps(); renderDetail(); } })(); diff --git a/vscode-appdaemon/src/logExplorer.ts b/vscode-appdaemon/src/logExplorer.ts index 5181692..e767d8e 100644 --- a/vscode-appdaemon/src/logExplorer.ts +++ b/vscode-appdaemon/src/logExplorer.ts @@ -169,13 +169,40 @@ export class LogExplorer implements vscode.Disposable { } finally { this.busy = false; } } private publish() { - const entries = [...this.entries.values()].sort((a, b) => a.time - b.time); + const entries = [...this.entries.values()].sort((a, b) => { + const time = a.time - b.time; + if (time) { return time; } + // Include raw app.log() lines written in the same second as initialization markers. + const priority = (entry: LogEntry) => /Initialization (?:started|completed|failed)/.test(entry.message) + ? (entry.message.includes('started') ? -1 : 1) : 0; + return priority(a) - priority(b); + }); // Legacy errors duplicated across main/error logs are merged only on exact match. const seen = new Set(); const unique = entries.filter(e => { const key = e.trace_id ? e.event_id : `${e.timestamp}|${e.app}|${e.level}|${e.message}`; if (seen.has(key)) { return false; } seen.add(key); return true; }); + // Direct app.log() calls have no LoggerInterface tag. Infer their initialization + // group while an explicit per-app initialize() scope is open. + const activeInitialization = new Map(); + for (const entry of unique) { + const marker = entry.message.match(/Initialization (started|completed|failed) \[group=initialization:([a-f0-9]{12})\]/i); + if (marker?.[1] === 'started') { activeInitialization.set(entry.app, marker[2]); } + const activeId = activeInitialization.get(entry.app); + if (activeId && !entry.group_id) { + entry.group_id = activeId; + entry.group_kind = 'initialization'; + entry.initialization_id = activeId; + entry.phase = 'initialization'; + entry.group_inferred = true; + } + if (entry.group_kind === 'initialization') { + entry.initialization_id = entry.initialization_id || entry.group_id; + entry.phase = 'initialization'; + } + if (marker && (marker[1] === 'completed' || marker[1] === 'failed')) { activeInitialization.delete(entry.app); } + } const zone = vscode.workspace.getConfiguration('appdaemon').get('logTimezone', 'Europe/Berlin'); this.activeWebview?.postMessage({ type: 'entries', entries: unique, warnings: [...this.warnings], limit: 10000, timezone: zone }); } diff --git a/vscode-appdaemon/src/logModel.ts b/vscode-appdaemon/src/logModel.ts index f2c419d..887e29e 100644 --- a/vscode-appdaemon/src/logModel.ts +++ b/vscode-appdaemon/src/logModel.ts @@ -4,6 +4,7 @@ export interface LogEntry { entity?: string; values?: Record; source?: { path: string; line: number }; initialization_id?: string; phase?: string; status?: string; + group_id?: string; group_kind?: string; group_inferred?: boolean; file?: string; raw?: string; time: number; trace_id?: string; [key: string]: unknown; } @@ -38,8 +39,11 @@ export function parseLine(line: string, file: string, offset: number, zone = 'Eu const m = line.match(/^(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}(?:\.\d+)?)\s+(DEBUG|INFO|WARNING|ERROR|CRITICAL)\s+([^:]+):\s?(.*)$/); if (!m) { return undefined; } const init = m[4].match(/\[init=([\w-]+)\]/); + const group = m[4].match(/\[group=(initialization|smartcondition|value_selector):([a-f0-9]{12})\]/i); const id = m[4].match(/\[event=([\w-]+) trace=([\w-]+)\]/); - return { event_id: id?.[1] || `${file}:${offset}`, trace_id: id?.[2], initialization_id: init?.[1], phase: init ? 'initialization' : undefined, timestamp: m[1], time: rawTime(m[1], zone), app: m[3].trim(), level: m[2], message: m[4], kind: 'log', cause_ids: [], file, raw: line }; + const groupKind = group?.[1]?.toLowerCase(); + const initializationId = groupKind === 'initialization' ? group?.[2] : init?.[1]; + return { event_id: id?.[1] || `${file}:${offset}`, trace_id: id?.[2], initialization_id: initializationId, phase: initializationId ? 'initialization' : undefined, group_id: group?.[2], group_kind: groupKind, timestamp: m[1], time: rawTime(m[1], zone), app: m[3].trim(), level: m[2], message: m[4], kind: 'log', cause_ids: [], file, raw: line }; } /** Preserve valid UTF-8 spans, including files containing mixed legacy bytes. */ diff --git a/vscode-appdaemon/tests/logExplorer.test.js b/vscode-appdaemon/tests/logExplorer.test.js index caf5dd3..27e7fc4 100644 --- a/vscode-appdaemon/tests/logExplorer.test.js +++ b/vscode-appdaemon/tests/logExplorer.test.js @@ -45,3 +45,18 @@ test('bounds retained history',()=>{ e.poll();e.poll();assert.ok(e.entries.size<=10000); }); process.on('exit',()=>fs.rmSync(root,{recursive:true,force:true})); + +test('groups plain app.log lines between explicit initialization markers',()=>{ + const e=explorer();messages=[]; + fs.writeFileSync(file,[ + '27-09-26 10:12:13 INFO kitchen: Initialization started [group=initialization:0123456789ab]', + '27-09-26 10:12:13 INFO kitchen: Setting up an output through app.log()', + '27-09-26 10:12:14 INFO kitchen: Configured helper [group=initialization:0123456789ab]', + '27-09-26 10:12:14 INFO kitchen: Initialization completed [group=initialization:0123456789ab]' + ].join('\n')+'\n');e.poll(); + const grouped=latest().filter(entry=>entry.app==='kitchen'); + assert.equal(grouped.length,4); + assert.deepEqual(grouped.map(entry=>entry.initialization_id),Array(4).fill('0123456789ab')); + assert.equal(grouped[1].group_inferred,true); + assert.equal(grouped[2].group_inferred,undefined); +}); diff --git a/vscode-appdaemon/tests/logModel.test.js b/vscode-appdaemon/tests/logModel.test.js index e30b441..cd6d846 100644 --- a/vscode-appdaemon/tests/logModel.test.js +++ b/vscode-appdaemon/tests/logModel.test.js @@ -27,3 +27,9 @@ test('raw initialization IDs are retained without structured events', () => { const e=parseLine('27-09-26 10:12:13 INFO app: Setting up [event=e1 trace=t1] [init=init1]','log',0); assert.equal(e.initialization_id,'init1'); assert.equal(e.phase,'initialization'); }); + +test('parses readable group tags without changing the log message format', () => { + const e=parseLine('27-09-26 10:12:13 INFO app: Selected value [group=value_selector:0123456789ab]','log',0); + assert.equal(e.group_id,'0123456789ab'); assert.equal(e.group_kind,'value_selector'); + assert.equal(e.initialization_id,undefined); assert.match(e.message,/\[group=value_selector:/); +}); diff --git a/vscode-appdaemon/tests/logUi.test.js b/vscode-appdaemon/tests/logUi.test.js index 4376f05..27d44a1 100644 --- a/vscode-appdaemon/tests/logUi.test.js +++ b/vscode-appdaemon/tests/logUi.test.js @@ -26,18 +26,20 @@ test('English interface, latest timestamps, sorting and separate initialization d.getElementById('sort').value='oldest';d.getElementById('sort').dispatchEvent(new dom.window.Event('input')); assert.equal(d.querySelector('[data-app]').dataset.app,'alpha'); const alpha=d.querySelector('[data-app="alpha"]');alpha.open=true;alpha.dispatchEvent(new dom.window.Event('toggle')); - assert.equal(alpha.querySelectorAll('.init-group').length,2); - d.getElementById('group-init').checked=false;d.getElementById('group-init').dispatchEvent(new dom.window.Event('input')); - assert.equal(d.querySelectorAll('.init-group').length,0); - assert.equal(d.querySelector('[data-app="alpha"]').querySelectorAll('.row').length,4); + assert.equal(alpha.querySelectorAll('.rows>.row').length,3); + assert.equal(alpha.querySelectorAll('.event-log-group').length,1); + assert.equal(alpha.querySelector('.event-log-group .row-message').textContent,'Preparing sensors\nReady'); + assert.equal(alpha.querySelectorAll('.rows details').length,0); + assert.equal(d.getElementById('group-init'),null); assert.deepEqual(errors,[]);dom.window.close(); }); test('copies selected logs and entire initialization groups through VS Code transport',()=>{ const {dom,d,sent,errors}=setup();const alpha=d.querySelector('[data-app="alpha"]');alpha.open=true;alpha.dispatchEvent(new dom.window.Event('toggle')); [...alpha.querySelectorAll('.row')].find(e=>e.textContent.includes('Température déjà disponible')).click();d.getElementById('copy').click(); assert.equal(sent.at(-1).type,'copy');assert.match(sent.at(-1).text,/Température déjà disponible/); - const groups=[...alpha.querySelectorAll('.init-group')]; - groups.find(e=>e.textContent.includes('Preparing sensors')).querySelector('.init-rows>button').click(); + const group=alpha.querySelector('.event-log-group'); + group.click();d.getElementById('copy').click(); + assert.match(d.getElementById('detail').textContent,/Preparing sensors\s+Ready/); assert.match(sent.at(-1).text,/Preparing sensors/);assert.match(sent.at(-1).text,/Ready/);assert.doesNotMatch(sent.at(-1).text,/Restarting/); const input=d.getElementById('search'),paste=new dom.window.KeyboardEvent('keydown',{key:'v',ctrlKey:true,bubbles:true,cancelable:true});input.dispatchEvent(paste);assert.equal(paste.defaultPrevented,false); assert.deepEqual(errors,[]);dom.window.close(); @@ -140,3 +142,18 @@ test('shows and refreshes relative time on each log entry while retaining exact dom.window.close(); }); + +test('shows consecutive logs from one explicit group as a single visible row',()=>{ + const {dom,d,entries,send}=setup(); + const group=[ + {...entries[3],event_id:'selector-1',time:entries[3].time+1000,message:'Rejected candidate',group_id:'0123456789ab',group_kind:'value_selector'}, + {...entries[3],event_id:'selector-2',time:entries[3].time+1000,message:'Selected candidate',group_id:'0123456789ab',group_kind:'value_selector'} + ]; + send(group); + const app=d.querySelector('[data-app="alpha"]');app.open=true;app.dispatchEvent(new dom.window.Event('toggle')); + const rows=[...app.querySelectorAll('.rows>.row')].filter(row=>row.textContent.includes('Rejected candidate')); + assert.equal(rows.length,1);assert.ok(rows[0].classList.contains('event-log-group')); + assert.match(rows[0].querySelector('.row-message').textContent,/Rejected candidate\nSelected candidate/); + assert.doesNotMatch(rows[0].textContent,/\[group=/); + dom.window.close(); +}); diff --git a/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix b/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix index bcff495..9e2097a 100644 Binary files a/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix and b/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix differ