Add logfmt support #2047

KingNoosh · 2017-08-25T10:55:27Z

Changes proposed in this pull request:

Add support for the logfmt format (key=val)

Checklist:

docs updated
tests updated

KingNoosh · 2017-08-25T16:46:28Z

The logfmt format is also supported and can be enabled by changing
LOGFMTDEFAULT to LOGFMTLOGFMT in the config/logformat file which will
start logging in the following format below.

level=PROTOCOL connection_uuid=9FF7F70E-5D57-435A-AAD9-EA069B6159D9.1 source=core message="S: 354 go ahead, make my day"

Any objects you pass through will also be appeneded to the log line as
key=value and will look like this:

level=NOTICE connection_uuid=9FF7F70E-5D57-435A-AAD9-EA069B6159D9.1 source=core message=disconnect ip=127.0.0.1 rdns=Unknown helo=3h2dnz8a0if relay=N early=N esmtp=N tls=N pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=222 lr="" time=0.052

You can find out more about logfmt here: https://brandur.org/logfmt

msimerson · 2017-08-25T22:55:57Z

connection.js

@@ -23,6 +22,7 @@ var trans       = require('./transaction');
 var plugins     = require('./plugins');
 var rfc1869     = require('./rfc1869');
 var outbound    = require('./outbound');
+var ResultStore = require('haraka-results');


Just curious, why move this down? The general format you'll find in most files is a section of node.js builtin modules, then a section of NPM modules, and finally a section of local (./) modules.

It was a mistake, I based this off the older one and reverted a lot of stuff, this should've been one of them, fixing now

Log ini

Signed-off-by: Anosh Malik <[email protected]>

smfreegard · 2017-08-28T16:08:53Z

package.json

@@ -23,6 +23,7 @@
    "iconv"                 : "~2.3.0",
    "ipaddr.js"             : "~1.5.0",
    "js-yaml"               : "~3.9.0",
+    "logfmt"                : "^1.2.0",


Shouldn't this be an optional dependency?

Nope, this is being used for default too, line 275 of logger.js

smfreegard

As per my comments.

msimerson · 2017-08-28T19:30:46Z

I have removed the log.ini portions from this PR, having moved them over to #2054 where they have continued.

msimerson · 2017-08-28T19:35:16Z

@KingNoosh , are you familiar with the git witchcraft known as rebasing? If so, please do the needful. If not, catch me on IRC, or just use git merge.

…feature/logformat

smfreegard · 2017-08-29T09:55:38Z

Ok - you don't appear to have benchmarked this like I suggested on IRC. I also didn't appreciate that you had made logfmt integral to logger.

Adding new dependencies into core shouldn't be done without very good reason. Here is why:

I've just done some really basic benchmarks which do a console.log of a single log line 1 million times. I picked the disconnect log line as it's the worst case as it puts everything inside an Array and then joins the array by ' ', so this is the worst example. It's also quite a long log line which was the other reason I picked it.

This is the original disconnect log line with the original code:

smf@i7desktop:~$ time node haraka_logger1.js 2>&1 > /dev/null

real	0m4.343s
user	0m4.148s
sys	0m0.244s

Here is the same but using logfmt.stringify:

smf@i7desktop:~$ time node haraka_logger2.js 2>&1 > /dev/null

real	0m11.633s
user	0m11.448s
sys	0m0.252s

That's 167.86% slower....

So, there's no way I'm going to approve this pull request with logfmt being used by default in logger.js. It should be lazy loaded if it's enabled and you should probably document the performance hit over standard logging as this seems pretty considerable to me.

For completeness I also changed the code to use es6 literals:

smf@i7desktop:~$ time node haraka_logger3.js 2>&1 > /dev/null

real	0m3.589s
user	0m3.472s
sys	0m0.168s

So that would be 17.36% faster

And I did the same by changing to the code to + ' ' + concatenate everything without using an Array:

smf@i7desktop:~$ time node haraka_logger4.js 2>&1 > /dev/null

real	0m5.060s
user	0m4.864s
sys	0m0.228s

Whist surprised me a bit as it's 16.51% slower than doing array.concat(' ' ).

So es6 literals are the fastest way to handle this. However I suggest you simply revert the changes to all of the log lines as changing log lines to es6 literals should be done in a separate pull request.

KingNoosh · 2017-08-30T10:03:23Z

With the changes suggested from IRC, this should be ready to review again.

smfreegard · 2017-08-30T15:54:32Z

docs/Logging.md

 the logger.js log\* method. objects-as-arguments are then sniffed
 to try to determine if they're a connection or plugin instance.
+<<<<<<< HEAD:docs/Logging_API.md


You've got a merge conflict marker here that you've forgotten to remove

smfreegard · 2017-08-30T15:55:03Z

docs/Logging.md

+
+You can find out more about logfmt here: [https://brandur.org/logfmt](https://brandur.org/logfmt)
+=======
+>>>>>>> upstream/master:docs/Logging.md


And another two here.

smfreegard · 2017-08-30T15:55:24Z

docs/Logging.md

+from `default` to `logfmt` in the `config/log.ini` file which will
+start logging in the following format below.
+
+    level=PROTOCOL connection_uuid=9FF7F70E-5D57-435A-AAD9-EA069B6159D9.1 source=core message="S: 354 go ahead, make my day"


I thought connection_uuid was changed to uuid ?

It's still connection_uuid, do you want me to rename to uuid?

smfreegard · 2017-08-30T15:57:05Z

logger.js

-        var pluginstr = '[' + (plugin || 'core') + ']';
+        var logobj = {
+            level,
+            connection_uuid: '-',


Ok - it appears not. This isn't going to be a connection_uuid, it could be a transaction ID or an outbound recipient ID. So uuid is far more appropriate (and terse).

smfreegard · 2017-08-30T15:57:41Z

plugins.js

-            'retval='   + constants.translate(retval),
-            'msg="'     + ((msg) ? msg : '') + '"',
-        ].join(' '));
+        object[log]({


Can you align this block like it was before.

smfreegard · 2017-08-30T16:16:25Z

docs/Logging.md

@@ -21,25 +21,25 @@ See also
 ------------------
 [https://github.com/haraka/Haraka/pull/119](https://github.com/haraka/Haraka/pull/119)

-logline will always always be in the form:
+The logline by default will be in the form of:

    [level] [connection uuid] [origin] message


Ooops - missed one.

Anosh Malik added 16 commits August 25, 2017 11:52

Add logfmt support

eef4bfc

Fix log_format typo

f5e7339

Rename connection-uuid to connection_uuid

ae3ba95

Update plugin log message

ca9f1c5

Add newline at end of config

b12d1ea

Update connection.js log messages

f25a60e

Update connection.js

6319cd6

Update logging for server.js

51f874e

Update logging for spf.js

01b2ec3

Update outbound/hmail.js logging

7986b7d

Update outbound/client_pool.js logging

1547743

Fix comment

c90ac39

Update logger.js test slightly

a4d2ace

Fix logfmt return

03b58c2

Update logging.js source to origin

8d590d7

Update docs

6dd222e

haraka deleted a comment from codecov bot Aug 25, 2017

Anosh Malik added 4 commits August 25, 2017 17:56

Rename connection_uuid to uuid

31be0f6

Update format constant

d80f01f

Update test

b30696e

Update test

f8e0315

KingNoosh force-pushed the feature/logformat branch from b30696e to f8e0315 Compare August 25, 2017 21:03

msimerson and others added 4 commits August 25, 2017 15:25

move log settings into log.ini

ef9a782

Rename logformat to format

dc076bc

restore defaults

43750e6

Merge branch 'feature/logformat' into log-ini

4627449

msimerson reviewed Aug 25, 2017

View reviewed changes

KingNoosh added 2 commits August 26, 2017 00:03

Merge pull request #1 from msimerson/log-ini

e8d11ff

Log ini

Update connection.js

bd2eb4e

Signed-off-by: Anosh Malik <[email protected]>

smfreegard reviewed Aug 28, 2017

View reviewed changes

smfreegard requested changes Aug 28, 2017

View reviewed changes

haraka deleted a comment from smfreegard Aug 28, 2017

haraka deleted a comment from baudehlo Aug 28, 2017

haraka deleted a comment from codecov bot Aug 28, 2017

Anosh Malik added 3 commits August 29, 2017 09:03

Merge branch 'feature/logformat' of github.com:KingNoosh/Haraka into …

9bb7b89

…feature/logformat

Merge remote-tracking branch 'upstream/master' into feature/logformat

73c2aa4

Update connection_uuid

b7436a3

haraka deleted a comment from codecov bot Aug 29, 2017

Anosh Malik added 3 commits August 29, 2017 17:34

Remove logfmt

efba420

Merge remote-tracking branch 'upstream/master' into feature/logformat

12e1bf0

Update tests

5fa4f2c

smfreegard reviewed Aug 30, 2017

View reviewed changes

Merge remote-tracking branch 'upstream/master' into feature/logformat

4b0fe48

smfreegard reviewed Aug 30, 2017

View reviewed changes

Update logging docs

2ca62ee

smfreegard approved these changes Aug 30, 2017

View reviewed changes

smfreegard merged commit c17da20 into haraka:master Aug 30, 2017

KingNoosh deleted the feature/logformat branch September 1, 2017 12:11

haraka deleted a comment from codecov bot Feb 23, 2021

msimerson mentioned this pull request Feb 23, 2021

Logs issued by connection.js don't use key-value pairs #2921

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logfmt support #2047

Add logfmt support #2047

KingNoosh commented Aug 25, 2017 •

edited

Loading

KingNoosh commented Aug 25, 2017

msimerson Aug 25, 2017

KingNoosh Aug 25, 2017

smfreegard Aug 28, 2017

KingNoosh Aug 29, 2017

smfreegard left a comment

msimerson commented Aug 28, 2017

msimerson commented Aug 28, 2017

smfreegard commented Aug 29, 2017

KingNoosh commented Aug 30, 2017

smfreegard Aug 30, 2017

smfreegard Aug 30, 2017

smfreegard Aug 30, 2017

KingNoosh Aug 30, 2017

KingNoosh Aug 30, 2017

smfreegard Aug 30, 2017

smfreegard Aug 30, 2017

smfreegard Aug 30, 2017

Add logfmt support #2047

Add logfmt support #2047

Conversation

KingNoosh commented Aug 25, 2017 • edited Loading

KingNoosh commented Aug 25, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

smfreegard left a comment

Choose a reason for hiding this comment

msimerson commented Aug 28, 2017

msimerson commented Aug 28, 2017

smfreegard commented Aug 29, 2017

KingNoosh commented Aug 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

KingNoosh commented Aug 25, 2017 •

edited

Loading