Better worker logs (#784)

* worker: added simple logging

* log run times

* changeset

* format

* log capacity

* updates

* format

.changeset/plenty-cobras-join.md

@@ -0,0 +1,5 @@
+---
+'@openfn/ws-worker': patch
+---
+
+log duration of runs and server capacity

packages/ws-worker/src/api/claim.ts

@@ -35,16 +35,18 @@ const claim = (
 
     const activeWorkers = Object.keys(app.workflows).length;
     if (activeWorkers >= maxWorkers) {
-      logger.debug('skipping claim attempt: server at capacity');
+      logger.debug(
+        `skipping claim attempt: server at capacity (${activeWorkers}/${maxWorkers})`
+      );
       return reject(new Error('Server at capacity'));
     }
 
     if (!app.queueChannel) {
       logger.debug('skipping claim attempt: websocket unavailable');
       return reject(new Error('No websocket available'));
     }
+    logger.debug(`requesting run (capacity ${activeWorkers}/${maxWorkers})`);
 
-    logger.debug('requesting run...');
     app.queueChannel
       .push<ClaimPayload>(CLAIM, { demand: 1 })
       .receive('ok', ({ runs }: ClaimReply) => {

packages/ws-worker/src/server.ts

@@ -181,6 +181,7 @@ function createServer(engine: RuntimeEngine, options: ServerOptions = {}) {
   app.execute = async ({ id, token }: ClaimRun) => {
     if (app.socket) {
       try {
+        const start = Date.now();
         app.workflows[id] = true;
 
         const {
@@ -197,7 +198,10 @@ function createServer(engine: RuntimeEngine, options: ServerOptions = {}) {
 
         // Callback to be triggered when the work is done (including errors)
         const onFinish = () => {
-          logger.debug(`workflow ${id} complete: releasing worker`);
+          const duration = (Date.now() - start) / 1000;
+          logger.debug(
+            `workflow ${id} complete in ${duration}s: releasing worker`
+          );
           delete app.workflows[id];
           runChannel.leave();
 

packages/ws-worker/src/start.ts

@@ -9,6 +9,8 @@ const args = cli(process.argv);
 
 const logger = createLogger('SRV', { level: args.log });
 
+logger.info('Starting worker server...');
+
 if (args.lightning === 'mock') {
   args.lightning = 'ws://localhost:8888/worker';
   if (!args.secret) {
@@ -25,7 +27,7 @@ const [minBackoff, maxBackoff] = args.backoff
   .map((n: string) => parseInt(n, 10) * 1000);
 
 function engineReady(engine: any) {
-  logger.debug('Creating worker server...');
+  logger.debug('Creating worker instance');
 
   const workerOptions: ServerOptions = {
     port: args.port,
@@ -61,6 +63,7 @@ function engineReady(engine: any) {
   logger.debug('Worker options:', humanOptions);
 
   createWorker(engine, workerOptions);
+  logger.success('Worker started OK');
 }
 
 if (args.mock) {