repaired the ability of nano to be able to output DEBUG messages

[glynnbird]

I noticed that when I ran my application with

DEBUG="*" node myapp.js

I wasn't seeing any debug output from Nano. I had a look at the code and there seemed to be some confusion about when Nano uses the debug package and where in the code a custom log function can be provided.

I have refactored the logger.js code so that it represents the default debug package function. The code that optionally switches in a custom, user-supplied log function was already handled in nano.js but there seemed to be some of this code leftover in logger.js, which caused no debug messages to ever work (unless you provided your own function).

With this PR, the debug messages now work with

• DEBUG="*" node mycode.js
• or export DEBUG=nano

I've also added a paragraph in README.md to explain this to users.

[glynnbird]

The code that allows a user defined function to be supplied is here:

• https://github.com/dscape/nano/blob/master/lib/nano.js#L45

This remains in place. The problem was that this code was also repeated in logger.js. If no overriding log function was provided, then no logging actually happened!

The modified test reflects the behaviour that logger module should return a function. Sorry if this wasn't clear in the PR.

[jhs]

Hi, @dscape.

I think the key point here, with which we can all agree, is that this API is not specified concretely nor tested against. AFAICT, the test suite does not test logging at all. (Yes, it hooks the debug package into the logging, but it does not actually test or confirm things.)

So, I propose we create a new PR which tests the logger API (in effect defining it concretely), and then after that, we can continue this conversation?

[jo]

:+1:

[jhs]

I think the confusion is this: if you look at logger.js, it exports a function which returns a function which returns a function. (That is not an composition error. A function returns a function which returns a third function.)

In other words, by looking at this code, one would expect to see it used like so:

var loggingSystem = require("./logger.js");

function actuallyLog(eventId, args) {
  console.log(eventId + " " + JSON.stringify(args)); // Simple example.
}

var logConfig = {"log": actuallyLog};
var loggerFactory = loggingSystem(logConfig);

// Suppose we have two concerns ("prefixes"): a generic logger plus one about, uh, bats.
var genLogger = loggerFactory();
var batLogger = loggerFactory("bats");

genLogger("Begin!");
genLogger("Something happened", {count:3});

batLogger("Strike!", {type:"aluminum"});
batLogger("Home run!", {type:"wood"});
batLogger("Found a mosquito", [0.3, 0.2, 0.1], {method:"echolocation"});

genLogger("Finished");

Output:

13qqx5 ["Begin!"]
13qqx5 ["Something happened",{"count":3}]
bats-8w2wes ["Strike!",{"type":"aluminum"}]
bats-8w2wes ["Home run!",{"type":"wood"}]
bats-8w2wes ["Found a mosquito",[0.3,0.2,0.1],{"method":"echolocation"}]
13qqx5 ["Finished"]

In other words, we would expect three function calls deep, through the metafunctions, to actually log events.

If you look at the code in nano.js: https://github.com/dscape/nano/blob/v6.1.4/lib/nano.js#L45

var log = typeof cfg.log === 'function' ? cfg.log : logger(cfg);

Here I am confused. The logging module will check cfg.log and react accordingly: https://github.com/dscape/nano/blob/v6.1.4/lib/logger.js#L18-L19

var log = cfg && cfg.log;
var logStrategy = typeof log === 'function' ? log : debug;

But the code in nano.js seems to guarantee that logger() will never be called with a .log value. In other words, there seems to be no way I can pass my logging function into logger.js, because nano.js will short-circuit that process.

My next confusion is, that the function log() in nano.js, is called with bits of information worth logging: the request (line 179), or errors (lines 191, 209, and 213). But, I would expect log(foo) not to actually log something, but rather to return a logger function. In other words, "log" from nano.js:45 references "logEvent" from logger.js:28.

If that is the case, then if somebody provides their own cfg.log function, fine, they can do what they want. However if they wish to rely on the default Debug package behavior, there is actually no way to do that. In other words, env DEBUG="nano/logger" nano.js would never actually output any messages.

Perhaps I have totally overthought myself into misunderstanding. It wouldn't be the first time. But if not, maybe you can agree that perhaps it is time that we nail down the logging API. If anybody has any feedback at all, then I would be grateful and I will happily write up some unit tests to codify that. Thank you very much!

[carlosduclos]

Hi, The NanoJS repository has been merged into apache/couchdb-nano. Could you close this pull request and open it there instead? Thanks in advance