scality / werelogs Goto Github PK

It looks like master for DBD is ignoring the environment variable METADATA_CONFIG_FILE.

This is a problem as vault is loading DBD.

The default configuration provided within DBD is incorrect.

Vault startup fails with :

> [email protected] start /home/ironman/IronMan-Vault
> node vaultd.js

/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/LogLevel.js:22
        throw new RangeError(`Invalid logging level: ${ level } is neither` + ` ${ logLevels.join(', ') }.`);
        ^

RangeError: Invalid logging level: undefined is neither trace, debug, info, warn, error, fatal.
    at Object.throwIfInvalid (/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/LogLevel.js:22:15)
    at new Logger (/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/Logger.js:55:22)
    at createLogger (/home/ironman/IronMan-Vault/node_modules/IronMan-MetaData/lib/server/Logging.js:5:12)
    at new DBD (/home/ironman/IronMan-Vault/node_modules/IronMan-MetaData/lib/server/DBD.js:28:25)
    at new Vault (/home/ironman/IronMan-Vault/lib/Vault.js:284:23)
    at Object.<anonymous> (/home/ironman/IronMan-Vault/vaultd.js:4:15)
    at Module._compile (module.js:435:26)
    at Object.Module._extensions..js (module.js:442:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:311:12)

How to reproduce :

1. be patient
2. Put 10 hours of data
3. Hope

<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0xb4870337399
1: log [/home/ironman/IronMan-MetaData/node_modules/werelogs/target/lib/RequestLogger.js:~151] [pc=0x1e9a7f024d0e](this=0x2eca71642131 <a RequestLogger with map 0x1d9ba9f31759>,level=0xb48703a4ec1 <String[5]: debug>,msg=0xdf6be6e7cd1 <String[24]: Request: new RaftRequest)
2: debug [/home/ironman/IronMan-MetaData/node_modules/werelogs/target/lib/RequestLogger.js:~115] [pc=0x1e9a7efabc26...

This would help a bit, especially with some explanations about the context you would want for each level.

Log verbosity is currently controlled by a static configuration file.

There is a need to be able to change to change the log verbosity without having to restart the daemon.

Having to restart mission critical service to investigate a problem is a major operational pain. When this is happening, we are already in a position where our negocation power with the customer is limited.

Here's my current usage. I have am using module logger as

logger.info(`Serving web content at ${addr.address}${addr.port} - PID: ${process.pid}`);

[2016-02-02T20:28:14.971Z]  INFO: S3/65420 on Rahuls-MacBook-Pro.local: undefined 'Serving web content at ::8000 - PID: 65420'

It will remove undefined if I log as

logger.info(`Serving web content at ${addr.address}${addr.port} - PID: ${process.pid}`, {});

[2016-02-02T20:33:28.814Z]  INFO: S3/65553 on Rahuls-MacBook-Pro.local: Serving web content at ::8000 - PID: 65553

Currently, if an user wants to instanciate multiple ModuleLoggers; or instanciate RequestLoggers from different files, he has to reproduce the configuration code for werelogs wherever he wishes to use it, instead of configuring it once and for all, and then only reuse the logging system as-is.

We need to improve this, for usability and future readability.

Currently, werelogs will dump all the history of one request when reaching the dump threshold level with a log entry. Then, if when unxinding the code, new log entries are entered, with a higher level than the dump threshold, each of them will trigger a full history dump again.

Some kind of flag should empty out the history of the request logger when the dump threshold is reached, and also prevent further log entries over the dump threshold from dumping again.

Since the Logger class is exported neither as a default nor as in an object, it can't be picked up by an ES6 import matching the ES6 implementation (i.e. not Babel, which is more permissive) nor a typescript module.

This can be fixed easily, but will require an update of some packages depending on it (either the ES5 modules (changing the export to module.exports.default = Logger; or everything (using module.exports = { Logger };)).

Edit: the first solution doesn't play too nice with Babel, sadly.

Since timestamp generation was a concern (e.g. new Date() vs Date.now() optimization), we could generate timestamp when a new request logger is created and record the process.hrtime(). We could use the hrtime calculate the milliseconds diff for the log entry and add it to the timestamp. This way we don't have to call Date.now() on every log entry.

For example, on a new request logger

// inside request logger
const reqTimestamp = Date.now();
const start = process.hrtime();

...

// inside doLog function
const elapsedMs = Math.floor(process.hrtime(start)[1] / 1000000); // convert nano to milli
const logTimestamp = reqTime + elapsedMs;

Actually, we compute the time field only for the RequestLogger, should we compute also for the Logger itself, in order to have proper log timeline ? :)

Typical configuration for logging is

{
   "logLevel": "info",
   "dumpLevel": "error"
}

This would make INFO level log print twice.

Proposed solution:

When dumping logs print until (logLevel - 1) level i.e. in this example, all log entries with levels ERROR, TRACE, DEBUG will be printed when dumping the logs and not INFO.

Metadata has a configuration file.
It now currently read as follows :

{
    "address": "127.0.0.1",
    "dbPath": "/tmp/databases",
    "port": 9000,
    "map" : [
        "deployment_metadata_1:9042",
        "deployment_metadata_2:9042",
        "deployment_metadata_3:9042",
        "deployment_metadata_4:9042",
        "deployment_metadata_5:9042"
    ],
    "repdPorts": [9043, 9199],
    "log": {
        "host": "127.0.0.1",
        "port": 5505,
        "level": "info",
        "dump": "error"
    }
}

The only two fields that should be specified are : address and map.

Currently the complete set of fields should be specified (log, repdPorts, port, dbPath). Otherwise the software fails to start.

Here is the error message generated when the log is missing in the configuration :

/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/LogLevel.js:22
        throw new RangeError(`Invalid logging level: ${ level } is neither` + ` ${ logLevels.join(', ') }.`);
        ^

RangeError: Invalid logging level: undefined is neither trace, debug, info, warn, error, fatal.
    at Object.throwIfInvalid (/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/LogLevel.js:22:15)
    at new Logger (/home/ironman/IronMan-Vault/node_modules/werelogs/target/lib/Logger.js:55:22)
    at createLogger (/home/ironman/IronMan-Vault/node_modules/IronMan-MetaData/lib/server/Logging.js:5:12)
    at new DBD (/home/ironman/IronMan-Vault/node_modules/IronMan-MetaData/lib/server/DBD.js:28:25)
    at new Vault (/home/ironman/IronMan-Vault/lib/Vault.js:284:23)
    at Object.<anonymous> (/home/ironman/IronMan-Vault/vaultd.js:4:15)
    at Module._compile (module.js:435:26)
    at Object.Module._extensions..js (module.js:442:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:311:12)

Would it be possible to get a somewhat clearer message ? (e.g. from the above it is not obvious why the software fails to run and it is only wrong configuration). A clear error message in the logs is expected from any reason that causes a failure in parsing the configuration.

In addition, all the fields except address and map would benefit from sensible default. If the log is not present in the configuration, would it be possible to use sensible default values ?

Finally in the future for backwards compatibility of the configuration could fields added to the configuration have a sensible default value that would allow the software to run even if these new fields are missing in the configuration ?

For most services, one might want to log the elapsed time of an operation when finishing it.
In order to provide this in an easy-to-use fashion, I've been thinking of a new logging method, 'end', that would use a configured logging level for the ending log entries; and that would use the internal hrtime to compute the elapsed time that it could automatically add to the added field data.
ie:

    const log = new Werelogs('service', { end: 'info' });
    ...
    var logger = log.newRequestLogger();
    ...
    log.end('message', {field: 0});

doLogIO currently takes a log level and a log entry. That being said, the log level should be part of the entry, making the first parameter useless.
This should be reworked and cleaned-up as soon as possible.

As described by @rachedbenmustapha in the PR #1 , We need to design some kind of fallback behavior for whenever enough errors occur simultaneously (but slowly) to fill the memory with log entries.

We need to make sure that the log system won't become a worsening factor, and that it won't hog all the memory for itself due to bad design decisions.

The first (and current) version shall be simple, but we need to think about a solution for the long-term.

The logging methods only expect one argument in the current version. This means that any extra argument is lost in the logging process, while it should at least be kept within an object.

We should fix this, so that no logging data is lost due to mis-use of the logging interface.

JSON.stringify throws Uncaught TypeError: Converting circular structure to JSON, Werelogs should be safeguarded against it.

I can't instantiate the logger because node is not happy with the current ES5 way to requiring things. Basically it should be

require('./es6-compat.js');

module.exports = require('./lib/Logger.js');

• Suppress CPU intensive calls
• Externalize log rotation and communication to ELK

I open this to discuss about logging the fatal errors to stderr too, that way we can still have in stdout the log, but we also have it in stderr, for the log beeing more visible

This is the output on CI

/home/ubuntu/werelogs/index.js
  0:0  error  Cannot find module 'babel-eslint'

I am not sure how this worked as we don't see babel-eslint in package.json but it's mentioned as
parser in eslintrc.

it would be nice to have the ip of the client (of the remote S3 client, of the remote vault client, of the remote bucketd client, of the remote repd client) in the log.

JSDoc comments concerning function parameters should be written as:
@params {Type} varname comment

Currently, a big part of the code has been written inverting the order of the var's name and its type. This should be fixed.

In order to provide complete coverage of logging use case, we cannot exclude logging outside of a request.
For instance, a starting daemon may want to notify it started listening on a port, but that can't be done within a request.

As such, we should provide a default Module Logger that would allow logging directly through the logger by default.

When a user logs something with additional data, using an internal data field has the bad behavior to overwrite a reserved internal key.
for instance:

reqLogger.info('text message', { name: 'pouet' });

here, the reserved internal field "name" will be overwritten.

We need to make sure this cannot happen in a default setting.

Such a behavior must be thought about for the default fields too.

It would be very useful on production system to be able to change log level to debug when receiving a SIGUSR1 signal and reverting to the configured log level when receiving that signal again.
Maybe SIGUSR2 to go intro trace mode as well.

This way we could dynamically switch between different log levels on a process without restarting it.