Improve JS logging (#743)

This PR tries to improve and rationalize what we log. Key points:
- introduce `logger.ts`: each file/component is encouraged to use the logger instead of writing directly to `console.*`
    * the logger automatically prepend a prefix like `[py-config]`, `[py-env]` which make it easier to understand where a certain message is printed from
    * it provide a central place where to add more features in the future. E.g., I can imagine having a config setting to completely silence the logs (not implemented yet)
- use the new loggers everywhere
- write to `.info()` instead of `.log()`. The idea is to keep `console.log` free, so that for the users it's easier to tell apart their own messages and the pyscript ones
- generally improve what we log. This is an endless exercise, but I tried to print more things which are useful to understand what's going on and in which order the various things are executed, and remove prints which were clearly debugging leftovers
This commit is contained in:
Antonio Cuni
2022-09-06 15:18:41 +02:00
committed by GitHub
parent e31e03afde
commit f3157b377f
23 changed files with 275 additions and 110 deletions

View File

@@ -2,6 +2,9 @@ import { runtimeLoaded } from '../stores';
import { guidGenerator, addClasses, removeClasses } from '../utils';
import type { Runtime } from '../runtime';
import { getLogger } from '../logger';
const logger = getLogger('pyscript/base');
// Global `Runtime` that implements the generic runtimes API
let runtime: Runtime;
@@ -49,7 +52,7 @@ export class BaseEvalElement extends HTMLElement {
this.appendOutput = false;
break;
default:
console.log(`${this.id}: custom output-modes are currently not implemented`);
logger.warn(`${this.id}: custom output-modes are currently not implemented`);
}
}
@@ -104,7 +107,7 @@ export class BaseEvalElement extends HTMLElement {
// "can't read 'name' of undefined" at import time
imports[name] = { ...(await import(url)) };
} catch {
console.error(`failed to fetch '${url}' for '${name}'`);
logger.error(`failed to fetch '${url}' for '${name}'`);
}
}
}
@@ -113,7 +116,6 @@ export class BaseEvalElement extends HTMLElement {
}
async evaluate(): Promise<void> {
console.log('evaluate');
this.preEvaluate();
let source: string;
@@ -158,7 +160,7 @@ export class BaseEvalElement extends HTMLElement {
this.postEvaluate();
} catch (err) {
console.error(err);
logger.error(err);
try{
if (Element === undefined) {
Element = <Element>runtime.globals.get('Element');
@@ -177,7 +179,7 @@ export class BaseEvalElement extends HTMLElement {
this.errorElement.style.display = 'block';
this.errorElement.style.visibility = 'visible';
} catch (internalErr){
console.error("Unnable to write error to error element in page.")
logger.error("Unnable to write error to error element in page.")
}
}
@@ -187,10 +189,10 @@ export class BaseEvalElement extends HTMLElement {
try {
const output = await runtime.run(source);
if (output !== undefined) {
console.log(output);
logger.info(output);
}
} catch (err) {
console.log(err);
logger.error(err);
}
} // end eval
@@ -241,14 +243,12 @@ function createWidget(name: string, code: string, klass: string) {
// })();
// }, 2000);
runtimeLoaded.subscribe(value => {
console.log('RUNTIME READY', value);
if ('run' in value) {
runtime = value;
setTimeout(() => {
void (async () => {
await this.eval(this.code);
this.proxy = this.proxyClass(this);
console.log('proxy', this.proxy);
this.proxy.connect();
this.registerWidget();
})();
@@ -258,7 +258,7 @@ function createWidget(name: string, code: string, klass: string) {
}
registerWidget() {
console.log('new widget registered:', this.name);
logger.info('new widget registered:', this.name);
runtime.globals.set(this.id, this.proxy);
}
@@ -267,10 +267,10 @@ function createWidget(name: string, code: string, klass: string) {
const output = await runtime.run(source);
this.proxyClass = runtime.globals.get(this.klass);
if (output !== undefined) {
console.log(output);
logger.info('CustomWidget.eval: ', output);
}
} catch (err) {
console.log(err);
logger.error('CustomWidget.eval: ', err);
}
}
}
@@ -319,7 +319,7 @@ export class PyWidget extends HTMLElement {
const mainDiv = document.createElement('div');
mainDiv.id = this.id + '-main';
this.appendChild(mainDiv);
console.log('reading source');
logger.debug('PyWidget: reading source', this.source);
this.code = await this.getSourceFromFile(this.source);
createWidget(this.name, this.code, this.klass);
}
@@ -361,10 +361,10 @@ export class PyWidget extends HTMLElement {
try {
const output = await runtime.run(source);
if (output !== undefined) {
console.log(output);
logger.info('PyWidget.eval: ', output);
}
} catch (err) {
console.log(err);
logger.error('PyWidget.eval: ', err);
}
}
}

View File

@@ -1,4 +1,7 @@
import { addClasses } from '../utils';
import { getLogger } from '../logger';
const logger = getLogger('py-box');
export class PyBox extends HTMLElement {
shadow: ShadowRoot;
@@ -24,7 +27,6 @@ export class PyBox extends HTMLElement {
// meaning that we end up with 2 editors, if there's a <py-repl> inside the <py-box>
// so, if we have more than 2 children with the cm-editor class, we remove one of them
while (this.childNodes.length > 0) {
console.log(this.firstChild);
if (this.firstChild.nodeName == 'PY-REPL') {
// in this case we need to remove the child and create a new one from scratch
const replDiv = document.createElement('div');
@@ -61,6 +63,6 @@ export class PyBox extends HTMLElement {
});
this.appendChild(mainDiv);
console.log('py-box connected');
logger.info('py-box connected');
}
}

View File

@@ -1,5 +1,9 @@
import { BaseEvalElement } from './base';
import { addClasses, htmlDecode } from '../utils';
import { getLogger } from '../logger'
const logger = getLogger('py-button');
export class PyButton extends BaseEvalElement {
widths: Array<string>;
@@ -65,9 +69,9 @@ export class PyButton extends BaseEvalElement {
this.runAfterRuntimeInitialized(async () => {
await this.eval(this.code);
await this.eval(registrationCode);
console.log('registered handlers');
logger.debug('registered handlers');
});
console.log('py-button connected');
logger.debug('py-button connected');
}
}

View File

@@ -3,6 +3,9 @@ import { BaseEvalElement } from './base';
import { appConfig } from '../stores';
import type { AppConfig, Runtime } from '../runtime';
import { PyodideRuntime, DEFAULT_RUNTIME_CONFIG } from '../pyodide';
import { getLogger } from '../logger';
const logger = getLogger('py-config');
/**
* Configures general metadata about the PyScript application such
@@ -41,7 +44,7 @@ export class PyConfig extends BaseEvalElement {
}
appConfig.set(this.values);
console.log('config set', this.values);
logger.info('config set:', this.values);
this.loadRuntimes();
}
@@ -57,7 +60,7 @@ export class PyConfig extends BaseEvalElement {
}
loadRuntimes() {
console.log('Initializing runtimes...');
logger.info('Initializing runtimes');
for (const runtime of this.values.runtimes) {
const runtimeObj: Runtime = new PyodideRuntime(runtime.src, runtime.name, runtime.lang);
const script = document.createElement('script'); // create a script DOM node

View File

@@ -3,13 +3,15 @@ import * as jsyaml from 'js-yaml';
import { runtimeLoaded, addInitializer } from '../stores';
import { handleFetchError } from '../utils';
import type { Runtime } from '../runtime';
import { getLogger } from '../logger';
const logger = getLogger('py-env');
// Premise used to connect to the first available runtime (can be pyodide or others)
let runtime: Runtime;
runtimeLoaded.subscribe(value => {
runtime = value;
console.log('RUNTIME READY');
});
export class PyEnv extends HTMLElement {
@@ -55,13 +57,14 @@ export class PyEnv extends HTMLElement {
this.paths = paths;
async function loadEnv() {
logger.info("Loading env: ", env);
await runtime.installPackage(env);
console.log('environment loaded');
}
async function loadPaths() {
logger.info("Paths to load: ", paths)
for (const singleFile of paths) {
console.log(`loading ${singleFile}`);
logger.info(` loading path: ${singleFile}`);
try {
await runtime.loadFromFile(singleFile);
} catch (e) {
@@ -69,11 +72,10 @@ export class PyEnv extends HTMLElement {
handleFetchError(<Error>e, singleFile);
}
}
console.log('paths loaded');
logger.info("All paths loaded");
}
addInitializer(loadEnv);
addInitializer(loadPaths);
console.log('environment loading...', this.env);
}
}

View File

@@ -1,5 +1,8 @@
import { BaseEvalElement } from './base';
import { addClasses, htmlDecode } from '../utils';
import { getLogger } from '../logger'
const logger = getLogger('py-inputbox');
export class PyInputBox extends BaseEvalElement {
widths: Array<string>;
@@ -43,7 +46,7 @@ export class PyInputBox extends BaseEvalElement {
this.runAfterRuntimeInitialized(async () => {
await this.eval(this.code);
await this.eval(registrationCode);
console.log('registered handlers');
logger.debug('registered handlers');
});
}
}

View File

@@ -1,4 +1,7 @@
import { BaseEvalElement } from './base';
import { getLogger } from '../logger';
const logger = getLogger('py-loader');
export class PyLoader extends BaseEvalElement {
widths: Array<string>;
@@ -26,12 +29,15 @@ export class PyLoader extends BaseEvalElement {
}
log(msg: string) {
// loader messages are showed both in the HTML and in the console
logger.info(msg);
const newLog = document.createElement('p');
newLog.innerText = msg;
this.details.appendChild(newLog);
}
close() {
logger.info('Closing');
this.remove();
}
}

View File

@@ -6,6 +6,9 @@ import { defaultKeymap } from '@codemirror/commands';
import { oneDarkTheme } from '@codemirror/theme-one-dark';
import { addClasses, htmlDecode } from '../utils';
import { BaseEvalElement } from './base';
import { getLogger } from '../logger';
const logger = getLogger('py-repl');
function createCmdHandler(el: PyRepl): StateCommand {
@@ -102,8 +105,8 @@ export class PyRepl extends BaseEvalElement {
});
if (!this.id) {
console.log(
"WARNING: <pyrepl> define with an id. <pyrepl> should always have an id. More than one <pyrepl> on a page won't work otherwise!",
logger.warn(
"WARNING: <py-repl> defined without an id. <py-repl> should always have an id, otherwise multiple <py-repl> in the same page will not work!"
);
}
@@ -139,7 +142,7 @@ export class PyRepl extends BaseEvalElement {
this.appendChild(mainDiv);
this.editor.focus();
console.log('connected');
logger.debug(`element ${this.id} successfully connected`);
}
addToOutput(s: string): void {
@@ -195,8 +198,4 @@ export class PyRepl extends BaseEvalElement {
getSourceFromElement(): string {
return this.editor.state.doc.toString();
}
render() {
console.log('rendered');
}
}

View File

@@ -10,6 +10,9 @@ import {
import { addClasses, htmlDecode } from '../utils';
import { BaseEvalElement } from './base';
import type { Runtime } from '../runtime';
import { getLogger } from '../logger';
const logger = getLogger('py-script');
// Premise used to connect to the first available runtime (can be pyodide or others)
let runtime: Runtime;
@@ -72,8 +75,6 @@ export class PyScript extends BaseEvalElement {
this.appendChild(mainDiv);
addToScriptsQueue(this);
console.log('connected');
if (this.hasAttribute('src')) {
this.source = this.getAttribute('src');
}
@@ -100,7 +101,7 @@ export class PyScript extends BaseEvalElement {
// "can't read 'name' of undefined" at import time
exports = { ...(await import(url)) };
} catch {
console.warn(`failed to fetch '${url}' for '${name}'`);
logger.warn(`failed to fetch '${url}' for '${name}'`);
continue;
}
@@ -209,9 +210,9 @@ const pyAttributeToEvent: Map<string, string> = new Map<string, string>([
["py-toggle", "toggle"],
]);
/** Initialize all elements with py-on* handlers attributes */
/** Initialize all elements with py-* handlers attributes */
async function initHandlers() {
console.log('Collecting nodes...');
logger.debug('Initializing py-* event handlers...');
for (const pyAttribute of pyAttributeToEvent.keys()) {
await createElementsWithEventListeners(runtime, pyAttribute);
}
@@ -251,8 +252,8 @@ async function createElementsWithEventListeners(runtime: Runtime, pyAttribute: s
/** Mount all elements with attribute py-mount into the Python namespace */
async function mountElements() {
console.log('Collecting nodes to be mounted into python namespace...');
const matches: NodeListOf<HTMLElement> = document.querySelectorAll('[py-mount]');
logger.info(`py-mount: found ${matches.length} elements`);
let source = '';
for (const el of matches) {

64
pyscriptjs/src/logger.ts Normal file
View File

@@ -0,0 +1,64 @@
/* Very simple logger interface.
Each module is expected to create its own logger by doing e.g.:
const logger = getLogger('my-prefix');
and then use it instead of console:
logger.info('hello', 'world');
logger.warn('...');
logger.error('...');
The logger automatically adds the prefix "[my-prefix]" to all logs; so e.g., the
above call would print:
[my-prefix] hello world
logger.log is intentionally omitted. The idea is that PyScript should not
write anything to console.log, to leave it free for the user.
Currently, the logger does not to anything more than that. In the future,
we might want to add additional features such as the ability to
enable/disable logs on a global or per-module basis.
*/
interface Logger {
debug(message: string, ...args: any[]): void;
info(message: string, ...args: any[]): void;
warn(message: string, ...args: any[]): void;
error(message: string, ...args: any[]): void;
}
const _cache = new Map<string, Logger>();
function getLogger(prefix: string): Logger {
let logger = _cache.get(prefix);
if (logger === undefined) {
logger = _makeLogger(prefix);
_cache.set(prefix, logger);
}
return logger;
}
function _makeLogger(prefix: string): Logger {
prefix = "[" + prefix + "] ";
function make(level: string) {
const out_fn = console[level].bind(console);
function fn(fmt: string, ...args: any[]) {
out_fn(prefix + fmt, ...args);
}
return fn
}
// 'log' is intentionally omitted
const debug = make('debug');
const info = make('info');
const warn = make('warn');
const error = make('error');
return {debug, info, warn, error};
}
export { getLogger };

View File

@@ -11,6 +11,9 @@ import { PyWidget } from './components/base';
import { PyLoader } from './components/pyloader';
import { globalLoader } from './stores';
import { PyConfig } from './components/pyconfig';
import { getLogger } from './logger';
const logger = getLogger('pyscript/main');
/* eslint-disable @typescript-eslint/no-unused-vars */
const xPyScript = customElements.define('py-script', PyScript);
@@ -26,6 +29,7 @@ const xPyConfig = customElements.define('py-config', PyConfig);
/* eslint-enable @typescript-eslint/no-unused-vars */
// As first thing, loop for application configs
logger.info('checking for py-confing');
const config: PyConfig = document.querySelector('py-config');
if (!config) {
const loader = document.createElement('py-config');
@@ -33,6 +37,7 @@ if (!config) {
}
// add loader to the page body
logger.info('add py-loader');
const loader = <PyLoader>document.createElement('py-loader');
document.body.append(loader);
globalLoader.set(loader);

View File

@@ -1,10 +1,13 @@
import { Runtime, RuntimeConfig } from './runtime';
import { getLastPath } from './utils';
import { getLogger } from './logger';
import type { PyodideInterface } from 'pyodide';
// eslint-disable-next-line
// @ts-ignore
import pyscript from './python/pyscript.py';
const logger = getLogger('pyscript/pyodide');
export const DEFAULT_RUNTIME_CONFIG: RuntimeConfig = {
src: 'https://cdn.jsdelivr.net/pyodide/v0.21.2/full/pyodide.js',
name: 'pyodide-default',
@@ -23,6 +26,7 @@ export class PyodideRuntime extends Runtime {
name = DEFAULT_RUNTIME_CONFIG.name,
lang = DEFAULT_RUNTIME_CONFIG.lang,
) {
logger.info('Runtime config:', { name, lang, src });
super();
this.src = src;
this.name = name;
@@ -46,7 +50,7 @@ export class PyodideRuntime extends Runtime {
* path.
*/
async loadInterpreter(): Promise<void> {
console.log('creating pyodide runtime');
logger.info('Loading pyodide');
// eslint-disable-next-line
// @ts-ignore
this.interpreter = await loadPyodide({
@@ -57,17 +61,13 @@ export class PyodideRuntime extends Runtime {
this.globals = this.interpreter.globals;
// now that we loaded, add additional convenience functions
console.log('loading micropip');
// XXX: ideally, we should load micropip only if we actually need it
await this.loadPackage('micropip');
console.log('loading pyscript...');
const output = await this.run(pyscript);
if (output !== undefined) {
console.log(output);
}
logger.info('importing pyscript.py');
await this.run(pyscript);
console.log('done setting up environment');
logger.info('pyodide loaded and initialized');
}
async run(code: string): Promise<any> {
@@ -79,11 +79,15 @@ export class PyodideRuntime extends Runtime {
}
async loadPackage(names: string | string[]): Promise<void> {
await this.interpreter.loadPackage(names);
logger.info(`pyodide.loadPackage: ${names.toString()}`);
await this.interpreter.loadPackage(names,
logger.info.bind(logger),
logger.info.bind(logger));
}
async installPackage(package_name: string | string[]): Promise<void> {
if (package_name.length > 0) {
logger.info(`micropip install ${package_name.toString()}`);
const micropip = this.globals.get('micropip');
await micropip.install(package_name);
micropip.destroy();

View File

@@ -92,7 +92,7 @@ def format_mime(obj):
break
if output is None:
if not_available:
console.warning(
console.warn(
f"Rendered object requested unavailable MIME renderers: {not_available}"
)
output = repr(output)
@@ -149,8 +149,6 @@ class Element:
return self.element.innerHtml
def write(self, value, append=False):
console.log(f"Element.write: {value} --> {append}")
out_element_id = self.id
html, mime_type = format_mime(value)
@@ -186,7 +184,7 @@ class Element:
if _el:
return Element(_el.id, _el)
else:
console.log(f"WARNING: can't find element matching query {query}")
console.warn(f"WARNING: can't find element matching query {query}")
def clone(self, new_id=None, to=None):
if new_id is None:
@@ -261,11 +259,7 @@ class PyItemTemplate(Element):
self._id = None
def create(self):
console.log("creating section")
new_child = create("div", self._id, "py-li-element")
console.log("creating values")
console.log("creating innerHtml")
new_child._element.innerHTML = dedent(
f"""
<label id="{self._id}" for="flex items-center p-2 ">
@@ -274,8 +268,6 @@ class PyItemTemplate(Element):
</label>
"""
)
console.log("returning")
return new_child
def on_click(self, evt):
@@ -331,7 +323,6 @@ class PyListTemplate:
print(txt)
def foo(evt):
console.log(evt)
evtEl = evt.srcElement
srcEl = Element(binds[evtEl.id])
srcEl.element.onclick()
@@ -358,7 +349,6 @@ class PyListTemplate:
return self._add(child)
def _add(self, child_elem):
console.log("appending child", child_elem.element)
self.pre_child_append(child_elem)
child_elem.pre_append()
self._children.append(child_elem)
@@ -387,19 +377,16 @@ class OutputCtxManager:
self._out = out
self.output_to_console = output_to_console
self._append = append
console.log("----> changed out to", self._out, self._append)
def revert(self):
console.log("----> reverted")
self._out = self._prev
def write(self, value):
console.log("writing to", self._out, value, self._append)
if self._out:
Element(self._out).write(value, self._append)
if self.output_to_console:
console.log(self._out, value)
console.info(f"[pyscript.py/OutputCtxManager] out={self._out}:", value)
class OutputManager:
@@ -430,7 +417,6 @@ class OutputManager:
self._err_manager.revert()
sys.stdout = self._out_manager
sys.stderr = self._err_manager
console.log("----> reverted")
pyscript = PyScript()

View File

@@ -11,6 +11,9 @@ import {
appConfig
} from './stores'
import type { PyScript } from './components/pyscript';
import { getLogger } from './logger';
const logger = getLogger('pyscript/runtime');
export type RuntimeInterpreter = PyodideInterface | null;
@@ -35,19 +38,16 @@ globalLoader.subscribe(value => {
let initializers_: Initializer[];
initializers.subscribe((value: Initializer[]) => {
initializers_ = value;
console.log('initializers set');
});
let postInitializers_: Initializer[];
postInitializers.subscribe((value: Initializer[]) => {
postInitializers_ = value;
console.log('post initializers set');
});
let scriptsQueue_: PyScript[];
scriptsQueue.subscribe((value: PyScript[]) => {
scriptsQueue_ = value;
console.log('scripts queue set');
});
let appConfig_: AppConfig = {
@@ -58,7 +58,6 @@ appConfig.subscribe((value: AppConfig) => {
if (value) {
appConfig_ = value;
}
console.log('config set!');
});
/*
@@ -170,12 +169,14 @@ export abstract class Runtime extends Object {
if (appConfig_ && appConfig_.autoclose_loader) {
loader?.close();
console.log('------ loader closed ------');
}
for (const initializer of postInitializers_) {
await initializer();
}
console.log('===PyScript page fully initialized===');
// NOTE: this message is used by integration tests to know that
// pyscript initialization has complete. If you change it, you need to
// change it also in tests/integration/support.py
logger.info('PyScript page fully initialized');
}
}

View File

@@ -2,6 +2,7 @@ import { writable } from 'svelte/store';
import type { PyLoader } from './components/pyloader';
import type { PyScript } from './components/pyscript';
import type { Runtime } from './runtime';
import { getLogger } from './logger';
export type Initializer = () => Promise<void>;
@@ -35,13 +36,9 @@ export const addToScriptsQueue = (script: PyScript) => {
};
export const addInitializer = (initializer: Initializer) => {
console.log('adding initializer', initializer);
initializers.update(initializers => [...initializers, initializer]);
console.log('added initializer', initializer);
};
export const addPostInitializer = (initializer: Initializer) => {
console.log('adding post initializer', initializer);
postInitializers.update(postInitializers => [...postInitializers, initializer]);
console.log('added post initializer', initializer);
};