Fix an issue with NodeJS host logging (#1819)

* Fix an issue with NodeJS host logging

Related to pulumi/pulumi#1694. This issue prevented the language host
from being aware that an engine (logging endpoint) was available and
thus no log messages were sent to the engine. By default, the language
host wrote them to standard out instead, which resulted in a pretty bad
error experience.

This commit fixes the PR and adds machinery to the NodeJS langhost tests
for testing the engine RPC endpoint. It is now possible to give a "log"
function to tests which will be hooked up to the "log" RPC endpoint
normally provided by the Pulumi engine.

* Remove accidental console.log
This commit is contained in:
Sean Gillespie 2018-08-24 16:50:09 -07:00 committed by GitHub
parent abfdf69a9c
commit a0cf415179
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 115 additions and 4 deletions

View file

@ -77,7 +77,7 @@ function main(args: string[]): void {
addToEnvIfDefined("PULUMI_NODEJS_DRY_RUN", argv["dry-run"]);
addToEnvIfDefined("PULUMI_NODEJS_PARALLEL", argv["parallel"]);
addToEnvIfDefined("PULUMI_NODEJS_MONITOR", argv["monitor"]);
addToEnvIfDefined("PULUMI_NODEJS_ENGINE", argv["engineAddr"]);
addToEnvIfDefined("PULUMI_NODEJS_ENGINE", argv["engine"]);
require("./run").run(argv);
}

View file

@ -0,0 +1,15 @@
let pulumi = require("../../../../../");
pulumi.log.info("info message");
pulumi.log.warn("warning message");
pulumi.log.error("error message");
class FakeResource extends pulumi.CustomResource {
constructor(name) {
super("test:index:FakeResource", name);
}
}
const res = new FakeResource("test");
pulumi.log.info("attached to resource", res);
pulumi.log.info("with streamid", res, 42);

View file

@ -19,6 +19,8 @@ import * as path from "path";
import { ID, runtime, URN } from "../../../index";
import { asyncTest } from "../../util";
const enginerpc = require("../../../proto/engine_grpc_pb.js");
const engineproto = require("../../../proto/engine_pb.js");
const gempty = require("google-protobuf/google/protobuf/empty_pb.js");
const gstruct = require("google-protobuf/google/protobuf/struct_pb.js");
const grpc = require("grpc");
@ -36,6 +38,10 @@ interface RunCase {
config?: {[key: string]: any};
expectError?: string;
expectResourceCount?: number;
expectedLogs?: {
count?: number;
ignoreDebug?: boolean;
};
invoke?: (ctx: any, tok: string, args: any) => { failures: any, ret: any };
readResource?: (ctx: any, t: string, name: string, id: string, par: string, state: any) => {
urn: URN | undefined, props: any | undefined };
@ -44,6 +50,7 @@ interface RunCase {
urn: URN | undefined, id: ID | undefined, props: any | undefined };
registerResourceOutputs?: (ctx: any, dryrun: boolean, urn: URN,
t: string, name: string, res: any, outputs: any | undefined) => void;
log?: (ctx: any, severity: any, message: string, urn: URN, streamId: number) => void;
}
function makeUrn(t: string, name: string): URN {
@ -370,9 +377,17 @@ describe("rpc", () => {
"sxs:message": "SxS config works!",
},
expectResourceCount: 2,
expectedLogs: {
count: 2,
ignoreDebug: true,
},
registerResource: (ctx: any, dryrun: boolean, t: string, name: string, res: any) => {
return { urn: makeUrn(t, name), id: name, props: undefined };
},
log: (ctx: any, severity: number, message: string, urn: URN, streamId: number) => {
assert.strictEqual(severity, engineproto.LogSeverity.INFO);
assert.strictEqual(/logging via (.*) works/.test(message), true);
},
},
// Test that leaked debuggable promises fail the deployment.
"promise_leak": {
@ -433,6 +448,48 @@ describe("rpc", () => {
return { urn: makeUrn(t, name), id: name, props: {} };
},
},
"logging": {
program: path.join(base, "018.logging"),
expectResourceCount: 1,
expectedLogs: {
count: 5,
ignoreDebug: true,
},
registerResource: (ctx: any, dryrun: boolean, t: string, name: string, res: any) => {
// "test" is the one resource this test creates - save the URN so we can assert
// it gets passed to log later on.
if (name === "test") {
ctx.testUrn = makeUrn(t, name);
}
return { urn: makeUrn(t, name), id: name, props: res};
},
log: (ctx: any, severity: number, message: string, urn: URN, streamId: number) => {
switch (message) {
case "info message":
assert.strictEqual(severity, engineproto.LogSeverity.INFO);
return;
case "warning message":
assert.strictEqual(severity, engineproto.LogSeverity.WARNING);
return;
case "error message":
assert.strictEqual(severity, engineproto.LogSeverity.ERROR);
return;
case "attached to resource":
assert.strictEqual(severity, engineproto.LogSeverity.INFO);
assert.strictEqual(urn, ctx.testUrn);
return;
case "with streamid":
assert.strictEqual(severity, engineproto.LogSeverity.INFO);
assert.strictEqual(urn, ctx.testUrn);
assert.strictEqual(streamId, 42);
return;
default:
assert.fail("unexpected message: " + message);
break;
}
},
},
};
for (const casename of Object.keys(cases)) {
@ -446,6 +503,7 @@ describe("rpc", () => {
const ctx: any = {};
const regs: any = {};
let regCnt = 0;
let logCnt = 0;
const monitor = createMockResourceMonitor(
// Invoke callback
(call: any, callback: any) => {
@ -519,8 +577,26 @@ describe("rpc", () => {
},
);
const engine = createMockEngine((call: any, callback: any) => {
const req: any = call.request;
const severity = req.getSeverity();
const message = req.getMessage();
const urn = req.getUrn();
const streamId = req.getStreamid();
if (opts.expectedLogs) {
if (!opts.expectedLogs.ignoreDebug || severity !== engineproto.LogSeverity.DEBUG) {
logCnt++;
if (opts.log) {
opts.log(ctx, severity, message, urn, streamId);
}
}
}
callback(undefined, new gempty.Empty());
});
// Next, go ahead and spawn a new language host that connects to said monitor.
const langHost = serveLanguageHostProcess();
const langHost = serveLanguageHostProcess(engine.addr);
const langHostAddr: string = await langHost.addr;
// Fake up a client RPC connection to the language host so that we can invoke run.
@ -546,6 +622,14 @@ describe("rpc", () => {
assert.strictEqual(regCnt, expectResourceCount,
`Expected exactly ${expectResourceCount} resource registrations; got ${regCnt}`);
if (opts.expectedLogs) {
const logs = opts.expectedLogs;
if (logs.count) {
assert.strictEqual(logCnt, logs.count,
`Expected exactly ${logs.count} logs; got ${logCnt}`);
}
}
// Finally, tear down everything so each test case starts anew.
await new Promise<void>((resolve, reject) => {
langHost.proc.kill();
@ -618,7 +702,19 @@ function createMockResourceMonitor(
return { server: server, addr: `0.0.0.0:${port}` };
}
function serveLanguageHostProcess(): { proc: childProcess.ChildProcess, addr: Promise<string> } {
// Despite the name, the "engine" RPC endpoint is only a logging endpoint. createMockEngine fires up a fake
// logging server so tests can assert that certain things get logged.
function createMockEngine(logCallback: (call: any, callback: any) => any): { server: any, addr: string } {
const server = new grpc.Server();
server.addService(enginerpc.EngineService, {
log: logCallback,
});
const port = server.bind("0.0.0.0:0", grpc.ServerCredentials.createInsecure());
server.start();
return { server: server, addr: `0.0.0.0:${port}` };
}
function serveLanguageHostProcess(engineAddr: string): { proc: childProcess.ChildProcess, addr: Promise<string> } {
// A quick note about this:
//
// Normally, `pulumi-language-nodejs` launches `./node-modules/@pulumi/pulumi/cmd/run` which is responsible
@ -630,7 +726,7 @@ function serveLanguageHostProcess(): { proc: childProcess.ChildProcess, addr: Pr
// set, it will use that path instead of the default value. For our tests here, we set it and point at the
// just built version of run.
process.env.PULUMI_LANGUAGE_NODEJS_RUN_PATH = "./bin/cmd/run";
const proc = childProcess.spawn("pulumi-language-nodejs");
const proc = childProcess.spawn("pulumi-language-nodejs", [engineAddr]);
// Hook the first line so we can parse the address. Then we hook the rest to print for debugging purposes, and
// hand back the resulting process object plus the address we plucked out.