mol-state & plugin: basic logging

src/mol-plugin/context.ts

@@ -17,6 +17,7 @@ import { PluginBehaviors, BuiltInPluginBehaviors } from './behavior';
 import { Loci, EmptyLoci } from 'mol-model/loci';
 import { Representation } from 'mol-repr';
 import { CreateStructureFromPDBe } from './state/actions/basic';
+import { LogEntry } from 'mol-util/log-entry';
 
 export class PluginContext {
     private disposed = false;
@@ -31,7 +32,8 @@ export class PluginContext {
             behavior: this.state.behavior.events,
             cameraSnapshots: this.state.cameraSnapshots.events,
             snapshots: this.state.snapshots.events,
-        }
+        },
+        log: this.ev<LogEntry>()
     };
 
     readonly behaviors = {
@@ -61,6 +63,10 @@ export class PluginContext {
         }
     }
 
+    log(e: LogEntry) {
+        this.events.log.next(e);
+    }
+
     /**
      * This should be used in all transform related request so that it could be "spoofed" to allow
      * "static" access to resources.
@@ -87,6 +93,8 @@ export class PluginContext {
         BuiltInPluginBehaviors.State.registerDefault(this);
         BuiltInPluginBehaviors.Representation.registerDefault(this);
         BuiltInPluginBehaviors.Camera.registerDefault(this);
+
+        merge(this.state.data.events.log, this.state.behavior.events.log).subscribe(e => this.events.log.next(e));
     }
 
     async _test_initBehaviors() {

src/mol-plugin/ui/controls.tsx

@@ -21,7 +21,7 @@ export class Controls extends PluginComponent<{ }, { }> {
 }
 
 
-export class _test_TrajectoryControls extends PluginComponent {
+export class TrajectoryControls extends PluginComponent {
     render() {
         return <div>
             <b>Trajectory: </b>

src/mol-plugin/ui/plugin.tsx

@@ -8,12 +8,15 @@ import * as React from 'react';
 import { PluginContext } from '../context';
 import { StateTree } from './state-tree';
 import { Viewport, ViewportControls } from './viewport';
-import { Controls, _test_UpdateTransform, _test_ApplyAction, _test_TrajectoryControls } from './controls';
+import { Controls, _test_UpdateTransform, _test_ApplyAction, TrajectoryControls } from './controls';
 import { PluginComponent, PluginReactContext } from './base';
 import { merge } from 'rxjs';
 import { State } from 'mol-state';
 import { CameraSnapshots } from './camera';
 import { StateSnapshots } from './state';
+import { List } from 'immutable';
+import { LogEntry } from 'mol-util/log-entry';
+import { formatTime } from 'mol-util';
 
 export class Plugin extends React.Component<{ plugin: PluginContext }, {}> {
     render() {
@@ -24,15 +27,15 @@ export class Plugin extends React.Component<{ plugin: PluginContext }, {}> {
                     <h3>Behaviors</h3>
                     <StateTree state={this.props.plugin.state.behavior} />
                 </div>
-                <div style={{ position: 'absolute', left: '350px', right: '300px', height: '100%' }}>
+                <div style={{ position: 'absolute', left: '350px', right: '300px', top: '0', bottom: '100px' }}>
                     <Viewport />
                     <div style={{ position: 'absolute', left: '10px', top: '10px', height: '100%', color: 'white' }}>
-                        <_test_TrajectoryControls />
+                        <TrajectoryControls />
                     </div>
                     <ViewportControls />
                 </div>
-                <div style={{ position: 'absolute', width: '300px', right: '0', height: '100%', padding: '10px', overflowY: 'scroll' }}>
-                    <_test_CurrentObject />
+                <div style={{ position: 'absolute', width: '300px', right: '0', top: '0', padding: '10px', overflowY: 'scroll' }}>
+                    <CurrentObject />
                     <hr />
                     <Controls />
                     <hr />
@@ -40,12 +43,44 @@ export class Plugin extends React.Component<{ plugin: PluginContext }, {}> {
                     <hr />
                     <StateSnapshots />
                 </div>
+                <div style={{ position: 'absolute', right: '300px', left: '350px', bottom: '0', height: '100px', overflow: 'hidden' }}>
+                    <Log />
+                </div>
             </div>
         </PluginReactContext.Provider>;
     }
 }
 
-export class _test_CurrentObject extends PluginComponent {
+export class Log extends PluginComponent<{}, { entries: List<LogEntry> }> {
+    private wrapper = React.createRef<HTMLDivElement>();
+
+    componentDidMount() {
+        this.subscribe(this.plugin.events.log, e => this.setState({ entries: this.state.entries.push(e) }));
+    }
+
+    componentDidUpdate() {
+        this.scrollToBottom();
+    }
+
+    state = { entries: List<LogEntry>() };
+
+    private scrollToBottom() {
+        const log = this.wrapper.current;
+        if (log) log.scrollTop = log.scrollHeight - log.clientHeight - 1;
+    }
+
+    render() {
+        return <div ref={this.wrapper} style={{ position: 'absolute', top: '0', right: '0', bottom: '0', left: '0', padding: '10px', overflowY: 'scroll' }}>
+            <ul style={{ listStyle: 'none' }}>
+                {this.state.entries.map((e, i) => <li key={i} style={{ borderBottom: '1px solid #999', padding: '3px' }}>
+                    [{e!.type}] [{formatTime(e!.timestamp)}] {e!.message}
+                </li>)}
+            </ul>
+        </div>;
+    }
+}
+
+export class CurrentObject extends PluginComponent {
     componentDidMount() {
         let current: State.ObjectEvent | undefined = void 0;
         this.subscribe(merge(this.plugin.behaviors.state.data.currentObject, this.plugin.behaviors.state.behavior.currentObject), o => {

src/mol-state/state.ts

@@ -16,6 +16,8 @@ import { StateTreeBuilder } from './tree/builder';
 import { StateAction } from './action';
 import { StateActionManager } from './action/manager';
 import { TransientTree } from './tree/transient';
+import { LogEntry } from 'mol-util/log-entry';
+import { now, formatTimespan } from 'mol-util/now';
 
 export { State }
 
@@ -37,7 +39,7 @@ class State {
             created: this.ev<State.ObjectEvent & { obj: StateObject }>(),
             removed: this.ev<State.ObjectEvent & { obj?: StateObject }>()
         },
-        warn: this.ev<string>(),
+        log: this.ev<LogEntry>(),
         changed: this.ev<void>()
     };
 
@@ -369,6 +371,7 @@ function doError(ctx: UpdateContext, ref: Ref, errorText: string | undefined) {
 
     if (errorText) {
         setCellStatus(ctx, ref, 'error', errorText);
+        ctx.parent.events.log.next({ type: 'error', timestamp: new Date(), message: errorText });
     }
 
     const cell = ctx.cells.get(ref)!;
@@ -391,27 +394,33 @@ function doError(ctx: UpdateContext, ref: Ref, errorText: string | undefined) {
 type UpdateNodeResult =
     | { action: 'created', obj: StateObject }
     | { action: 'updated', obj: StateObject }
-    | { action: 'replaced', oldObj?: StateObject, newObj: StateObject }
+    | { action: 'replaced', oldObj?: StateObject, obj: StateObject }
     | { action: 'none' }
 
 async function updateSubtree(ctx: UpdateContext, root: Ref) {
     setCellStatus(ctx, root, 'processing');
 
     try {
+        const start = now();
         const update = await updateNode(ctx, root);
+        const time = now() - start;
+
         if (update.action !== 'none') ctx.changed = true;
 
         setCellStatus(ctx, root, 'ok');
         if (update.action === 'created') {
             ctx.parent.events.object.created.next({ state: ctx.parent, ref: root, obj: update.obj! });
+            ctx.parent.events.log.next(LogEntry.info(`Created ${update.obj.label} in ${formatTimespan(time)}.`));
             if (!ctx.hadError) {
                 const transform = ctx.tree.transforms.get(root);
                 if (!transform.props || !transform.props.isGhost) ctx.newCurrent = root;
             }
         } else if (update.action === 'updated') {
             ctx.parent.events.object.updated.next({ state: ctx.parent, ref: root, action: 'in-place', obj: update.obj });
+            ctx.parent.events.log.next(LogEntry.info(`Updated ${update.obj.label} in ${formatTimespan(time)}.`));
         } else if (update.action === 'replaced') {
-            ctx.parent.events.object.updated.next({ state: ctx.parent, ref: root, action: 'recreate', obj: update.newObj, oldObj: update.oldObj });
+            ctx.parent.events.object.updated.next({ state: ctx.parent, ref: root, action: 'recreate', obj: update.obj, oldObj: update.oldObj });
+            ctx.parent.events.log.next(LogEntry.info(`Updated ${update.obj.label} in ${formatTimespan(time)}.`));
         }
     } catch (e) {
         ctx.changed = true;
@@ -463,7 +472,7 @@ async function updateNode(ctx: UpdateContext, currentRef: Ref): Promise<UpdateNo
                 const newObj = await createObject(ctx, currentRef, transform.transformer, parent, transform.params);
                 current.obj = newObj;
                 current.version = transform.version;
-                return { action: 'replaced', oldObj, newObj: newObj };
+                return { action: 'replaced', oldObj, obj: newObj };
             }
             case Transformer.UpdateResult.Updated:
                 current.version = transform.version;

src/mol-util/log-entry.ts

@@ -0,0 +1,22 @@
+/**
+ * Copyright (c) 2018 mol* contributors, licensed under MIT, See LICENSE file for more info.
+ *
+ * @author David Sehnal <david.sehnal@gmail.com>
+ */
+
+export { LogEntry }
+
+interface LogEntry {
+    type: LogEntry.Type,
+    timestamp: Date,
+    message: string
+}
+
+namespace LogEntry {
+    export type Type = 'message' | 'error' | 'warning' | 'info'
+
+    export function message(msg: string): LogEntry { return { type: 'message', timestamp: new Date(), message: msg }; }
+    export function error(msg: string): LogEntry { return { type: 'error', timestamp: new Date(), message: msg }; }
+    export function warning(msg: string): LogEntry { return { type: 'warning', timestamp: new Date(), message: msg }; }
+    export function info(msg: string): LogEntry { return { type: 'info', timestamp: new Date(), message: msg }; }
+}

src/mol-util/now.ts

@@ -27,4 +27,21 @@ namespace now {
     export type Timestamp = number & { '@type': 'now-timestamp' }
 }
 
-export { now }
+
+function formatTimespan(t: number) {
+    if (isNaN(t)) return 'n/a';
+
+    let h = Math.floor(t / (60 * 60 * 1000)),
+        m = Math.floor(t / (60 * 1000) % 60),
+        s = Math.floor(t / 1000 % 60),
+        ms = Math.floor(t % 1000).toString();
+
+    while (ms.length < 3) ms = '0' + ms;
+
+    if (h > 0) return `${h}h${m}m${s}.${ms}s`;
+    if (m > 0) return `${m}m${s}.${ms}s`;
+    if (s > 0) return `${s}.${ms}s`;
+    return `${t.toFixed(0)}ms`;
+}
+
+export { now, formatTimespan }