Refactor how the logs work

[jmdobry]

This is what I'm thinking:

• - Add a new tail option to the start command.
  • If tail is true:
    • - The start command should not unref() the child, but should wait for the child to die.
    • - The Emulator's logs should pipe to the parent terminals stdio.
    • - The Emulator's logs should also continue to be written to the log file.
    • - Winston should use two transports: Console and File.
    • - If the user presses Ctrl+C the Emulator will be killed.
  • If tail is false:
    • - The start command will unref() the child and exit.
    • - The Emulator's logs should not pipe to the parent terminals stdio.
    • - The Emulator's logs should also continue to be written to the log file.
    • - Winston should use one transport: File.
• Refactor how the logs work:
  • - Instead of overriding the console methods with winston methods, move logging into its own module that can be imported where its needed and components can call logger.log() instead of console.log(), etc.

[codecov-io]

Codecov Report

Merging #89 into master will decrease coverage by 12.35%.
The diff coverage is 44.71%.

@@             Coverage Diff             @@
##           master      #89       +/-   ##
===========================================
- Coverage   76.49%   64.13%   -12.36%     
===========================================
  Files          52       52               
  Lines        2097     2130       +33     
===========================================
- Hits         1604     1366      -238     
- Misses        493      764      +271

Impacted Files	Coverage Δ
src/cli/commands/config/index.js	100% <ø> (ø)	⬆️
src/options.js	100% <ø> (ø)	⬆️
src/service/service.js	100% <100%> (ø)	⬆️
src/supervisor/supervisor.js	35.03% <28%> (-36.51%)	⬇️
src/service/grpc-service.js	32.43% <36.36%> (+0.92%)	⬆️
src/cli/commands/start.js	64.86% <37.5%> (-8.47%)	⬇️
src/model/functions.js	17.6% <5.55%> (-44.25%)	⬇️
src/service/rest-service.js	54.54% <50%> (-35.26%)	⬇️
src/cli/controller.js	71.07% <63.88%> (-2.9%)	⬇️
src/emulator/emulator.js	88.46% <66.66%> (+0.46%)	⬆️
... and 8 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 2bee7d2...f925818. Read the comment docs.

[laurenzlong]

Hey Jason, most of this sounds good! I'd have to ensure that if we're no longer overriding console with winston methods, console.log from the functions code will continue to be displayed in the terminal.

As well, I noticed that emulator code has a lot of console.logs in it right now. Are these meant for debugging, or are these things that you'd like to display to the user? Ideally I would like a differentiation between console.logs from the user's functions code, and console.logs from the emulator. So that the Firebase CLI only pipes the console.logs from the user's functions code, but not from the emulator. I'm not sure how to do this other than to either elevate the severity of the console.logs from user code to console.warn, or to downgrade the console.logs from the emulator to console.debug. Do you have any thoughts on this?

I also want to confirm that it is your intention to not display the error messages in the terminal when tail is set to false.

[jmdobry]

All stdout and stderr from a function should always be captured and sent to the log file and in the case of tail: true, to the terminal as well.

The console.log() calls that you're seeing are the Emulator matching what production does, e.g. Function execution started., Execution took 16ms, etc. Those should also always be captured as well.

Emulator debugging logs (console.debug()) are only logged if verbose is set to true. One would normally only set verbose to true if debugging the Emulator itself.

[laurenzlong]

Sounds good. I agree with your rationale that the emulator should provide the same logs as production. I am also seeing cases such as https://github.com/GoogleCloudPlatform/cloud-functions-emulator/blob/master/src/cli/controller.js#L173, where the messages do not show up in production. Having them be written to stdout is cluttering up the terminal. Perhaps these should be changed to logger.debug instead?

Should error logs be sent to the terminal if tail is set to false?

[jmdobry]

Actually, some of the logs should conditionally change their log level based on the value of the tail option. For example, if tail is false then you're using the functions CLI and you do want to see some of those logs (to match what gcloud beta functions prints to the terminal).

Should error logs be sent to the terminal if tail is set to false?

No, because if tail is false, then the terminal has released the child process and the parent process may very well have already exited.

[laurenzlong]

I've added more commits:

• Put logging into its own file (utils/logger). So another file can use it by requiring it, and then calling logger.info(), or logger.debug(), etc.
• Do not unref child process if tailing is true, and listen to ctrl+C to terminate parent and child processes.

Let me know what you think so far. As for your comment about conditionally changing log levels, what do you think about making use of more granular levels for logging? Winston supports all 6 of the npm logging levels. My suggestion would be:

• logger.error: use for error messages
• logger.info: use for messages that show up in production Stackdriver logs (e.g. Function execution started)
• logger.verbose: use for messages that show up in gcloud (e.g. 'Waiting for operation to finish...')
• logger.debug: use for messages for debugging the emulator itself

The Firebase CLI would use info level logs, and this CLI would can default to verbose level logs.

This would also mean adding one more config option (debug), so log level would be verbose if verbose=true, and debug if debug=true.