Modified some system logs to flow through gRPC.

Author: yojagad

src/Context.ts

@@ -4,8 +4,8 @@ import { AzureFunctionsRpcMessages as rpc } from '../azure-functions-language-wo
 import { Request, RequestProperties } from './http/Request';
 import { Response } from './http/Response';
 import LogLevel = rpc.RpcLog.Level;
+import LogCategory = rpc.RpcLog.RpcLogCategory;
 import { Context, ExecutionContext, Logger, BindingDefinition, HttpRequest } from './public/Interfaces' 
-import { systemWarn } from './utils/Logger';
 
 export function CreateContextAndInputs(info: FunctionInfo, request: rpc.IInvocationRequest, logCallback: LogCallback, callback: ResultCallback) {
   let context = new InvocationContext(info, request, logCallback, callback);
@@ -79,9 +79,9 @@ class InvocationContext implements Context {
       _promise = isPromise === true;
       if (_done) {
         if (_promise) {
-          logCallback(LogLevel.Error, "Error: Choose either to return a promise or call 'done'.  Do not use both in your script.");
+          logCallback(LogLevel.Error, LogCategory.User, "Error: Choose either to return a promise or call 'done'.  Do not use both in your script.");
         } else {
-          logCallback(LogLevel.Error, "Error: 'done' has already been called. Please check your script for extraneous calls to 'done'.");
+          logCallback(LogLevel.Error, LogCategory.User, "Error: 'done' has already been called. Please check your script for extraneous calls to 'done'.");
         }
         return;
       }
@@ -106,10 +106,9 @@ function logWithAsyncCheck(done: boolean, log: LogCallback, level: LogLevel, exe
     let badAsyncMsg = "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. ";
     badAsyncMsg += `Function name: ${executionContext.functionName}. Invocation Id: ${executionContext.invocationId}. `;
     badAsyncMsg += `Learn more: https://go.microsoft.com/fwlink/?linkid=2097909 `;
-    log(LogLevel.Warning, badAsyncMsg);
-    systemWarn(badAsyncMsg);
+    log(LogLevel.Warning, LogCategory.System, badAsyncMsg);
   }
-  return log(level, ...args);
+  return log(level, LogCategory.User, ...args);
 }
 
 export interface InvocationResult {
@@ -119,7 +118,7 @@ export interface InvocationResult {
 
 export type DoneCallback = (err?: Error | string, result?: any) => void;
 
-export type LogCallback = (level: LogLevel, ...args: any[]) => void;
+export type LogCallback = (level: LogLevel, category: rpc.RpcLog.RpcLogCategory, ...args: any[]) => void;
 
 export type ResultCallback = (err?: any, result?: InvocationResult) => void;
 

src/Worker.ts

@@ -57,4 +57,4 @@ export function startNodeWorker(args) {
   process.on('exit', code => {
     systemLog(`Worker ${workerId} exited with code ${code}`);
   });
-}
+}

src/WorkerChannel.ts

@@ -1,13 +1,14 @@
 import { format, isFunction } from 'util';
 import { AzureFunctionsRpcMessages as rpc } from '../azure-functions-language-worker-protobuf/src/rpc';
-import Status = rpc.StatusResult.Status;
 import { IFunctionLoader } from './FunctionLoader';
 import { CreateContextAndInputs, LogCallback, ResultCallback } from './Context';
 import { IEventStream } from './GrpcService';
 import { toTypedData } from './converters';
 import { augmentTriggerMetadata } from './augmenters';
-import { systemError, systemLog } from './utils/Logger';
+import { systemError } from './utils/Logger';
 import { InternalException } from './utils/InternalException';
+import LogCategory = rpc.RpcLog.RpcLogCategory;
+import LogLevel = rpc.RpcLog.Level;
 
 /**
  * The worker channel should have a way to handle all incoming gRPC messages.
@@ -46,7 +47,11 @@ export class WorkerChannel implements IWorkerChannel {
       if (eventHandler) {
         eventHandler.apply(this, [msg.requestId, msg[event]]);
       } else {
-        systemError(`Worker ${workerId} had no handler for message '${event}'`)
+        this.log({
+          message: `Worker ${workerId} had no handler for message '${event}'`,
+          level: LogLevel.Error,
+          logCategory: LogCategory.System
+        });
       }
     });
     eventStream.on('error', function (err) {
@@ -109,7 +114,11 @@ export class WorkerChannel implements IWorkerChannel {
       }
       catch(exception) {
         errorMessage = `Worker was unable to load function ${msg.metadata.name}: '${exception}'`;
-        systemError(errorMessage)
+        this.log({
+          message: errorMessage,
+          level: LogLevel.Error,
+          logCategory: LogCategory.System
+        });
         err = exception;
       }
 
@@ -133,12 +142,13 @@ export class WorkerChannel implements IWorkerChannel {
     augmentTriggerMetadata(msg);
 
     let info = this._functionLoader.getInfo(<string>msg.functionId);
-    let logCallback: LogCallback = (level, ...args) => {
+    let logCallback: LogCallback = (level, category, ...args) => {
       this.log({
         invocationId: msg.invocationId,
         category: `${info.name}.Invocation`,
         message: format.apply(null, args),
-        level: level
+        level: level,
+        logCategory: category
       });
     }
 
@@ -238,7 +248,11 @@ export class WorkerChannel implements IWorkerChannel {
   public functionEnvironmentReloadRequest(requestId: string, msg: rpc.IFunctionEnvironmentReloadRequest): void {
     // Add environment variables from incoming
     let numVariables = (msg.environmentVariables && Object.keys(msg.environmentVariables).length) || 0;
-    systemLog(`Reloading environment variables. Found ${numVariables} variables to reload.`);
+    this.log({
+      message: `Reloading environment variables. Found ${numVariables} variables to reload.`,
+      level: LogLevel.Information,
+      logCategory: LogCategory.System
+    });
 
     let error = null;
     try {

src/utils/Logger.ts

@@ -1,3 +1,8 @@
+/**
+ *  Use these methods only if you want to guarantee the messages reach the host despite potential performance impact. 
+    Otherwise, please stick to utilizing the gRPC channel to propagate these messages with category: RpcLogCategory.System
+ **/ 
+
 const logPrefix = "LanguageWorkerConsoleLog";
 
 export function systemLog(message?: any, ...optionalParams: any[]) { 

test/ContextTests.ts

@@ -28,7 +28,7 @@ describe('Context', () => {
     it ('async function logs error on calling context.done', async () => {
         await callUserFunc(BasicAsync.asyncAndCallback, _context);
         sinon.assert.calledOnce(_logger);
-        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Error, "Error: Choose either to return a promise or call 'done'.  Do not use both in your script.");
+        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Error, rpc.RpcLog.RpcLogCategory.User, "Error: Choose either to return a promise or call 'done'.  Do not use both in your script.");
     });
 
     it ('async function calls callback and returns value without context.done', async () => {
@@ -40,21 +40,21 @@ describe('Context', () => {
     it ('function logs error on calling context.done more than once', () => {
         callUserFunc(BasicCallback.callbackTwice, _context);
         sinon.assert.calledOnce(_logger);
-        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Error, "Error: 'done' has already been called. Please check your script for extraneous calls to 'done'.");
+        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Error, rpc.RpcLog.RpcLogCategory.User, "Error: 'done' has already been called. Please check your script for extraneous calls to 'done'.");
     });
 
     it ('function logs error on calling context.log after context.done() called', () => {
         callUserFunc(BasicCallback.callbackOnce, _context);
         _context.log("");
         sinon.assert.calledTwice(_logger);
-        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Warning, "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. Function name: test. Invocation Id: 1. Learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ");
+        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Warning, rpc.RpcLog.RpcLogCategory.System, "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. Function name: test. Invocation Id: 1. Learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ");
     });
 
     it ('function logs error on calling context.log from non-awaited async call', async () => {
         await callUserFunc(BasicAsync.asyncPlainFunction, _context);
         _context.log("");
         sinon.assert.calledTwice(_logger);
-        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Warning, "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. Function name: test. Invocation Id: 1. Learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ");
+        sinon.assert.calledWith(_logger, rpc.RpcLog.Level.Warning, rpc.RpcLog.RpcLogCategory.System, "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. Function name: test. Invocation Id: 1. Learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ");
     });
 
     it ('function calls callback correctly with bindings', () => {