[logging] Send ffx log stderr to the output channel

Change-Id: I31375e13b3066dccb89114b2f6bfa5b76ebe7adf
diff --git a/src/ffx.ts b/src/ffx.ts
index d21482e..97599d1 100644
--- a/src/ffx.ts
+++ b/src/ffx.ts
@@ -4,6 +4,8 @@
 
 import * as vscode from 'vscode';
 import { ChildProcessWithoutNullStreams, spawn } from 'child_process';
+// @ts-ignore: no @types/jsonparse available.
+import * as JsonParser from 'jsonparse';
 
 /**
  * FuchsiaDevice represents the object returned from `ffx target list`.
@@ -212,12 +214,31 @@
   }
 
   /**
+   * Runs ffx --target [device] --machine json log
+   *
+   * @param device the name of the target device to use on ffx log
+   * @param onData when data is received this command will be called
+   * @returns the ffx log process
+   */
+  public runLog(device: string | undefined, onData: (data: Object) => void): FfxLog {
+    let args = (device)? ['--target', device] : [];
+    args = args.concat(['--machine', 'json', 'log']);
+    let cmd = `${this.ffxPath} ${args.join(' ')}`;
+    return new FfxJsonStream(
+      this.spawn(args),
+      onData,
+      (data) => {
+        this.log.appendLine(`Error [${cmd}]: ${data}`);
+      });
+  }
+
+  /**
    * Spawns a new process running ffx with the given arguments.
    *
    * @param args command line arguments to ffx.
    * @returns The ChildProcess is returned or undefined if there was a problem.
    */
-  public spawn(args: string[]): ChildProcessWithoutNullStreams | undefined {
+  spawn(args: string[]): ChildProcessWithoutNullStreams | undefined {
     if (this.ffxPath === undefined) {
       return undefined;
     }
@@ -274,3 +295,37 @@
     });
   }
 }
+
+export type FfxLog = JsonStreamProcess;
+
+/**
+ * A stream of JSON Data coming from a process.
+ */
+class JsonStreamProcess {
+  private parser: JsonParser;
+
+  constructor(
+    private process: ChildProcessWithoutNullStreams | undefined,
+    private onData: (data: Object) => void,
+    private onError: (data: string) => void,
+  ) {
+    this.parser = new JsonParser();
+    this.process?.stdout.on('data', (chunk) => {
+      this.parser.write(chunk);
+    });
+    this.process?.stderr.on('data', this.onError);
+    let self = this;
+    this.parser.onValue = function(value: Object) {
+      if (this.stack.length === 0) {
+        self.onData(value);
+      }
+    };
+  }
+
+  /**
+   * Kills the underlying process.
+   */
+  public stop() {
+    this.process?.kill();
+  }
+}
diff --git a/src/logging/view_provider.ts b/src/logging/view_provider.ts
index af9bab9..3006182 100644
--- a/src/logging/view_provider.ts
+++ b/src/logging/view_provider.ts
@@ -3,10 +3,7 @@
 // found in the LICENSE file.
 
 import * as vscode from 'vscode';
-import { Ffx, FuchsiaDevice } from '../ffx';
-import { ChildProcessWithoutNullStreams } from 'child_process';
-// @ts-ignore: no @types/jsonparse available.
-import * as JsonParser from 'jsonparse';
+import { Ffx, FfxLog, FuchsiaDevice } from '../ffx';
 
 export const TOGGLE_LOG_VIEW_COMMAND = 'workbench.view.extension.fuchsia-logging';
 
@@ -14,7 +11,7 @@
   public static readonly viewType = 'vscode-fuchsia.loggingView';
 
   private view?: vscode.WebviewView;
-  private process?: ChildProcessWithoutNullStreams;
+  private process?: FfxLog;
   private currentDevice?: string;
 
   constructor(
@@ -63,7 +60,7 @@
       if (this.view?.visible) {
         this.startListeningForLogs();
       } else {
-        this.process?.kill();
+        this.process?.stop();
       }
     });
   }
@@ -103,19 +100,10 @@
   }
 
   private startListeningForLogs() {
-    this.process?.kill();
-    let args = (this.currentDevice !== undefined) ? ['--target', this.currentDevice] : [];
-    this.process = this.ffx.spawn(args.concat(['--machine', 'json', 'log']));
-    const parser = new JsonParser();
-    this.process?.stdout.on('data', (chunk) => {
-      parser.write(chunk);
+    this.process?.stop();
+    this.process = this.ffx.runLog(this.currentDevice, (data: Object) => {
+      this.addLog(data);
     });
-    let self = this;
-    parser.onValue = function (value: Object) {
-      if (this.stack.length === 0) {
-        self.addLog(value);
-      }
-    };
   }
 
   private _getHtmlForWebview(webview: vscode.Webview): string {
diff --git a/src/test/suite/ffx.test.ts b/src/test/suite/ffx.test.ts
index b99e3aa..9309a30 100644
--- a/src/test/suite/ffx.test.ts
+++ b/src/test/suite/ffx.test.ts
@@ -4,7 +4,7 @@
 import * as vscode from 'vscode';
 import * as assert from 'assert';
 
-import { describe, it } from 'mocha';
+import { beforeEach, describe, it } from 'mocha';
 import { createSandbox } from 'sinon';
 import { Ffx, FfxEventType, FuchsiaDevice } from '../../ffx';
 import { ToolFinder } from '../../tool_finder';
@@ -314,4 +314,48 @@
       assert.strictEqual(count, 1);
     });
   });
+
+  describe('#runLog', () => {
+    let ffx: Ffx;
+    let log: vscode.OutputChannel;
+
+    const LOG_ARGS = ['--target', 'foo', '--machine', 'json', 'log'];
+
+    beforeEach(() => {
+      let logger = sandbox.spy(vscode.window.createOutputChannel);
+      log = logger('test_ffx');
+      ffx = new Ffx(log, TEST_CWD, TEST_FFX);
+    });
+
+    it('parses stdout and sends it to the callback', () => {
+      let received = undefined;
+      const TEST_DATA : Object = {'foo': 'bar'};
+      stubbedSpawn.spawnStubInfo.callsFake(() => stubbedSpawn.spawnEvent);
+      ffx.runLog('foo', (data) => {
+        received = data;
+      });
+      assert.deepStrictEqual(stubbedSpawn.spawnStubInfo.getCall(0).args,
+        [TEST_FFX, LOG_ARGS, { cwd: TEST_CWD }]);
+      stubbedSpawn.spawnEvent.stdout?.emit('data', JSON.stringify(TEST_DATA));
+      assert.deepStrictEqual(received, TEST_DATA);
+    });
+
+    it('sends stderr to the log', () => {
+      sandbox.spy(log, 'appendLine');
+      stubbedSpawn.spawnStubInfo.callsFake(() => stubbedSpawn.spawnEvent);
+      ffx.runLog('foo', (_) => {});
+      stubbedSpawn.spawnEvent.stderr?.emit('data', 'oh no');
+      // @ts-ignore: sinon
+      assert.ok(log.appendLine.calledTwice);
+      assert.deepStrictEqual(
+        // @ts-ignore: sinon
+        log.appendLine.getCall(0).args[0],
+        `Running: /path/to/ffx ${LOG_ARGS.join(' ')}`);
+      assert.deepStrictEqual(
+        // @ts-ignore: sinon
+        log.appendLine.getCall(1).args[0],
+        `Error [/path/to/ffx ${LOG_ARGS.join(' ')}]: oh no`
+      );
+    });
+  });
 });
diff --git a/src/test/suite/logging/view_provider.test.ts b/src/test/suite/logging/view_provider.test.ts
index 61840ff..f59e406 100644
--- a/src/test/suite/logging/view_provider.test.ts
+++ b/src/test/suite/logging/view_provider.test.ts
@@ -11,7 +11,6 @@
 import { LoggingViewProvider, TOGGLE_LOG_VIEW_COMMAND } from '../../../logging/view_provider';
 import { Ffx, FuchsiaDevice } from '../../../ffx';
 import { StubbedSpawn } from '../utils';
-import { EventEmitter } from 'stream';
 
 describe('Logging view provider tests', function () {
   const sandbox = createSandbox();
@@ -19,8 +18,11 @@
   let uri : vscode.Uri;
   let provider: LoggingViewProvider;
   let targetEventEmitter : vscode.EventEmitter<FuchsiaDevice | null>;
+  let log: vscode.OutputChannel;
 
   this.beforeEach(() => {
+    let logger = sandbox.spy(vscode.window.createOutputChannel);
+    log = logger('test_ffx');
     sandbox.spy(vscode.commands);
     uri = vscode.Uri.file('/fake/file');
     targetEventEmitter = new vscode.EventEmitter<FuchsiaDevice | null>();
@@ -36,10 +38,10 @@
 
   describe('visibility changes', () => {
     it('stops the ffx process when the view is hidden', () => {
-      let fakeProcess = { kill: sandbox.spy(), stdout: new EventEmitter() };
+      let fakeProcess = { stop: sandbox.spy() };
 
       // @ts-ignore
-      ffx.spawn.returns(fakeProcess);
+      ffx.runLog.returns(fakeProcess);
       let provider = new LoggingViewProvider(uri, ffx);
       let emitter = new vscode.EventEmitter<void>();
       let view = fakeWebviewView(sandbox, true, emitter.event);
@@ -52,7 +54,7 @@
       // @ts-ignore: readonly field, but set it for testing purposes.
       view.visible = false;
       emitter.fire();
-      assert.ok(fakeProcess.kill.calledOnce);
+      assert.ok(fakeProcess.stop.calledOnce);
     });
 
     it('spawns an ffx process when the view appears', () => {
@@ -61,23 +63,25 @@
       // @ts-ignore: passing empty objects that we don't need.
       provider.resolveWebviewView(view, {}, {});
       emitter.fire();
-      assert.ok(ffx.spawn.calledOnce);
-      assert.deepStrictEqual(ffx.spawn.getCall(0).args[0], ['--machine', 'json', 'log']);
+      assert.ok(ffx.runLog.calledOnce);
+      assert.deepStrictEqual(ffx.runLog.getCall(0).args[0], undefined);
     });
   });
 
   describe('add a log', () => {
     it('pushes a log to the webview when received', () => {
       let process = new StubbedSpawn(sandbox);
+      let ffx = new Ffx(log, 'foo');
+      // @ts-ignore: fake process
+      sandbox.stub(ffx, 'spawn').returns(process.spawnEvent);
+      let provider = new LoggingViewProvider(uri, ffx);
 
-      // @ts-ignore
-      ffx.spawn.returns(process);
       let emitter = new vscode.EventEmitter<void>();
       let view = fakeWebviewView(sandbox, true, emitter.event);
       // @ts-ignore: passing empty objects that we don't need.
       provider.resolveWebviewView(view, {}, {});
 
-      // Creates the process
+      // The view should be visible now.
       emitter.fire();
 
       const data = '{"data":{"TargetLog": {}}}';
@@ -94,9 +98,11 @@
 
     it('handles logs that contain new lines', () => {
       let process = new StubbedSpawn(sandbox);
+      let ffx = new Ffx(log, 'foo');
+      // @ts-ignore: fake process
+      sandbox.stub(ffx, 'spawn').returns(process.spawnEvent);
+      let provider = new LoggingViewProvider(uri, ffx);
 
-      // @ts-ignore
-      ffx.spawn.returns(process);
       let emitter = new vscode.EventEmitter<void>();
       let view = fakeWebviewView(sandbox, true, emitter.event);
       // @ts-ignore: passing empty objects that we don't need.
@@ -156,11 +162,8 @@
       assert.ok(view.webview.postMessage.calledOnce);
       // @ts-ignore: getCall comes from sinon
       assert.deepStrictEqual(view.webview.postMessage.getCall(0).args[0], { type: 'reset' });
-      assert.ok(ffx.spawn.calledOnce);
-      assert.deepStrictEqual(
-        ffx.spawn.getCall(0).args[0],
-        ['--target', 'foo', '--machine', 'json', 'log']
-      );
+      assert.ok(ffx.runLog.calledOnce);
+      assert.deepStrictEqual(ffx.runLog.getCall(0).args[0], 'foo');
     });
 
     it('shows the view when the device changes and the view is not visible', () => {