Logging

[ismay]

I'm wondering if there is a recommended approach to logging to the console from our apps. I've seen regular, unconditional, console.log() statements being used for errors and the like. And I think I've seen a couple of other approaches as well.

Personally I don't like the logging during tests that much as I find it a bit noisy. In general I think I would prefer it if the logging was toggle-able. So:

1. I was wondering if there is already an agreed upon way to handle logging in our apps.
2. With regards to making logging toggleable, something like https://www.npmjs.com/package/debug has always worked well for me. It'll allow us to toggle logging for any module that implements it, not just the one you're working on currently, with environment vars.

I'm wondering what everyone thinks of this / prefers, etc.

[ismay]

To elaborate a bit on how I'd see point 2 working:

• By default, console logging would be completely disabled (CLI apps need to log at least some information of course).
• Let's say you're debugging a front-end application, and you want to turn on logging for the module that you suspect is causing the problem, in the console you'd set:

// If you expect d2's causing the problem you're debugging, set this and refresh
localStorage.debug = 'd2:*'

// See also: https://www.npmjs.com/package/debug#browser-support

Or, if you're debugging something server-side, you'd set an env variable to trigger the logging:

DEBUG=module-to-debug node script.js

[Mohammer5]

So far I have good experience with (dis-/)enabling logging per module, which is like your second bullet point. It's just hard to say what should be logged and what shouldn't.

It could be very detailed, it could be redux stuff only, etc.

[ismay]

It's just hard to say what should be logged and what shouldn't. It could be very detailed, it could be redux stuff only, etc.

If we'd use debug, you can specify that you want to log all debug messages for a module, or use colon to specify the exact bit you're interested in d2:only-this-specific-bit. So there's a bit of control over what you'll log.

And as to where you'd place calls to debug, it's more of a judgement call I guess. I can imagine that after a while we'd get a feel for what's useful to log when debugging and what's not.

[HendrikThePendric]

Since this is a topic I don't know much about, I'm going to start with some questions before I start a discussion based on the wrong assumptions:

1. To me it seems that the main feature that the debug package offers is automatic prefixes to console log messages. Is this correct, or am I missing something else?
2. And assuming 1 is correct, then is the advantage of having these prefixes then to filter stuff in the Browser's DevTools console?

Some general opinions I do have about logging:

• I don't think console.log message should ever show up during tests and in production, because they should be removed from the code-base. It should be pretty easy to guarantee this via the UglifyJsPlugin settings, and ESlint warnings.
• On the other hand, conditional console.error messages are perfectly valid in production as they could help us get to the bottom of bugs via user-reports. I can imagine we don't want to see them in CI environments though.
• I like being able to console.log stuff when building test as well, so in development. As I said before, I can imagine we don't want to see them in a CI environment.
• I am wary of introducing any type of solution that "reduces clutter on the console" or "enables name-spaced filtering" of console messages (in development). Because ultimately, this will lead to a lot of logging messages creeping into the code base.
• In general, I have very bad experiences with using a text filter on console messages in Chrome DevTools. Once you apply the filter, all types of messages that don't match are suppressed. I haven't been able to find a way to filter console.log messages, but allow all errors. And this can lead to pretty confusing situations where you don't see errors showing up initially.

[Mohammer5]

To me it seems that the main feature that the debug package offers is automatic prefixes to console log messages. Is this correct, or am I missing something else?

debug also doesn't print anything unless the DEBUG env variable contains the prefix name, so in the end, you'll have control over what you're logging. This could go so far, that you have an app, for which you could add debug statements with

const debugApp = debug('app:core')

You could then add debugs for specific pages, like:

const debugLoginPage = debug('app:login')

If you want to debug everything, you'd set the DEBUG variable to * or app:*. If you want to debug the core and the login page, you'd set DEBUG to app:core,app:login.

Of course this wouldn't be set during production, testing, deployment, etc, so the output there wouldn't contain our debug messages.

Plus, when using this in our libs, we could add the lib to the debug env var, to see the debug logs for the lib as well

[ismay]

So @HendrikThePendric, to elaborate a bit on @Mohammer5's answer. With debug our apps won't log at all, unless you tell them to. That goes for all environments.

Benefit is that you can still enable logging in production easily if you need it. You just set localStorage.debug and specify the libraries that should start logging.

And in development, you'd probably just turn on all logging for the library you're working on in your npm scripts, by prefixing it "start": "DEBUG=current-app:* react-scripts start"

[HendrikThePendric]

Thanks for explaining @ismay and @Mohammer5. I quite like this now. And if we can add some ESLint/pre-commit rule that stimulates developers to remove their log-lines from the code-base, then I'd be all for it.

[varl]

Some notes:

1. For CLI we have an implementation which does reporting in a consistent way for all cli-* tools: https://github.com/dhis2/cli-helpers-engine/blob/master/lib/reporter.js, something similar for libs/apps with a simplified api could be nice.

2. For NodeJS apps (e.g. app store backend) we should use the same as we do for the browser. Looks like debug does this nicely.

3. Usually I just use the console implementation and strip unwanted log statements in production builds:

Console
assert: function assert()
clear: function clear()
count: function count()
countReset: function countReset()
debug: function debug()
dir: function dir()
dirxml: function dirxml()
error: function error()
exception: function exception()
group: function group()
groupCollapsed: function groupCollapsed()
groupEnd: function groupEnd()
info: function info()
log: function log()
profile: function profile()
profileEnd: function profileEnd()
table: function table()
time: function time()
timeEnd: function timeEnd()
timeLog: function timeLog()
timeStamp: function timeStamp()
trace: function trace()
warn: function warn()

I usually don't debug in production builds more than to verify that I can reproduce the issue, and figure out from what commit the build is from, so that's not a feature at the top of my priorities.

[Mohammer5]

I'd like to continue this discussion:

After having used our debug tool for the cli, I really would like to change our logging to the debug module. It's working really nice, we'd have a finer control over what we want to log and it works both on cli and the browser out of the box.

So I'd like to propose a way to use it:

1. Every app/lib/service gets its own namespace

This would mean that

• ui-core has a ui-core namespace
• in the app-runtime the data service would have it's own namespace (not app-runtime:data-provider but just data-provider)
• maintenance-app would have it's own namespace

2. The second-level namespace is already specific

• These namespace should be for very specific groups (or even on a file level)
• This could be as abstract as app:redux and as detailed as lib:fetchUrl

3. The third-level namespace is the final one and separates the already specific, second-level one in concrete actions

• This could be lib:fetchUrl:success, lib:fetchUrl:error, lib:fetchUrl:info
• It could as well be app:redux:dispatch, app:redux:state-change

---

Of course we could create deeper namespaces but in my experience, it'll be very hard to read output then if you want to log several things at one AND one tends to use too deep namespaces, which will most likely trigger some kind of logger-call refactoring every now and then, which should be avoided as much as possible in my opinion

[Mohammer5]

I assume what I just said it mostly interesting to @varl and @amcgee

[varl]

I would like to see a holistic approach to the namespacing, covering all our modules, so that at least hitting the correct "main" application or library is very easy.

One of the things that would be important with debug would be to be able to turn on all our logs without whitelisting them one by one, so the top namespace would be e.g.:

dhis2:*

We generally deal with two different types of software, libraries and applications, so having a namespace for those two could also be handy:

dhis2:lib:*
dhis2:app:*

Beneath that we have library groups, e.g. the UI libraries:

dhis2:lib:ui:*
dhis2:lib:ui:core
dhis2:lib:ui:widgets
dhis2:lib:ui:forms

If we need to go further down than that is up to each library. I don't think we need to e.g. isolate out dhis2:lib:ui:core:button at this stage, but maybe some components in widgets do need that. I do think it's important to be able to turn on all UI library logging in one go, and not be forced to type: DEBUG=ui-core:*,ui-widgets:*,ui-forms:*

By design debug doesn't enable ui-core:* if you enable ui-widgets, which is annoying when you want to see e.g. the logs for components in ui-core that the HeaderBar in ui-widgets is using. Even more so when you want the providers and an app, which would mean: DEBUG=maintenance-app:*,ui-widgets:*,app-runtime:*

Being able to say, "screw it" and do: DEBUG=dhis2:* in that case would be liberating.

For our applications it would look similar:

dhis2:app:maintenance:*

An app could add additional namespaces for more granular information, but any DHIS2 developer will at least know that DEBUG=dhis2:app:maintenance:* will give them all the logs from Maintenance app and DEBUG=dhis2:* will yield logs from all relevant DHIS2 modules, apps as well as libs.

Generally while working a developer would be most interested in running dhis2:* and only start adding more granular whitelists as she wants to remove some irrelevant statements, e.g. she knows the bug is in the app: dhis2:app:*.

This would work on any application without specifying the app explicitly. In merged logs from multiple apps it is still possible to be even more fine-grained: dhis2:app:dashboards

[Mohammer5]

Generally while working a developer would be most interested in running dhis2: and only start adding more granular whitelists as she wants to remove some irrelevant statements, e.g. she knows the bug is in the app: dhis2:app:.

I have not seen this approach yet though

From my experience, wildcards that cover a lot of debug namespaces (like dhis2:* or dhis2:lib:*) are rarely used as they normally print so much in the console, that you lose the overview of what's going an.

Whenever I tried the approach with using the higher-level namespaces, I got lost, so I start a different approach:

Using one namespace, trying to see what's going on there (either top-down (reverse-engineering) or bottom-up, starting with the smallest unit that's being used) until I realize that it's not the parts, that's bugging, then moving on the next/previous namespace that's processing the data until I eventually found the bug's origin. Then I'll enable explicitly the namespaces that are involved to get the final result and monitor their output while working on the bug.

namespaces that divide the application/libs on a granular level (like dhis2:lib:ui:*)

But I get the point that inter-lib/app debugging might be needed in our case. This seems to be a thing that intuitively every developer wants to do (myself included), I often found myself more hindered than helped by doing this, especially when ending up with a much longer output on the cli, because all the inclusion/exclusion namespaces are quite long.

The wildcards don't just work on namespace level, you can use than as a partial wildcard as well:

$ DEBUG=dhis2:lib:ui* node index.js 
  dhis2:lib:ui-core Debug core +0ms
  dhis2:lib:ui-widget Debug widgets +0ms
  dhis2:lib:ui-forms Debug forms +0ms

index.js:

const Debug = require('debug')

const debug = Debug('dhis2')
const debugApp = debug.extend('app')
const debugLib = debug.extend('lib')
const debugLibUiCore = debugLib.extend('ui-core')
const debugLibUiWidgets = debugLib.extend('ui-widget')
const debugLibUiForms = debugLib.extend('ui-forms')

debugLibUiCore('Debug core')
debugLibUiWidgets('Debug widgets')
debugLibUiForms('Debug forms')

---

I think these are fine though:

dhis2:lib:ui:*
dhis2:lib:ui:core
dhis2:lib:ui:widgets
dhis2:lib:ui:forms

I see problems with this:

dhis2:lib:app:runtime:data:....
dhis2:lib:app:runtime:config:....
dhis2:lib:cli:style:cmds:validate:info
dhis2:lib:cli:style:cmds:validate:error

I think this would totally suffice:

app-runtime:data:....
app-runtime:config:....
cli-style:cmds:validate:info
cli-style:cmds:validate:error

# this as well
ui-core:table:...
ui-widgets:headerbar:...
ui-forms:validation:...

[varl]

From my experience, wildcards that cover a lot of debug namespaces (like dhis2: or dhis2:lib:) are rarely used as they normally print so much in the console, that you lose the overview of what's going an.

As you said, it depends if the developer starts top-down or bottom-up. I jump between apps and libraries every hour of every day so my default would always be dhis2:* as I would only see relevant output for the app I am working on. If it's too much I'd scope it down from there, as I don't have it in my head which modules exist for each lib/app.

If I was jumping into ui-core I might not even know that there is a Table namespace, so I'd start with ui-core:* and see that there is a ui-core:table namespace being logged, and it is what I'm interested in, so I'd drill down, every time.

To make matters worse, I might not even know that import-export-app is using app-runtime if I didn't check the package.json, and if I just whitelist import-export-app:* then I won't see the messages from app-runtime at all.

Yes, dhis2:cli would likely be its own namespace. It is not a library but a standalone tool so it doesn't make sense to keep it under dhis2:lib:cli.

The wildcards don't just work on namespace level, you can use than as a partial wildcard as well

Ah, yes. 👍 I find having e.g. dhis2:${group} more predictable as it's general enough to be consistent for every package we have.

Ref. debug/info/warning/error messages

From some of your examples it looks like there is some sort of log level idea baked into that convention. I'm not overly fond of the way it's done in debug. I would have preferred a more common log.info, log.debug, log.warn styled approach and using a LEVEL=debug,warn variable to whitelist specific messages.

I still want the ability to whitelist all DHIS2 modules without using the * whitelist. 🤔

At the end of the day

If we add "dhis2" to your examples, I might be OK with that:

dhis2:app-runtime:data:....
dhis2:app-runtime:config:....
dhis2:cli-style:cmds:validate:info
dhis2:cli-style:cmds:validate:error

# this as well
dhis2:ui-core:table:...
dhis2:ui-widgets:headerbar:...
dhis2:ui-forms:validation:...

# for apps i think this is unclean though
dhis2:maintenance-app
dhis2:import-export-app

I still prefer having very wide scopes dhis2:app, dhis2:lib, (and maybe dhis2:cli), so a developer can set localStorage.debug = 'dhis2:*' in their browser to see all log statements from our own modules. Otherwise a developer would have to set:

localStorage.debug = 'maintenance-app:*,dashboards-app:*,etc,etc,etc'

[Mohammer5]

I still prefer having very wide scopes dhis2:app, dhis2:lib, (and maybe dhis2:cli)

I've thought a bit about this the last two hours and I think you're right here. It's easy to forget the sheer amount of apps and libs we're dealing with here (at least I haven't worked with this amount of stuff before), so this might be appropriate actually.

so a developer can set localStorage.debug = 'dhis2:*' in their browser to see all log statements from our own modules. Otherwise a developer would have to set:

Very good point, haven't thought about that.

I would have preferred a more common log.info, log.debug, log.warn styled approach and using a LEVEL=debug,warn variable to whitelist specific messages.

Yes I'd like to have different debug levels as well.. also I'd prefer if one debug function could have a group of namespaces (disabling or higher specificity would have priority, so you could still do dhis2:*,-dhis2:lib). But one can't have everything.. We could write our own wrapper for that though which is somewhere in our cli libs? (do we have a lib that's used by both FE and cli?)

---

Ok, so let's break it down:

1. The main namespace for all apps/libs will be dhis2
2. The second namespace will be app, lib or cli
3. The third namespace will be the name (maintenance, import-export, ui-core, etc.) (I think we can omit the trailling -app?)
4. The fourth is the namespace for what's being debugged
5. The fifth is optional and can be describing an internal process of what's being debugged

[varl]

(I think we can omit the trailling -app?)

Agreed.

[ismay]

Sounds good to me 👍

[varl]

If interested, take a look at the proposed debug implementation in https://github.com/dhis2/import-export-app/pull/61.

[Mohammer5]

I think @varl has a fair point about code getting cluttered with debug statements, if we're trying to have a sophisticated approach.

So maybe a step back here:

• Let's not put debug statements in our apps
• We could still do it for libraries, because these are harder to debug in app context The component libs will most likely also need fewer debug statements as they contain little to no business logic (data provider might be different here, but I think that's a data provider specific issue then)

I've talked about this with @ismay a bit more in depth on slack yesterday, and we arrived at a conclusion that I have been a bit mistaken about the purpose of debug: I wanted to use it for logging as well while the purpose is debugging only

debug offers a way to override the logging function: https://github.com/visionmedia/debug#output-streams

With this, we'll have the different log levels at hand:

import Debug from 'debug'

const createDebug = () => Debug('dhis2')

const debug = createDebug()
debug.log = console.log.bind(console)

const logInfo = createDebug()
info.log = console.info.bind(console)

const logWarning = createDebug()
info.log = console.warn.bind(console)

const logError = createDebug()
info.log = console.error.bind(console)

export { debug, logInfo, logWarning, logError }

Maybe we can utilize this somehow?

Edit: Maybe printLog, printInfo, printWarning and printError to have a consistent naming (logLog would've been aweful)

[ismay]

So the main downsides that we've encountered seem to be:

• The lack of logging levels. Which would allow you to filter by severity (besides the filtering by domain that debug already allows)
• Visual clutter in code

To me the goal of implementing something like this (or similar) is:

• Ability to easily debug our code (both in dev and production)
• No console.logging by default in production
• Uniform approach to logging debug messages

Those are the main goals I can think of.

With regards to the clutter. I don't think we can avoid the extra code, but maybe there's a different approach that offers the granularity we need without as much verbosity. Maybe that'd be less cluttery?

About the logging levels, maybe there are other libs/solutions out there that would match the goals above and also include logging levels? @Mohammer5's comment above also shows a way that we could implement this with debug.

[ismay]

To elaborate a bit on my goal above Ability to easily debug our code (both in dev and production) and reply to @varl's comment in the linked issue:

I'm having a hard time seeing the net gain here. Even if I just put a stray console.log in a file, the browser developer tools tells me exactly what file and line it originated from (given that we have source maps). That beats out being able to say e.g. localStorage.debug = '*:helper:xhr:ready-state' in my book.

To me the benefit of using debug or something similar is to not log anything by default in production. I don't like opening the logs in production and having to mentally filter out a lot of info. For me it leads to me ignoring the logs more, where I'd prefer not to do that as there might be something important there.

Also, I like that setting it in localStorage allows me to enable logging for the area I'm interested in, whether it's in production or during dev, and to reload the app without losing that. Putting a console.log during development is easy. But in production I find debugging with the browser tools more cumbersome than just enabling sth like debug.

The main benefit to me is having something uniform, that works the same everywhere, and doesn't have to be stripped out, or clutters the console.

[ismay]

Maybe it's helpful to talk about the goals? I'm not sure if what I'm saying above aligns with how everyone else perceives the goals of implementing this?

Also, as an example, this lib. is more elaborate and allows levels as well: https://github.com/Download/ulog#logging-methods

[varl]

ulog looks like what I would expect to see from a logger library.

---

The main benefit to me is having something uniform, that works the same everywhere, and doesn't have to be stripped out, or clutters the console.

console satisfies 3/4 or 4/4 depending on the perspective, if you turn off all the logs (trace, log, debug, etc) you don't want in the developer tools they are disabled globally in the browser (across tabs). That gets a 4/4 from me.

If you want everything enabled in your browser tools and still don't want to see the messages, and would prefer to set something in localStorage to change the log levels, then it's a 3/4.

It's technically possible, even if the solution is not to your liking.

However, there are some problems with console:

• it exist on the global environment, with everything that implies: good and bad
• it should be declared as a global variable in source files so we can use certain ESLint rules
• we need to keep track of which tools does what with console statements, CRA might strip console.log in production while that's not something we want (as an example)
• readability across libraries and apps is not effective across browsers, depends on the built-in browser tools for filtering etc.
• too easy to have different log conventions in apps and libraries

[Mohammer5]

I've played a bit around with ulog just now, here's what I can say:

• It supports both namespaces and log level (which is quite nice) This is something we were missing with debug, at least in terms of out of the box functionality
• It supports multiple arguments to their logging functions (just like console.log) This is different with debug, where you'd have to use %[X], I like the ulog way more
• It does not print the namespace colored This is an advantage of debug, because it increases readability quite a bit
• It does not print the time between following logging functions if they're from the same namespace This doesn't really matter to us anyways I think

It's quite easy to create a wrapper for debug to have the log level functionality as well, but it requires a wrapper while it's quite hard to get the colored outputs of debug in ulog. To me it breaks down to:

• if we're fine with a wrapper (lib or runtime service?), I'd go for debug
• if we want to use only the out of the box functionality of those libs, I'd favor ulog

[amcgee]

ulog looks nice, albeit not the cleanest code I've seen.

I don’t generally like leaving logs in production code but assuming performance doesn’t degrade (the log functions are replaced with noops when logging a level disabled, though each module instantiates a log object) I'm not opposed to supporting it. I do think we should set the level to NONE in production by default.

I'm also not a huge fan of locking up the log and debug querystring parameters, but maybe we could rename them or

debug has nicer code but is probably a bigger bundle and doesn't appear to no-op the log functions when disabled, so there is some production overhead for each log call.

My first inclination would be to support either of these libraries but strip the code in production builds to prevent any performance issues (including bundle size bloat - we already have HUGE bundles and adding thousands of log lines all throughout the codebase plus a logging library wouldn't help that)

I'd be happy to switch to using something like this internally to cli, but I have been pretty happy with the logging options in the reporting module so far, and I don't think we need the granularity of module-specific logging (or even really more than 2 log levels) when we have the --verbose flag and are only running one command at a time. As such I don't see a huge advantage to using the same library in both places.

[Mohammer5]

I've been playing around with debug, ulog and combining them, and I think ulog is the lib to go here.

---

It will def. clutter code, but I think we can regard it as code comments which will be printed on the console at runtime as well.

They actually can even help reading through code because you know what's happening without having to read every single line of code.

What has worked best for me last weekend was:

1. ulog.info for general process steps
2. ulog.log for detailed steps (think of verbose)
3. ulog.debug for logging more than just messages, like objects, responses, etc.

[ismay]

To reply to @varl's comment above:

ulog looks like what I would expect to see from a logger library

Yes. Though I do think that in this issue we're conflating logging and debugging (poorly chosen title from me initially). To me there's a difference between the two: with logging you want all the messages and would generally expect the loglevels we've been talking about. You'd react to any warnings or error messages that pop up for example.

With debugging I'm usually already focusing on a certain area and have an idea of what I'm looking for. Any extra messages are annoying to me in that case. I just want to see the logs I'm interested in.

So I agree that it fits better with what you'd expect from a logging lib. I do hope though that we're not focusing too much on picking a logging lib though, and that that's causing us to pick a solution that's not geared towards helping with debugging (with would be what I consider the goal of this issue).

console satisfies 3/4 or 4/4 depending on the perspective

To me, the biggest thing I'd miss with vanilla console is toggling only specific areas on for logging. I like being able to just turn on the logging for a specific area and have it be persistent after a refresh etc.

ulog looks nice, albeit not the cleanest code I've seen

Yeah I think it's worth noting that I mentioned ulog because it has an api that fits with what we were talking about earlier. I wouldn't necessarily go for this exact lib, it seems to not be that popular, so I'd expect there to be better solutions if this is the direction we want to go in.

My first inclination would be to support either of these libraries but strip the code in production builds to prevent any performance issues (including bundle size bloat - we already have HUGE bundles and adding thousands of log lines all throughout the codebase plus a logging library wouldn't help that)

I would like to have something like debug's functionality in production personally. But yes, bundle size is definitely a very important consideration. I'd be interested in the actual increase in size. It might be worth it.

We seem to already be talking a bit about the solutions. Maybe we should see if we can converge on the intended goals first? I'm not sure if we're all aiming for the same thing? If I reformulate what I said earlier I think the clearest I can state what my aim was is:

• Switch on log messages per area easily (in dev and production)
• No console.logging by default in production
• Uniform approach to logging debug messages

[Mohammer5]

With debugging I'm usually already focusing on a certain area and have an idea of what I'm looking for. Any extra messages are annoying to me in that case. I just want to see the logs I'm interested in.

This is totally possible with ulog with DEBUG=dhis2:lib:ui-widget:header-bar:* LOG=0 (or the localStorage variant)

ulog will log everything from error level to debug level for the specified namespace, all other namespaces depend on the log level.

Switch on log messages per area easily (in dev and production)

I'm not sure what we can do to turn on ulog's logs in production, but I haven't looked for it either, but I'm sure there is a way if we want to?

Maybe we should see if we can converge on the intended goals first? I'm not sure if we're all aiming for the same thing? If I reformulate what I said earlier I think the clearest I can state what my aim was is:

• Switch on log messages per area easily (in dev and production)
• No console.logging by default in production
• Uniform approach to logging debug messages

I agree with the last two points, I don't agree with the first one:

1. You can spin up your dev env on master with the appropriate play/debug environment and you'll have the same log/debug messages (and a direct link to the source file as the code is not uglified)
2. For debugging actual production environment (the ones with actual people's data), we should aim for this: https://jira.dhis2.org/browse/DHIS2-3481 (storing error messages and opt-in to sending them to us, so we know what's happening in the wild)

I've talked to @varl about No 2 today and we both feel the we need to try to get this going

[varl]

I think that we can leave NodeJS (e.g. the app-store backend) and CLI out of this discussion: https://github.com/dhis2/notes/issues/46#issuecomment-491960766 (May 13th) and focus on the browser (libs/apps).

[HendrikThePendric]

I see this conversation has progressed quite a bit now, and we are considering different tools....

However, one of the concerns I voiced in my initial comment has not really been resolved: How do we prevent too many log statements from gradually being introduced into our codebases?

My main concern is that I am not convinced that anyone is ever able to distinguish between log statements that are relevant now, and ones that are going to remain relevant indefinitely?

It's quite likely that when new features are introduced they are initially a bit unstable and bugs will pop up. It may now seem justified to put some log statements in and keep them in indefinitely. However, over time, the new functionality will stabilise and hopefully no more issues will arise from that area of the codebase. At that point it may not be justified anymore to have these log statements in the codebase.... But this is going to be a gradual process, so there is no way that anyone is going to go in and remove these log statements. They'll just stay there forever....

So I guess my questions are:

• How to decide what to log (and what not to log)?
• How manage the amount of log statements in a codebase?
• How would a "cleanup" be triggered?

Or alternatively, I guess we could also collectively decide that having lots of log statements in our codebase is not a bad thing. You'd have to convince me on this first ;-)

[varl]

Additional food for thought from everyone's favorite linter:

https://eslint.org/docs/rules/no-console

In JavaScript that is designed to be executed in the browser, it’s considered a best practice to avoid using methods on console. Such messages are considered to be for debugging purposes and therefore not suitable to ship to the client. In general, calls using console should be stripped before being pushed to production.

...

If you’re using Node.js, however, console is used to output information to the user and so is not strictly used for debugging purposes. If you are developing for Node.js then you most likely do not want this rule enabled.

[Mohammer5]

How do we prevent too many log statements from gradually being introduced into our codebases?

I think this can only be done with experience, we could start with one app (I think the new maintenance is a app to start with) and see how it feels, if we have the feeling of having too many or to few info/log/debug statements)

My main concern is that I am not convinced that anyone is ever able to distinguish between log statements that are relevant now, and ones that are going to remain relevant indefinitely? [...] It's quite likely that when new features are introduced they are initially a bit unstable and bugs will pop up. It may now seem justified to put some log statements in and keep them in indefinitely.

I think we have to use the correct log leves, then this should be a lot clearer. info should only be used for information that's going to be relevant later debug should be used for debugging purposes, also during development

How to decide what to log (and what not to log)?

This is what has worked best for me:

• info for general process steps
• log for detailed steps (think of verbose)
• debug for logging more than just messages, like objects, responses, etc.

I guess the info statements could/should stay indefinitely and will most likely be removed when code changes.

How manage the amount of log statements in a codebase?

Trial and error and collaboration (PRs), there's no automated way to detect the right amount of log statements

How would a "cleanup" be triggered?

I think cleanup is a part of refactoring. We now have the possibility to work on such things before an issue is done (#55), so whenever you encounter too many log statements which are outside of the frame of your issue, you can create another small branch/PR, that addresses exactly this

Or alternatively, I guess we could also collectively decide that having lots of log statements in our codebase is not a bad thing. You'd have to convince me on this first ;-)

If we follow proper architecture patterns and we lean towards the "1 function 1 task/purpose" strategy (which I think we already do and is normal in FP), we might end up with lots of info/log/debug statements, but they're only few when you look at a file (but there'd be many files with logging).

We'd also have to follow some common logging patterns:

1. Write full sentences that explain the context ("No data" is not helpful at all)
2. Don't just repeat declarative code (like logging the function's name that's being called, it still lacks context)

I'd propose we try it out and see if it actually helps, because the experience I had last weekend was: I understand function internals (with log statements) without having to read the imperative code bits until I need to know them to that level of detail.

[ismay]

I agree with the last two points, I don't agree with the first one

Ok yeah, I see your point. Let's drop that then. So then we have:

• Switch on log messages per area easily
• No console.logging by default in production
• Uniform approach to logging debug messages

So given @HendrikThePendric's concerns, and to play advocate of the devil here, I guess an alternative could be to just remove all console.log statements from our libs and apps (not cli as I consider it more part of the UI there). Not even keeping them for dev. That seems like the minimalist solution. If you want to debug something then you just put some log statements, and your console won't be cluttered by any other messages. And then afterwards you remove it again. That would also solve these points in a way and would just require us to remove all console.logs.

And then the debug/ulog type implementation is the other side of the coin. Requires more attention and maintenance. So I guess the question then is what benefits we have with this solution over the above (unless there's another valid approach that I've missed), and whether it's worth it.

[HendrikThePendric]

I think you've summarised it nicely @ismay.

I've got to admit, after reading the excellent explanations provided by @Mohammer5, it sort of feels like going the debug/ulog route will just increase the workload. Now we'll have to start maintaining not only the functional part of the codebase, the dependencies and build pipelines, the tests, but also the log statements....

I think there is already way too much overhead in modern JavaScript projects, and we'd be introducing even more work for ourselves. This is only justifiable if there are clear benefits to be reaped. Writing tests is a good example of something like this: it adds a huge burden but the fact that refactoring is much easier, and the chance of regressions goes down justifies the amount of work....

ATM I am failing to see clear benefits of having to maintain all these comments. The benefits that I have read about all seem very limited:

1. Preventing log statements from entering production => ESLint can prevent that, and other tools are available too
2. Filtering based on namespaces => yeah this might be handy, but this is still working on the assumption that we have been able identify things to logs whilst developing that are later useful in debugging an issue
3. Switching on logging in production => See the previous point, but I also think that this is only really an advantage if we are encountering problems in production that cannot be reproduced locally. And since we can easily switch to a different remote backend, I don't think this is much of a benefit either.

Maybe there are more benefits. Please correct me if I missed important ones...

[Mohammer5]

@HendrikThePendric I think that'd be true if we were only talking about an app itself or a library itself.

To me, the two biggest advantage are:

1. I can enable to debug modules of libraries like ui-core, ui-widgets, ui-forms, possibly app-shell and app-runtime as well. If we have documented our libs' api and responses properly, this shouldn't be necessary.

2. I can watch complex processes in a linear way (let's say you'd have to debug the maintenance app, it's ridiculously difficult to know what's happening, and where).

---

We could also do this: Use ulog.info only, and disallow log and debug.

info should then mainly display the steps of the processes defined by a feature (spec) log and debug would be used for developing and should be stripped before a PR is approved

[varl]

I just had a security analysis session and this item came up on the security checklist for web applications:

Verify that web or application server and application framework debug modes are disabled in production to eliminate debug features, developer consoles, and unintended security disclosures.

To sum up, we have good reason to strip logs from the production build.

[ismay]

Verify that web or application server and application framework debug modes are disabled in production to eliminate debug features, developer consoles, and unintended security disclosures.

Do they mean sending debug messages to a third party? Because local debugging features are fine in a frontend right?

[ismay]

Just curious btw. I'm fine with stripping console statements from a production build.

[varl]

Do they mean sending debug messages to a third party? Because local debugging features are fine in a frontend right?

That must be the primary intent. A secondary would be to avoid accidental log statements that leak information that has security implications an attacker could use. It's on the OWASP AVSV checklist which is rather paranoid. "Better safe than sorry" is their job though. :shipit:

edit: Although users do tend to post screenshots of their browser console on e.g. community.dhis2.org so they could inadvertently leak info they shouldn't...

[ismay]

Although users do tend to post screenshots of their browser console on e.g. community.dhis2.org so they could inadvertently leak info they shouldn't...

Hmm yeah true. Interesting.