Call a function B from inside function A, and make B do something when A starts and finishes

Question

Given the following code...

function logger = ??

function doSomething() {
  logger("doSomething")
  console.log("Middle of doing something")
}

Is it possible to define logger such that the following output is produced?

"started function doSomething"
"Middle of doing something"
"finished function doSomething"

I've considered the following:

• Encapsulating doSomething in another function that prints first line, calls doSomething while passing the arguments, then prints last line.

• Doing the same thing previously mentioned but with a decorator so it's prettier.

• Sending an event at the end of doSomething to notify logger it finished and using async code to do that (this one was kind of a shot in the dark, not sure about it)

It was hinted to me during an interview that this is possible via "something to do with heap and the call stack".

Is there a solution that does not involve doSomething telling logger when it has finished?

Answer 1

I've considered ... Encapsulating ... with a decorator ...

That's the way to go.

Sending an event at the end of doSomething to notify logger it finished and using async code...

Using asynchronous code is only relevant when you already have an asynchronous API involved in doSomething.

Is there a solution that does not involve doSomething telling logger when it has finished?

That's the basic idea of decorators.

Example:

let logger = console.log;

// Decorator
function logged(task) {
    return function(...args) {
        logger("starting " + task.name);
        const result = task(...args);
        logger("ending " + task.name);
        return result;
    };
}

// Your function -- unaware of logger
function doSomething(arg) {
  console.log("Middle of doing something with argument " + arg);
  return arg.toUpperCase();
}

// Decorating...
doSomething = logged(doSomething);

// Run...
let result = doSomething("test");
console.log(result);

More features...

There are many extensions/features you can add. For instance:

• Include a generic decorator function that takes the target function and any number of decorators as arguments;
• The name of the decorated function could be made equal to the original function name;
• A decorator can decide to perform some action in a finally block
• ...

let logger = console.log;

// Generic decorator function
function decorate(target, ...decorators) {
    return decorators.reduce((acc, decorator) =>
        // Propagate target function name
        Object.defineProperty(decorator(acc), "name", { 
            value: target.name
        })
    , target);
}

// Decorator
function logged(task) {
    return function(...args) {
        logger("starting " + task.name);
        let result;
        try {
            result = task(...args);
        } finally { // Also execute in case of error
            logger("ending " + task.name);
        }
        return result;
    };
}

// Your function -- unaware of logger
function doSomething(arg) {
  console.log("Middle of doing something with argument " + arg);
  return arg.toUpperCase();
}

// Decorating with two (same) decorators...
doSomething = decorate(doSomething, logged, logged);

// Run...
let result = doSomething("test");
console.log(result);

Answer 2

Decorator handling both synchronous and asynchronous functions

You can create a decorator function that handles both synchronous and asynchronous functions.

In the snippet below, logger is a decorator function that takes in a function as it's argument and returns a decorated function that handles the logging.

If the input function returns a Promise, it's handled using Promise.prototype.finally.

const logger =
  (func) =>
  (...args) => {
    console.log(`Started: ${func.name}`);
    try {
      const ret = func(...args);
      if (ret instanceof Promise) {
        return ret.finally(() => console.log(`Ended: ${func.name}`));
      }
      console.log(`Ended: ${func.name}`);
      return ret;
    } catch (err) {
      console.log(`Ended: ${func.name}`);
      throw err;
    }
  };

const sleep = (timer) => new Promise((res) => setTimeout(res, timer));

const asyncAdd = logger(async function asyncAdd(a, b) {
  await sleep(1000).then();
  console.log(`Adding ${a} and ${b}`);
  return a + b;
});

const syncSubtraction = logger(function syncSubtraction(a, b) {
  console.log(`Subtracting ${b} from ${a}`);
  return a - b;
});

console.log(`Result of syncSubtraction(2, 1): ${syncSubtraction(2, 1)}`);
console.log("=========================");
asyncAdd(1, 2).then((res) => console.log(`Result of asyncAdd(1, 2): ${res}`));

.as-console-wrapper { max-height: 100% !important; top: 0; }

NOTE:

1. Using the finally method ensures that the "Ended" log is printed even if the async function being decorated fails.

2. The try...catch block ensures the same thing but for synchronous functions.

const logger =
  (func) =>
  (...args) => {
    console.log(`Started: ${func.name}`);
    try {
      const ret = func(...args);
      if (ret instanceof Promise) {
        return ret.finally(() => console.log(`Ended: ${func.name}`));
      }
      console.log(`Ended: ${func.name}`);
      return ret;
    } catch (err) {
      console.log(`Ended: ${func.name}`);
      throw err;
    }
  };


const syncFail = logger(function syncFail() {
  console.log("Inside syncFail");
  throw new Error("Error in syncFail");
});

const sleep = (timer) => new Promise((res) => setTimeout(res, timer));

const asyncFail = logger(async function asyncFail() {
  await sleep(1000);
  console.log("Inside asyncFail");
  throw new Error("Error in asyncFail");
});

try {
  syncFail();
} catch (err) {
  console.log(err.message);
}
console.log("==========================");
asyncFail().catch((err) => console.log(err.message));

.as-console-wrapper { max-height: 100% !important; top: 0; }

Handling error cases differently:

If you want to handle the error scenario differently than the success one, for example by printing an error log instead of the end log, then refer to the snippet below:

const logger =
  (func) =>
  (...args) => {
    console.log(`Started: ${func.name}`);
    try {
      const ret = func(...args);
      if (ret instanceof Promise) {
        return ret
          .then((res) => {
            console.log(`Ended: ${func.name}`);
            return res;
          })
          .catch((err) => {
            console.log(`Errored: ${func.name}`);
            throw err;
          });
      }
      console.log(`Ended: ${func.name}`);
      return ret;
    } catch (err) {
      console.log(`Errored: ${func.name}`);
      throw err;
    }
  };

const syncFail = logger(function syncFail() {
  console.log("Inside syncFail");
  throw new Error("Error in syncFail");
});

const sleep = (timer) => new Promise((res) => setTimeout(res, timer));

const asyncFail = logger(async function asyncFail() {
  await sleep(1000);
  console.log("Inside asyncFail");
  throw new Error("Error in asyncFail");
});

try {
  syncFail();
} catch (err) {
  console.log(err.message);
}
console.log("==========================");
asyncFail().catch((err) => console.log(err.message));

.as-console-wrapper { max-height: 100% !important; top: 0; }

There's no change in the behavior of the success scenarios:

const logger =
  (func) =>
  (...args) => {
    console.log(`Started: ${func.name}`);
    try {
      const ret = func(...args);
      if (ret instanceof Promise) {
        return ret
          .then((res) => {
            console.log(`Ended: ${func.name}`);
            return res;
          })
          .catch((err) => {
            console.log(`Errored: ${func.name}`);
            throw err;
          });
      }
      console.log(`Ended: ${func.name}`);
      return ret;
    } catch (err) {
      console.log(`Errored: ${func.name}`);
      throw err;
    }
  };

const sleep = (timer) => new Promise((res) => setTimeout(res, timer));

const asyncAdd = logger(async function asyncAdd(a, b) {
  await sleep(1000).then();
  console.log(`Adding ${a} and ${b}`);
  return a + b;
});

const syncSubtraction = logger(function syncSubtraction(a, b) {
  console.log(`Subtracting ${b} from ${a}`);
  return a - b;
});

console.log(`Result of syncSubtraction(2, 1): ${syncSubtraction(2, 1)}`);
console.log("=========================");
asyncAdd(1, 2).then((res) => console.log(`Result of asyncAdd(1, 2): ${res}`));

.as-console-wrapper { max-height: 100% !important; top: 0; }

Answer 3

I'll just complement @trincot's solution with the asynchronous code handling.

It can wait until the async task will be finished and the wrapped function doesn't know anything about the decorator

const logStarting = (taskName) => console.log("starting " + taskName);

const logFinishing = (taskName) => console.log('ending ' + taskName);

const logFailed = (taskName, e) => console.error('The task: ' + taskName + ' has failed with an error: ', e);

function logged(task) {
  const taskName = task.name;
  if (task.constructor.name === 'AsyncFunction') {
    return async function(...args) {
      logStarting(taskName);
      try {
        const result = await task(...args);
        logFinishing(taskName);
        return result;
      } catch(e) {
        logFailed(taskName, e);
        thrhow e;
      }
    }
  }
  
  return function(...args) {
    logStarting(taskName);
    try {
      const result = task(...args);
      logFinishing(taskName);
      return result;
    } catch(e) {
       logFailed(taskName, e);
       thrhow e;
    }
  };
}

Answer 4

Ok so after learning about garbage collectors in C# I stumbled upon something that instantly reminded me of this problem. This appears to be the solution:

const registerFinalizer = new FinalizationRegistry(message => {
  console.log(message)
});

function logger() {
  console.log("started function")
  registerFinalizer.register(logger.caller, "finished running")
}

function doSomething() {
  logger()
  console.log("doing stuff")
}


doSomething()

setInterval(function() {

}, 1000)

FinalizationRegistry basically observes the function and calls the callback once the garbage collector removes the object, which in this case happens some time after the function finished execution.

It was probably the interviewer's way to check my knowledge of the garbage collector, it just doesn't seem like a popular subject in JavaScript, I would never have found this solution if not looking at another language.

Also, apparently it has nothing to do really with logging, and this is probably a bad way to log, it logs that the function doSomething has finished running in a big delay since it waits for garbage collector to do his thing, that's why we need the setInterval in the end(or any other thing to keep the process running).