You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@openwhisk.apache.org by al...@apache.org on 2020/04/14 00:45:07 UTC
[openwhisk-wskdebug] 01/02: add debug() logs with DEBUG=wskdebug
providing time spent details
This is an automated email from the ASF dual-hosted git repository.
alexkli pushed a commit to branch performance
in repository https://gitbox.apache.org/repos/asf/openwhisk-wskdebug.git
commit a1d9da2af64a6e2e7f87a11431fa298f82bd23df
Author: Alexander Klimetschek <ak...@adobe.com>
AuthorDate: Mon Apr 13 17:02:01 2020 -0700
add debug() logs with DEBUG=wskdebug providing time spent details
---
index.js | 2 ++
package-lock.json | 54 +++++++++++++++++++++++++++++++++++++++++++++++++++---
package.json | 3 +++
src/agentmgr.js | 10 ++++++++++
src/debug.js | 21 +++++++++++++++++++++
src/debugger.js | 31 +++++++++++++++++++++++++++++--
src/invoker.js | 21 ++++++++++++++-------
src/watcher.js | 2 ++
8 files changed, 132 insertions(+), 12 deletions(-)
diff --git a/index.js b/index.js
index 0406efe..18d13ff 100644
--- a/index.js
+++ b/index.js
@@ -21,6 +21,7 @@ const yargs = require("yargs");
const Debugger = require("./src/debugger");
const path = require("path");
const fs = require("fs");
+const debug = require('./src/debug');
function enableConsoleColors() {
// colorful console.error() and co
@@ -286,6 +287,7 @@ function registerExitHandler(dbg) {
}
async function wskdebug(args, isCommandLine=false) {
+ debug("wskdebug arguments:", args);
const originalConsole = enableConsoleColors();
try {
diff --git a/package-lock.json b/package-lock.json
index 28b394f..00a4067 100644
--- a/package-lock.json
+++ b/package-lock.json
@@ -655,9 +655,9 @@
}
},
"debug": {
- "version": "3.2.6",
- "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz",
- "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==",
+ "version": "4.1.1",
+ "resolved": "https://registry.npmjs.org/debug/-/debug-4.1.1.tgz",
+ "integrity": "sha512-pYAIzeRo8J6KPEaJ0VWOh5Pzkbw/RetuzehGM7QRRX5he4fPHx2rdKMB256ehJCkX+XRQm16eZLqLNS8RSZXZw==",
"requires": {
"ms": "^2.1.1"
}
@@ -1938,6 +1938,15 @@
"integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU=",
"dev": true
},
+ "debug": {
+ "version": "3.2.6",
+ "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz",
+ "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==",
+ "dev": true,
+ "requires": {
+ "ms": "^2.1.1"
+ }
+ },
"emoji-regex": {
"version": "7.0.3",
"resolved": "https://registry.npmjs.org/emoji-regex/-/emoji-regex-7.0.3.tgz",
@@ -2106,6 +2115,17 @@
"requires": {
"debug": "^3.1.0",
"lodash": "^4.16.4"
+ },
+ "dependencies": {
+ "debug": {
+ "version": "3.2.6",
+ "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz",
+ "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==",
+ "dev": true,
+ "requires": {
+ "ms": "^2.1.1"
+ }
+ }
}
},
"mock-require": {
@@ -2160,6 +2180,16 @@
"debug": "^3.2.6",
"iconv-lite": "^0.4.4",
"sax": "^1.2.4"
+ },
+ "dependencies": {
+ "debug": {
+ "version": "3.2.6",
+ "resolved": "https://registry.npmjs.org/debug/-/debug-3.2.6.tgz",
+ "integrity": "sha512-mel+jf7nrtEl5Pn1Qx46zARXKDpBbvzezse7p7LqINmdoIk8PYP5SySaxEmYv6TZ0JyEKA1hsCId6DIhgITtWQ==",
+ "requires": {
+ "ms": "^2.1.1"
+ }
+ }
}
},
"nice-try": {
@@ -2419,6 +2449,11 @@
"callsites": "^3.0.0"
}
},
+ "parse-ms": {
+ "version": "2.1.0",
+ "resolved": "https://registry.npmjs.org/parse-ms/-/parse-ms-2.1.0.tgz",
+ "integrity": "sha512-kHt7kzLoS9VBZfUsiKjv43mr91ea+U05EyKkEtqp7vNbHxmaVuEqN7XxeEVnGrMtYOAxGrDElSi96K7EgO1zCA=="
+ },
"path-exists": {
"version": "4.0.0",
"resolved": "https://registry.npmjs.org/path-exists/-/path-exists-4.0.0.tgz",
@@ -2462,6 +2497,19 @@
"integrity": "sha1-IZMqVJ9eUv/ZqCf1cOBL5iqX2lQ=",
"dev": true
},
+ "pretty-bytes": {
+ "version": "5.3.0",
+ "resolved": "https://registry.npmjs.org/pretty-bytes/-/pretty-bytes-5.3.0.tgz",
+ "integrity": "sha512-hjGrh+P926p4R4WbaB6OckyRtO0F0/lQBiT+0gnxjV+5kjPBrfVBFCsCLbMqVQeydvIoouYTCmmEURiH3R1Bdg=="
+ },
+ "pretty-ms": {
+ "version": "6.0.1",
+ "resolved": "https://registry.npmjs.org/pretty-ms/-/pretty-ms-6.0.1.tgz",
+ "integrity": "sha512-ke4njoVmlotekHlHyCZ3wI/c5AMT8peuHs8rKJqekj/oR5G8lND2dVpicFlUz5cbZgE290vvkMuDwfj/OcW1kw==",
+ "requires": {
+ "parse-ms": "^2.1.0"
+ }
+ },
"process-on-spawn": {
"version": "1.0.0",
"resolved": "https://registry.npmjs.org/process-on-spawn/-/process-on-spawn-1.0.0.tgz",
diff --git a/package.json b/package.json
index 6aa1af5..b717ddf 100644
--- a/package.json
+++ b/package.json
@@ -42,12 +42,15 @@
"file": "test/logfile.setup.js"
},
"dependencies": {
+ "debug": "^4.1.1",
"fetch-retry": "^3.1.0",
"fs-extra": "^8.1.0",
"isomorphic-fetch": "^2.2.1",
"livereload": "^0.9.1",
"manakin": "^0.5.2",
"openwhisk": "^3.21.1",
+ "pretty-bytes": "^5.3.0",
+ "pretty-ms": "^6.0.1",
"yargs": "^15.3.1"
},
"peerDependencies": {
diff --git a/src/agentmgr.js b/src/agentmgr.js
index ecf33a2..1806c05 100644
--- a/src/agentmgr.js
+++ b/src/agentmgr.js
@@ -27,6 +27,7 @@ try {
const fs = require('fs-extra');
const sleep = require('util').promisify(setTimeout);
+const debug = require('./debug');
function getAnnotation(action, key) {
const a = action.annotations.find(a => a.key === key);
@@ -76,6 +77,7 @@ async function deleteActionIfExists(wsk, name) {
if (await actionExists(wsk, name)) {
await wsk.actions.delete(name);
}
+ debug(`restore: ensured removal of action ${name}`);
}
@@ -170,6 +172,7 @@ class AgentMgr {
// agent using ngrok for forwarding
agentName = "ngrok";
agentCode = await this.ngrokAgent.getAgent(action);
+ debug("started local ngrok proxy");
} else {
this.concurrency = await this.openwhiskSupports("concurrency");
@@ -197,6 +200,7 @@ class AgentMgr {
name: backupName,
action: action
});
+ debug(`created action backup ${backupName}`);
if (this.argv.verbose) {
console.log(`Original action backed up at ${backupName}.`);
@@ -220,6 +224,7 @@ class AgentMgr {
await this.pushAgent(action, agentCode, backupName);
}
}
+ debug(`installed agent (${agentName}) in place of ${this.actionName}`);
if (this.argv.verbose) {
console.log(`Agent installed.`);
@@ -238,6 +243,7 @@ class AgentMgr {
} finally {
if (this.ngrokAgent) {
await this.ngrokAgent.stop();
+ debug("ngrok shut down");
}
}
}
@@ -404,15 +410,18 @@ class AgentMgr {
try {
// the original was backed up in the copy
const original = await this.wsk.actions.get(copy);
+ debug("restore: fetched action original from backup copy (move step 1)");
// copy the backup (copy) to the regular action
await this.wsk.actions.update({
name: this.actionName,
action: original
});
+ debug("restore: restored action with original (move step 2)");
// remove the backup
await this.wsk.actions.delete(copy);
+ debug("restore: deleted backup copy (move step 3)");
// remove any helpers if they exist
await deleteActionIfExists(this.wsk, `${this.actionName}_wskdebug_invoked`);
@@ -492,6 +501,7 @@ class AgentMgr {
]
}
});
+ debug(`created helper action ${actionName}`);
}
// ----------------------------------------< openwhisk feature detection >-----------------
diff --git a/src/debug.js b/src/debug.js
new file mode 100644
index 0000000..6e4cc49
--- /dev/null
+++ b/src/debug.js
@@ -0,0 +1,21 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+'use strict';
+
+// common debug() instance for shared time spent measurments (+millis)
+module.exports = require('debug')('wskdebug');
diff --git a/src/debugger.js b/src/debugger.js
index 3bf6433..7343fb6 100644
--- a/src/debugger.js
+++ b/src/debugger.js
@@ -24,12 +24,17 @@ const Watcher = require('./watcher');
const openwhisk = require('openwhisk');
const { spawnSync } = require('child_process');
const sleep = require('util').promisify(setTimeout);
+const debug = require('./debug');
+const prettyBytes = require('pretty-bytes');
+const prettyMilliseconds = require('pretty-ms');
/**
* Central component of wskdebug.
*/
class Debugger {
constructor(argv) {
+ this.startTime = Date.now();
+ debug("starting debugger");
this.argv = argv;
this.actionName = argv.action;
@@ -51,12 +56,15 @@ class Debugger {
// quick fail for missing requirements such as docker not running
await OpenWhiskInvoker.checkIfAvailable();
+ debug("verified that docker is available and running");
console.info(`Starting debugger for /${this.wskProps.namespace}/${this.actionName}`);
// get the action metadata
const actionMetadata = await this.agentMgr.peekAction();
+ debug("fetched action metadata from openwhisk");
+
// local debug container
this.invoker = new OpenWhiskInvoker(this.actionName, actionMetadata, this.argv, this.wskProps, this.wsk);
@@ -70,10 +78,17 @@ class Debugger {
// start container - get it up fast for VSCode to connect within its 10 seconds timeout
await this.invoker.startContainer();
+ debug(`started container: ${this.invoker.name()}`);
+
// get code and /init local container
const actionWithCode = await this.agentMgr.readActionWithCode();
+
+ debug(`fetched action code from openwhisk (${prettyBytes(actionWithCode.exec.code.length)})`);
+
await this.invoker.init(actionWithCode);
+ debug("installed action on container (/init)");
+
// setup agent in openwhisk
await this.agentMgr.installAgent(actionWithCode, this.invoker);
@@ -87,10 +102,17 @@ class Debugger {
console.log();
console.info(`Action : ${this.actionName}`);
- this.invoker.logInfo();
+ if (this.sourcePath) {
+ console.info(`Sources : ${this.invoker.getSourcePath()}`);
+ }
+ console.info(`Image : ${this.invoker.getImage()}`);
+ console.info(`Container : ${this.invoker.name()}`);
+ console.info(`Debug type : ${this.invoker.getDebugKind()}`);
+ console.info(`Debug port : localhost:${this.invoker.getPort()}`);
if (this.argv.condition) {
console.info(`Condition : ${this.argv.condition}`);
}
+ console.info(`Startup : ${prettyMilliseconds(Date.now() - this.startTime)}`)
console.log();
console.info(`Ready, waiting for activations! Use CTRL+C to exit`);
@@ -183,6 +205,8 @@ class Debugger {
return;
}
this.shuttingDown = true;
+ const shutdownStart = Date.now();
+ debug("shutting down...");
// only log this if we started properly
if (this.ready) {
@@ -198,14 +222,16 @@ class Debugger {
}
if (this.invoker) {
await this.tryCatch(this.invoker.stop());
+ debug(`stopped container: ${this.invoker.name()}`);
}
if (this.watcher) {
await this.tryCatch(this.watcher.stop());
+ debug("stopped source file watching");
}
// only log this if we started properly
if (this.ready) {
- console.log(`Done`);
+ console.log(`Done (shutdown took ${prettyMilliseconds(Date.now() - shutdownStart)})`);
}
this.ready = false;
}
@@ -234,6 +260,7 @@ class Debugger {
process.exit(2);
}
this.wskProps.namespace = namespaces[0];
+ debug(`fetched namespace name: ${this.wskProps.namespace} (was not in wskprops file)`);
}
}
}
diff --git a/src/invoker.js b/src/invoker.js
index f2fe6dc..9a92318 100644
--- a/src/invoker.js
+++ b/src/invoker.js
@@ -241,13 +241,20 @@ class OpenWhiskInvoker {
});
}
- async logInfo() {
- if (this.sourcePath) {
- console.info(`Sources : ${this.sourcePath}`);
- }
- console.info(`Image : ${this.image}`);
- console.info(`Debug type : ${this.debugKind}`);
- console.info(`Debug port : localhost:${this.debug.port}`)
+ getSourcePath() {
+ return this.sourcePath;
+ }
+
+ getImage() {
+ return this.image;
+ }
+
+ getDebugKind() {
+ return this.debugKind;
+ }
+
+ getPort() {
+ return this.debug.port;
}
async init(actionWithCode) {
diff --git a/src/watcher.js b/src/watcher.js
index 4e0fd91..dcea5a6 100644
--- a/src/watcher.js
+++ b/src/watcher.js
@@ -20,6 +20,7 @@
const fs = require('fs-extra');
const livereload = require('livereload');
const { spawnSync } = require('child_process');
+const debug = require('./debug');
class Watcher {
constructor(argv, wsk) {
@@ -105,6 +106,7 @@ class Watcher {
if (this.argv.livereload) {
console.info(`LiveReload enabled for ${watch} on port ${this.liveReloadServer.config.port}`);
}
+ debug("started source file watching");
}
}