first draft of log explorer
This commit is contained in:
Pierre committed
1 parent
191e69eb1d
commit
400837b41a
16 files changed
+1495
-79
No files matched your search
@@ -0,0 +1,47 @@
|
||||
const { test } = require('node:test');
|
||||
const assert = require('node:assert/strict');
|
||||
const fs = require('fs');
|
||||
const os = require('os');
|
||||
const path = require('path');
|
||||
const Module = require('module');
|
||||
const root = fs.mkdtempSync(path.join(os.tmpdir(), 'ad-log-test-'));
|
||||
const originalLoad = Module._load;
|
||||
let messages = [];
|
||||
const vscode = {workspace:{workspaceFolders:[{uri:{fsPath:root}}], getConfiguration:()=>({get:(key, fallback)=>fallback})}};
|
||||
Module._load = function(id, ...args) { return id === 'vscode' ? vscode : originalLoad.call(this, id, ...args); };
|
||||
const {LogExplorer} = require('../out/logExplorer');
|
||||
Module._load = originalLoad;
|
||||
function explorer() { const e = new LogExplorer({}); const webview={postMessage:m=>messages.push(m)}; e.panel={webview}; e.activeWebview=webview; return e; }
|
||||
function latest() { return messages.at(-1)?.entries || []; }
|
||||
fs.mkdirSync(path.join(root,'logs'));
|
||||
const file=path.join(root,'logs/appdaemon.log');
|
||||
test('follows incomplete UTF-8 lines and multiline exceptions',()=>{
|
||||
const e=explorer(); messages=[];
|
||||
const first='27-09-26 10:12:13 ERROR app: Échec';
|
||||
const bytes=Buffer.from(first+'\n'); const split=bytes.indexOf(Buffer.from('É'))+1;
|
||||
fs.writeFileSync(file,bytes.subarray(0,split));e.poll();assert.equal(latest().length,0);
|
||||
fs.appendFileSync(file,Buffer.concat([bytes.subarray(split),Buffer.from(' File "app.py", line 42\nRuntimeError: failed\n')]));e.poll();
|
||||
assert.equal(latest().length,1);assert.match(latest()[0].message,/Échec\n File/);assert.match(latest()[0].message,/RuntimeError/);
|
||||
});
|
||||
test('detects same-sized inode replacement and truncation',()=>{
|
||||
const e=explorer();messages=[];
|
||||
fs.writeFileSync(file,'27-09-26 10:12:13 INFO app: before\n');e.poll();
|
||||
fs.renameSync(file,file+'.old');fs.writeFileSync(file,'27-09-26 10:12:14 INFO app: after!\n');e.poll();
|
||||
assert.ok(latest().some(x=>x.message==='after!'));
|
||||
fs.writeFileSync(file,'27-09-26 10:12:15 INFO a: x\n');e.poll();assert.ok(latest().some(x=>x.message==='x'));
|
||||
});
|
||||
test('reads base text logs and ignores structured events by default',()=>{
|
||||
const e=explorer();messages=[];
|
||||
fs.writeFileSync(file,'27-09-26 10:12:13 ERROR app: failed\n27-09-26 10:12:14 INFO AppDaemon: AppDaemon is ready\n');
|
||||
fs.writeFileSync(path.join(root,'logs/error.log'),'27-09-26 10:12:13 ERROR app: failed\n');
|
||||
fs.writeFileSync(path.join(root,'logs/events.jsonl'),JSON.stringify({version:1,event_id:'trace-only',timestamp:'2026-09-27T08:12:14Z',level:'INFO',kind:'evaluation',message:'not a raw log',app:'app',cause_ids:[]})+'\n');e.poll();
|
||||
assert.equal(latest().filter(e=>e.message==='failed').length,1);
|
||||
assert.ok(latest().some(e=>e.app==='AppDaemon' && e.message==='AppDaemon is ready'));
|
||||
assert.equal(latest().some(e=>e.event_id==='trace-only'),false);
|
||||
});
|
||||
test('bounds retained history',()=>{
|
||||
const e=explorer();messages=[];
|
||||
fs.writeFileSync(file,Array.from({length:10500},(_,i)=>`27-09-26 10:12:13 INFO app: message ${i}\n`).join(''));
|
||||
e.poll();e.poll();assert.ok(e.entries.size<=10000);
|
||||
});
|
||||
process.on('exit',()=>fs.rmSync(root,{recursive:true,force:true}));
|
||||
@@ -0,0 +1,29 @@
|
||||
const { test } = require('node:test');
|
||||
const assert = require('node:assert/strict');
|
||||
const { parseLine, rawTime } = require('../out/logModel');
|
||||
test('raw log levels, app names and readable IDs', () => {
|
||||
const e = parseLine('27-09-26 10:12:13 WARNING my_app: Alerte : détail [event=e1 trace=t1]', '/logs/main.log', 123);
|
||||
assert.equal(e.event_id, 'e1'); assert.equal(e.app, 'my_app'); assert.equal(e.level, 'WARNING'); assert.equal(e.trace_id, 't1');
|
||||
});
|
||||
test('timestamps use the AppDaemon timezone instead of the workstation timezone', () => {
|
||||
assert.equal(rawTime('27-09-26 10:12:13', 'Europe/Berlin'), Date.parse('2026-09-27T08:12:13Z'));
|
||||
assert.equal(rawTime('27-01-26 10:12:13', 'Europe/Berlin'), Date.parse('2026-01-27T09:12:13Z'));
|
||||
});
|
||||
test('structured events retain causal links and evaluation values', () => {
|
||||
const entry = {version:1,event_id:'e2',cause_ids:['e1'],probable_cause_ids:['e1'],message:'Condition',app:'app',kind:'evaluation',timestamp:'2026-09-27T08:12:13Z',values:{'sensor.a':true}};
|
||||
assert.deepEqual(parseLine(JSON.stringify(entry), '/logs/events.jsonl', 0).values, entry.values);
|
||||
});
|
||||
test('invalid structured records and continuations are rejected', () => {
|
||||
for (const value of ['{broken}', JSON.stringify({version:1,event_id:'e',cause_ids:[null],message:'bad',app:'app',timestamp:'now'}), ' File "app.py", line 3']) assert.equal(parseLine(value,'/logs/log',0),undefined);
|
||||
});
|
||||
test('decodes UTF-8, Windows-1252 and mixed historical log bytes', () => {
|
||||
const { decodeLogLine } = require('../out/logModel');
|
||||
assert.equal(decodeLogLine(Buffer.from('Échec – déjà 🔥')), 'Échec – déjà 🔥');
|
||||
assert.equal(decodeLogLine(Buffer.from([0xc9,0x63,0x68,0x65,0x63,0x20,0x96,0x20,0xe9])), 'Échec – é');
|
||||
assert.equal(decodeLogLine(Buffer.concat([Buffer.from('déjà → '),Buffer.from([0xe9])])), 'déjà → é');
|
||||
assert.equal(decodeLogLine(Buffer.from([0xe9]), 'utf8'), '\ufffd');
|
||||
});
|
||||
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');
|
||||
});
|
||||
@@ -0,0 +1,142 @@
|
||||
const {test}=require('node:test');
|
||||
const assert=require('node:assert/strict');
|
||||
const fs=require('fs');
|
||||
const path=require('path');
|
||||
const {JSDOM,VirtualConsole}=require('jsdom');
|
||||
const media=path.join(__dirname,'../media');
|
||||
function setup() {
|
||||
const errors=[], sent=[];
|
||||
const virtualConsole=new VirtualConsole();virtualConsole.on('jsdomError',e=>errors.push(e));
|
||||
const html=fs.readFileSync(path.join(media,'logExplorer.html'),'utf8').replace(/<meta http-equiv="Content-Security-Policy"[^>]+>/,'').replace(/<script[^>]+src="\{\{JS\}\}"[^>]*><\/script>/,'');
|
||||
const dom=new JSDOM(html,{runScripts:'outside-only',virtualConsole});
|
||||
dom.window.acquireVsCodeApi=()=>({postMessage:message=>sent.push(message),getState:()=>({}),setState() {}});
|
||||
dom.window.eval(fs.readFileSync(path.join(media,'logExplorer.js'),'utf8'));
|
||||
const entry=(id,app,second,message,extra={})=>{const timestamp=`2026-09-27T08:00:${String(second).padStart(2,'0')}Z`;return {event_id:id,app,time:Date.parse(timestamp),timestamp,message,kind:'log',cause_ids:[],level:'INFO',...extra};};
|
||||
const entries=[entry('init1','alpha',1,'Preparing sensors',{initialization_id:'init-one'}),entry('init2','alpha',2,'Ready',{initialization_id:'init-one'}),entry('init3','alpha',3,'Restarting',{initialization_id:'init-two'}),entry('a','alpha',10,'Température déjà disponible'),entry('b','beta',20,'Connection ready')];
|
||||
const send=items=>dom.window.dispatchEvent(new dom.window.MessageEvent('message',{data:{type:'entries',entries:items,warnings:[],limit:10000}}));
|
||||
send(entries);
|
||||
return {dom,d:dom.window.document,entries,sent,errors,send};
|
||||
}
|
||||
test('English interface, latest timestamps, sorting and separate initialization groups',()=>{
|
||||
const {dom,d,errors}=setup();
|
||||
assert.equal(d.documentElement.lang,'en');
|
||||
assert.equal(d.getElementById('copy').textContent,'Copy selected log');
|
||||
assert.deepEqual([...d.querySelectorAll('[data-app]')].map(e=>e.dataset.app),['beta','alpha']);
|
||||
assert.match(d.querySelector('[data-app="alpha"] .last-age').title,/10:00:10/);
|
||||
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.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();
|
||||
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();
|
||||
});
|
||||
test('retains selected text during live updates and copies it with Ctrl+C',async()=>{
|
||||
const {dom,d,entries,sent,errors,send}=setup();const alpha=d.querySelector('[data-app="alpha"]');alpha.open=true;alpha.dispatchEvent(new dom.window.Event('toggle'));
|
||||
const text=alpha.querySelector('.row-message'),range=d.createRange();range.selectNodeContents(text);dom.window.getSelection().addRange(range);
|
||||
const original=text.textContent;
|
||||
send([...entries,{...entries[3],event_id:'new',time:30,message:'New log'}]);
|
||||
assert.equal(dom.window.getSelection().toString(),original);assert.match(d.getElementById('status').textContent,/buffered/);
|
||||
text.dispatchEvent(new dom.window.KeyboardEvent('keydown',{key:'c',ctrlKey:true,bubbles:true,cancelable:true}));
|
||||
assert.equal(sent.at(-1).text,original);
|
||||
dom.window.getSelection().removeAllRanges();d.dispatchEvent(new dom.window.Event('selectionchange'));await new Promise(resolve=>setTimeout(resolve,15));
|
||||
assert.match(d.querySelector('[data-app="alpha"]').textContent,/New log/);
|
||||
assert.deepEqual(errors,[]);dom.window.close();
|
||||
});
|
||||
test('log content is never interpreted as HTML',()=>{
|
||||
const {dom,d,entries,send,errors}=setup();send([{...entries[0],app:'<script>bad</script>',initialization_id:undefined,message:'<img src=x onerror=alert(1)>'}]);
|
||||
const app=d.querySelector('[data-app]');app.open=true;app.dispatchEvent(new dom.window.Event('toggle'));
|
||||
assert.equal(d.querySelectorAll('#apps img,#apps script').length,0);assert.match(app.textContent,/<img/);assert.deepEqual(errors,[]);dom.window.close();
|
||||
});
|
||||
test('shows same-event log lines together with one causes link and keeps newer events below',()=>{
|
||||
const {dom,d,entries,send,sent}=setup();
|
||||
const trigger={...entries[3],event_id:'motion-callback',time:entries[3].time+1000,message:'Callback trigger by sensor.kitchen_last_motion(7 => 0)',trace_id:'motion-event'};
|
||||
const evaluation={...entries[3],event_id:'motion-evaluation',time:entries[3].time+1000,message:'[kitchen_occupancy][Evaluating] Triggered by (sensor.kitchen_last_motion[0] <= 5)[True]',trace_id:'motion-event',cause_ids:['state-event']};
|
||||
const newer={...entries[3],event_id:'later-log',time:entries[3].time+2000,message:'Later event'};
|
||||
send([trigger,evaluation,newer].sort((a,b)=>a.time-b.time));
|
||||
const alpha=d.querySelector('[data-app="alpha"]');alpha.open=true;alpha.dispatchEvent(new dom.window.Event('toggle'));
|
||||
const rows=alpha.querySelector('.rows'),combined=rows.children[0];
|
||||
assert.ok(combined.classList.contains('event-log-group'));
|
||||
assert.match(combined.querySelector('.row-message').textContent,/Callback trigger by sensor.kitchen_last_motion/);
|
||||
assert.match(combined.querySelector('.row-message').textContent,/Triggered by \(sensor.kitchen_last_motion/);
|
||||
assert.equal(combined.querySelectorAll('.link-hint').length,1);
|
||||
assert.equal(rows.children[1].querySelector('.row-message').textContent,'Later event');
|
||||
combined.click();d.getElementById('copy').click();
|
||||
assert.match(sent.at(-1).text,/Callback trigger by sensor.kitchen_last_motion/);
|
||||
assert.match(sent.at(-1).text,/Triggered by \(sensor.kitchen_last_motion/);
|
||||
assert.match(d.getElementById('detail').textContent,/Callback trigger by sensor.kitchen_last_motion/);
|
||||
dom.window.close();
|
||||
});
|
||||
test('does not show a mirrored evaluation twice in the cause graph',()=>{
|
||||
const {dom,d,entries,send}=setup();
|
||||
const time=entries[3].time+1000,trace='same-run';
|
||||
const state={...entries[3],event_id:'state-event',kind:'state_changed',message:'sensor.ext_back_humidity.state: 66 → 65',time,trace_id:trace,cause_ids:[]};
|
||||
const message='[living_room_cant_open_window][Evaluating] No valid conditions';
|
||||
const evaluation={...entries[3],event_id:'technical-evaluation',kind:'evaluation',message,time,trace_id:trace,cause_ids:['state-event'],values:{'sensor.ext_back_humidity':'65'}};
|
||||
const callback={...entries[3],event_id:'callback-log',message:'[living_room_cant_open_window] Callback trigger by sensor.ext_back_humidity(66 => 65)',time,trace_id:trace,cause_ids:['state-event']};
|
||||
const mirroredLog={...entries[3],event_id:'evaluation-log',message,time:time+1,trace_id:trace,cause_ids:['technical-evaluation']};
|
||||
send([state,evaluation,callback,mirroredLog].sort((a,b)=>a.time-b.time));
|
||||
const app=d.querySelector('[data-app="alpha"]');app.open=true;app.dispatchEvent(new dom.window.Event('toggle'));
|
||||
const combined=app.querySelector('.event-log-group');
|
||||
assert.ok(combined);
|
||||
assert.equal(combined.querySelectorAll('.link-hint').length,1);
|
||||
combined.click();
|
||||
const matchingNodes=[...d.querySelectorAll('#detail .node .text')].filter(item=>item.textContent.includes('No valid conditions'));
|
||||
assert.equal(matchingNodes.length,1);
|
||||
assert.equal(d.querySelectorAll('#detail .values tr').length,1);
|
||||
dom.window.close();
|
||||
});
|
||||
test('pulses an app when a new log arrives and refreshes its last-log age',async()=>{
|
||||
const {dom,d,entries,send}=setup();
|
||||
const beta=entries.find(e=>e.app==='beta'),nextTime=beta.time+2000;
|
||||
dom.window.Date.now=()=>beta.time+3000;
|
||||
const newer={...beta,event_id:'beta-new',time:nextTime,timestamp:new Date(nextTime).toISOString(),message:'Fresh log'};
|
||||
send([...entries,newer]);
|
||||
const app=d.querySelector('[data-app="beta"]');
|
||||
assert.ok(app.classList.contains('new-log-app'));
|
||||
app.open=true;app.dispatchEvent(new dom.window.Event('toggle'));
|
||||
assert.ok(app.querySelector('.recent-log'));
|
||||
assert.equal(app.querySelector('.last-age').textContent,'Last log: 1 second ago');
|
||||
dom.window.Date.now=()=>nextTime+65000;
|
||||
await new Promise(resolve=>setTimeout(resolve,1100));
|
||||
assert.equal(app.querySelector('.last-age').textContent,'Last log: 1 minute ago');
|
||||
dom.window.close();
|
||||
});
|
||||
|
||||
test('distinguishes log lines from supplemental records when configured',()=>{
|
||||
const {dom,d,entries,send}=setup();
|
||||
const trace={...entries[3],event_id:'trace-evaluation',kind:'evaluation',message:'Condition was evaluated'};
|
||||
send([...entries,trace]);
|
||||
assert.match(d.getElementById('status').textContent,/5 log lines \+ 1 trace event/);
|
||||
assert.match(d.getElementById('status').title,/configured history files/);
|
||||
dom.window.close();
|
||||
});
|
||||
|
||||
test('shows and refreshes relative time on each log entry while retaining exact time on hover',async()=>{
|
||||
const {dom,d,entries}=setup();
|
||||
const entry=entries.find(e=>e.event_id==='a');
|
||||
dom.window.Date.now=()=>entry.time+120000;
|
||||
const app=d.querySelector('[data-app="alpha"]');
|
||||
app.open=true;
|
||||
app.dispatchEvent(new dom.window.Event('toggle'));
|
||||
const row=[...d.querySelectorAll('[data-app="alpha"] .row')].find(item=>item.textContent.includes('Température déjà disponible'));
|
||||
const relativeTime=()=>[...app.querySelectorAll('.row')].find(item=>item.textContent.includes('Température déjà disponible')).querySelector('.relative-time');
|
||||
assert.equal(relativeTime().textContent,'2 minutes ago');
|
||||
assert.match(relativeTime().title,/10:00:10/);
|
||||
dom.window.Date.now=()=>entry.time+3600000;
|
||||
await new Promise(resolve=>setTimeout(resolve,1600));
|
||||
assert.equal(relativeTime().textContent,'1 hour ago');
|
||||
dom.window.close();
|
||||
});
|
||||
|
||||
Reference in new issue
Block a user