diff --git a/eventsforwarder.py b/eventsforwarder.py index 8d7c757..96ea8b4 100644 --- a/eventsforwarder.py +++ b/eventsforwarder.py @@ -43,23 +43,25 @@ class ServiceCaller(ConditionalAction): class EventsForwarder(hass.Hass, LoggerInterface): def initialize(self): - self.initialize_logger_interface(self.get_ad_api()) - self.mute_logger(self.args.get('mute', False)) - self.forwarders = {} - self.services_caller = {} - self.event_handlers = [] - for key, block in self.args.get('forwarders', {}).items(): - try: - senders = [EventSender(self, config) - for config in block.get('events_to_send', {}).values()] - callers = [ServiceCaller(self, config) - for config in block.get('services_to_call', {}).values()] - self.forwarders[key] = senders - self.services_caller[key] = callers - self.event_handlers.append(EventHandler( - self, block['events_to_listen'], self.on_event, key)) - except ParsingException as error: - self.log_error(f"Invalid forwarder {key}: {error}") + with self.log_group("App Initialization"): + self.initialize_logger_interface(self.get_ad_api()) + self.mute_logger(self.args.get('mute', False)) + self.forwarders = {} + self.services_caller = {} + self.event_handlers = [] + for key, block in self.args.get('forwarders', {}).items(): + try: + senders = [EventSender(self, config) + for config in block.get('events_to_send', {}).values()] + callers = [ServiceCaller(self, config) + for config in block.get('services_to_call', {}).values()] + self.forwarders[key] = senders + self.services_caller[key] = callers + self.event_handlers.append(EventHandler( + self, block['events_to_listen'], self.on_event, key)) + except ParsingException as error: + self.log_error(f"Invalid forwarder {key}: {error}") + self.log_info("Initialisation completed") def on_event(self, event_name, event_data, forwarder_key): for sender in self.forwarders.get(forwarder_key, []): diff --git a/smartcondition.py b/smartcondition.py index eff2d75..4c6f5f5 100644 --- a/smartcondition.py +++ b/smartcondition.py @@ -57,7 +57,13 @@ 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') + log_group = parser.parse_args('log_group',None) + if log_group is not None: + self.__log_group = str(log_group) + elif isinstance(condition_name, list): + self.__log_group = ', '.join(map(str, condition_name)) + else: + self.__log_group = str(condition_name or 'condition') if condition_name: if isinstance(condition_name,list): for name in condition_name: @@ -163,17 +169,17 @@ class Evaluator(): raise e - def __log_group(self): + def __log_group_scope(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 group_scope(self.__log_group) return nullcontext() def evaluate(self,log = True): - with self.__log_group(): + with self.__log_group_scope(): try: result = self.__evaluate() except EvaluationException as e: self.__log(f"{e}",level = "ERROR") @@ -503,7 +509,7 @@ class Evaluator(): self.__last_evaluation_result = new_result def __trigger_callbacks(self,trigger_reason,triggered_from_activation = False): - with self.__log_group(): + with self.__log_group_scope(): return self.__trigger_callbacks_in_group(trigger_reason, triggered_from_activation) def __trigger_callbacks_in_group(self,trigger_reason,triggered_from_activation = False): diff --git a/smartobject.py b/smartobject.py index 4cec20f..d00332c 100644 --- a/smartobject.py +++ b/smartobject.py @@ -184,16 +184,16 @@ class SmartObject(hass.Hass,LoggerInterface): # → 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']}]") + with self.log_group('App Initialization') as group: + self.log(f"Initialization started [group={group['kind']}:{group['id']}]") try: succeeded = self._initialize_smart_object() except BaseException: - self.log(f"Initialization failed [group=initialization:{group['id']}]", level='ERROR') + self.log(f"Initialization failed [group={group['kind']}:{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) + self.log(f"Initialization {status} [group={group['kind']}:{group['id']}]", level=level) def _initialize_smart_object(self): try: diff --git a/unit_tests/test_logger_interface_grouping.py b/unit_tests/test_logger_interface_grouping.py index 7fb4a78..4691ff4 100644 --- a/unit_tests/test_logger_interface_grouping.py +++ b/unit_tests/test_logger_interface_grouping.py @@ -78,8 +78,8 @@ class LoggerGroupingTests(unittest.TestCase): 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(): + evaluator._Evaluator__log_group = 'smart_conditions' + with evaluator._Evaluator__log_group_scope(): 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(']') @@ -87,6 +87,19 @@ class LoggerGroupingTests(unittest.TestCase): self.assertEqual(marker_a, marker_b) self.assertTrue(marker_a.startswith('smartcondition:')) + def test_log_group_takes_priority_over_condition_name(self): + app = FakeApp() + evaluator = smartcondition.Evaluator(app, {}, activated=False, + condition_name='condition-a', log_group='group-a') + self.assertEqual(evaluator._Evaluator__log_group, 'group-a') + self.assertEqual(evaluator._Evaluator__log_to_string('message'), '[condition-a] message') + with evaluator._Evaluator__log_group_scope() as group: + self.assertEqual(group['label'], 'group-a') + + fallback = smartcondition.Evaluator(app, {}, activated=False, + condition_name=['condition-a', 'condition-b']) + self.assertEqual(fallback._Evaluator__log_group, 'condition-a, condition-b') + def test_nested_scopes_inherit_outer_group_and_reset_after_exception(self): app = FakeApp() with app.log_group('value_selector', 'sensor.a') as outer: diff --git a/virtualsensors.py b/virtualsensors.py index 5bf9511..75a61b0 100644 --- a/virtualsensors.py +++ b/virtualsensors.py @@ -542,10 +542,18 @@ class BinarySensor(VirtualSensorBase): self.output_sensor.set_state(state = new_value) def on_sensor_change(self,prev_result,result): - if result == SmartCondition.Result.Unavailable: self.output_sensor.set_state(state = 'unavailable') - elif result == SmartCondition.Result.Succeeded: self.output_sensor.set_state(state = 'on') - elif result == SmartCondition.Result.Failed: self.output_sensor.set_state(state = 'off') - # else: Disabled means we keep the previous value + target_state = None + if result == SmartCondition.Result.Unavailable: target_state = 'unavailable' + elif result == SmartCondition.Result.Succeeded: target_state = 'on' + elif result == SmartCondition.Result.Failed: target_state = 'off' + else: target_state = None #Disabled means we keep the previous value + + if target_state != None: + self.output_sensor.set_state(state = target_state) + self.log_info(f"{self.sensor_name} = {target_state}") + else: + self.log_info(f"SmartCondition of {self.sensor_name} is disabled") + def generate_dependencies_list(self): dependencies = list() diff --git a/vscode-appdaemon/README.md b/vscode-appdaemon/README.md index 5c26a6b..f91b6cf 100644 --- a/vscode-appdaemon/README.md +++ b/vscode-appdaemon/README.md @@ -21,7 +21,7 @@ The explorer groups lines by the app name in the standard AppDaemon log format. **AD Logs** turns red when the loaded logs contain an ERROR or CRITICAL entry. **Clear logs** empties the configured log files and clears the current explorer history. -The standard AppDaemon text logs do not contain causal links or reliable initialization boundaries. The details panel will say so for ordinary entries. Existing messages that already contain trace or initialization metadata can still be grouped or linked; the explorer does not create that metadata. No AppDaemon Python changes are needed for this raw-log view. +Lines carrying the same `[group=:]` marker are grouped together, and the supplied name is shown in the explorer. Ordinary AppDaemon lines without a group marker remain individual log entries. Trace metadata can still be used for causal links where present. ## Settings diff --git a/vscode-appdaemon/media/logExplorer.js b/vscode-appdaemon/media/logExplorer.js index 1e4f27c..9121205 100644 --- a/vscode-appdaemon/media/logExplorer.js +++ b/vscode-appdaemon/media/logExplorer.js @@ -26,7 +26,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, '').replace(/ \[group=(?:initialization|smartcondition|value_selector):[a-f0-9]{12}\]/gi, ''); + const cleanMessage = e => e.message.replace(/ \[event=[\w-]+ trace=[\w-]+\]/g, '').replace(/ \[init=[^\]]+\]/g, '').replace(/ \[group=[^\]]+:[a-f0-9]{12}\]/gi, ''); const formatTime = (entry, includeYear = false) => { if (!Number.isFinite(entry.time)) return entry.timestamp; try { @@ -68,13 +68,12 @@ }); return container; } - function blockTitle(items, groupKey) { + function blockTitle(items) { 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'); + const kind = items.find(entry => entry.group_kind)?.group_kind; + const name = kind || (items.length > 1 || first.trace_id ? 'Event' : 'Log'); + const label = items.map(entry => entry.group_label).find(Boolean) || first.entity || first.app; + return node('div', kind ? name : `${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' : ''}`); @@ -188,25 +187,24 @@ detail.querySelector('.rows')?.remove(); if (!detail.open) return; const rows = node('div', undefined, 'rows'); - const units = [], initGroups = new Map(); + const units = [], groupUnits = new Map(); logs.forEach(e => { - 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); + if (e.group_id) { + const key = `group:${e.group_id}`; + if (!groupUnits.has(key)) { const unit = { key, entries: [] }; groupUnits.set(key, unit); units.push(unit); } + groupUnits.get(key).entries.push(e); } else { - const key = e.group_id ? `group:${e.group_id}` : e.kind === 'log' && e.trace_id ? `trace:${e.trace_id}` : undefined; + const key = e.kind === 'log' && e.trace_id ? `trace:${e.trace_id}` : undefined; const previous = units[units.length - 1]; if (key && previous && !previous.id && previous.key === key) previous.entries.push(e); else units.push({ key, entries: [e] }); } }); - const startTime = unit => unit.id - ? (entries.find(e => e.app === app && e.initialization_id === unit.id && e.kind === 'initialization_started') || unit.entries[0]).time - : unit.entries[0].time; + const startTime = unit => unit.entries[0].time; units.sort((a, b) => startTime(a) - startTime(b)); if (units.length > 150) rows.append(node('div', `${units.length - 150} older rows/groups: narrow the time range or search.`, 'more')); units.slice(-150).forEach(unit => { - appendEventRows(rows, unit.entries, unit.id ? `initialization:${unit.id}` : undefined); + appendEventRows(rows, unit.entries, unit.key); }); detail.append(rows); const position = logScrollPositions.get(app); diff --git a/vscode-appdaemon/src/logExplorer.ts b/vscode-appdaemon/src/logExplorer.ts index 6b2e836..a2c93e2 100644 --- a/vscode-appdaemon/src/logExplorer.ts +++ b/vscode-appdaemon/src/logExplorer.ts @@ -223,14 +223,7 @@ export class LogExplorer implements vscode.Disposable { } private publish() { const publication = ++this.publication; - 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); - }); + const entries = [...this.entries.values()].sort((a, b) => a.time - b.time); // Legacy errors duplicated across main/error logs are merged only on exact match. const seen = new Set(); const unique = entries.filter(e => { @@ -238,26 +231,6 @@ export class LogExplorer implements vscode.Disposable { if (seen.has(key)) { return false; } seen.add(key); return true; }); this.onErrorCountChanged?.(unique.filter(e => (e.kind === 'log' || e.kind.startsWith('initialization_')) && (e.level === 'ERROR' || e.level === 'CRITICAL')).length); - // 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 }); void this.resolveSources(unique, publication); diff --git a/vscode-appdaemon/src/logModel.ts b/vscode-appdaemon/src/logModel.ts index 887e29e..1b1eb11 100644 --- a/vscode-appdaemon/src/logModel.ts +++ b/vscode-appdaemon/src/logModel.ts @@ -3,8 +3,8 @@ export interface LogEntry { kind: string; cause_ids: string[]; probable_cause_ids?: string[]; 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; + status?: string; + group_id?: string; group_kind?: string; file?: string; raw?: string; time: number; trace_id?: string; [key: string]: unknown; } @@ -38,12 +38,10 @@ 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 group = m[4].match(/\[group=([^\]\r\n]+):([a-f0-9]{12})\]/i); const id = m[4].match(/\[event=([\w-]+) trace=([\w-]+)\]/); - 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 }; + const groupKind = group?.[1]?.trim(); + return { event_id: id?.[1] || `${file}:${offset}`, trace_id: id?.[2], 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/vscode-appdaemon-0.2.0.vsix b/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix index 36c94e5..cbdadbf 100644 Binary files a/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix and b/vscode-appdaemon/vscode-appdaemon-0.2.0.vsix differ