Logging: When 'n' What

Logging can be surprisingly simple, as simple as calling globally available utility (console.log, puts, fmt.Println, echo) but deciding how much to log, how verbose log messages should be can be tricky, Usually it’s a balance of logging as little as possible and as much as necessary.

INFO for business, DEBUG for engineers #

Info and debug here refer to logging levels. Sometimes you need to audit what exactly happened even if your program works correctly. Produces no errors. Although there are dedicated techniques and patterns which can be utilized for proper auditing mechanism logs are often the naive solution. Easy to implement and easy to consume. For this purpose use clear language in your log messages, avoid engineering jargon. This will likely be read by people who might not necessarily have an engineering background.

When in fact program produces an error every single detail can be important in discovering true cause of the issue. Especially if you’re faced with race condition type of bugs. You might as well want also some metadata about the environment program was executing in. These logs are meant to help an engineer fix the bug and thus it is preferable for log messages to be verbose and to include engineering jargon. Contrary for info level logs, it is preferable to have much more debug level statements.

Formatting log messages #

In its basic form log records are simple strings written to a file on disk separated usually with a new line. When in doubt how to construct a log message it can be very useful to separate the message itself from parameters. As per UNIX philosophy rule, Expect the output of every program to become the input to another, as yet unknown, program. Don't clutter output with extraneous information., if you structure log messages in a certain way it can be easier for others to parse.

// Combined message and parameters
Logger.log(`Attempt #${attempt}: Successfully updated email for user with ID: ${user.id} and username ${user.username} from ${old_email} to ${user.email}. Operation lasted ${duration}ms`)

// Separate log message and parameters
Logger.log(`Successfully updated user email. [user_id: ${user.id}, username: ${user.username}, old_email: ${old_email}, new_email: ${user.email}, duration_ms: ${duration}, attempt: ${attempt}]`)

Fingers crossed #

This technique allows you to get the best of both worlds. The idea is to log everything but to be selective what exactly will be written to disk. It relies on log levels to achieve this.

In the context of a web request you log everything. When a request is done and before you write logs to disk you check if you have any ERROR level logs. If so you write everything to disk but if not you filter out DEBUG level log for example and only write INFO level log records.