Client IDs in logs should be at the beginning

[lord-alfred]

Now the logs look like this:

time="2019-08-06T23:20:53+03:00" level=debug msg="[0.0.0.0:25] Waiting for a new client. Next Client ID: 1"
time="2019-08-06T23:21:26+03:00" level=debug msg="[0.0.0.0:25] Waiting for a new client. Next Client ID: 2"
time="2019-08-06T23:21:26+03:00" level=info msg="Handle client [127.0.0.1], id: 1"
time="2019-08-06T23:21:26+03:00" level=debug msg="Writing response to client: \n220 example.com SMTP #1 (1) 2019-08-06T23:21:26+03:00\r\n"
time="2019-08-06T23:21:26+03:00" level=debug msg="Client sent: EHLO localhost"
time="2019-08-06T23:21:26+03:00" level=debug msg="Writing response to client: \n250-example.com Hello\r\n250-SIZE 3145728\r\n250-PIPELINING\r\n250-STARTTLS\r\n250-ENHANCEDSTATUSCODES\r\n250 HELP\r\n"
time="2019-08-06T23:21:26+03:00" level=debug msg="Client sent: QUIT"
time="2019-08-06T23:21:26+03:00" level=debug msg="Writing response to client: \n221 2.0.0 Bye\r\n"
time="2019-08-06T23:21:56+03:00" level=debug msg="[0.0.0.0:25] Waiting for a new client. Next Client ID: 3"
time="2019-08-06T23:21:56+03:00" level=info msg="Handle client [127.0.0.1], id: 2"
time="2019-08-06T23:21:56+03:00" level=debug msg="Writing response to client: \n220 example.com SMTP #2 (1) 2019-08-06T23:21:56+03:00\r\n"
time="2019-08-06T23:21:56+03:00" level=debug msg="Client sent: EHLO localhost"
time="2019-08-06T23:21:56+03:00" level=debug msg="Writing response to client: \n250-example.com Hello\r\n250-SIZE 3145728\r\n250-PIPELINING\r\n250-STARTTLS\r\n250-ENHANCEDSTATUSCODES\r\n250 HELP\r\n"
time="2019-08-06T23:21:56+03:00" level=debug msg="Client sent: QUIT"
time="2019-08-06T23:21:56+03:00" level=debug msg="Writing response to client: \n221 2.0.0 Bye\r\n"

And there is no way to make grep to get the delivery progress of a specific letter.

For example, in postfix logs looks like:

Aug  4 06:25:55 servername postfix/qmgr[21396]: DAD61250E8: removed
Aug  4 06:25:55 servername postfix/smtpd[4607]: disconnect from smtp2.dfw.sitename.com[X.X.80.173] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Aug  4 06:26:00 servername postfix/smtpd[4497]: connect from localhost[127.0.0.1]
Aug  4 06:26:00 servername postfix/smtpd[4497]: disconnect from localhost[127.0.0.1] ehlo=1 quit=1 commands=2
Aug  4 06:26:09 servername postfix/smtpd[4607]: connect from smtp3-2.dfw.sitename.com[X.X.81.238]
Aug  4 06:26:11 servername postfix/smtpd[4607]: 07C82250E8: client=smtp3-2.dfw.sitename.com[X.X.81.238]
Aug  4 06:26:11 servername postfix/cleanup[4465]: 07C82250E8: message-id=<0e1d1452dd822b4c33c122fd7919d542@sitename.com>
Aug  4 06:26:11 servername postfix/qmgr[21396]: 07C82250E8: from=<resvipocomro=site.com@bounces.sitename.com>, size=32406, nrcpt=1 (queue active)
Aug  4 06:26:11 servername postfix/pipe[4610]: 07C82250E8: to=<resvipocomro@site.com>, relay=myhook, delay=0.53, delays=0.38/0/0/0.15, dsn=2.0.0, status=sent (delivered via myhook service (Saved (32049 bytes) from: [hello@sitename.com] to: [resvipocomro@site.com]))
Aug  4 06:26:11 servername postfix/qmgr[21396]: 07C82250E8: removed
Aug  4 06:26:11 servername postfix/smtpd[4607]: disconnect from smtp3-2.dfw.sitename.com[X.X.81.238] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Aug  4 06:26:21 servername postfix/smtpd[4497]: connect from smtp2-2.bur.sitename.com[X.X.123.37]
Aug  4 06:26:22 servername postfix/smtpd[4497]: 8DF37250E8: client=smtp2-2.bur.sitename.com[X.X.123.37]
Aug  4 06:26:22 servername postfix/cleanup[4697]: 8DF37250E8: message-id=<fc2683283337c34ccbe288787de9151b@sitename.com>
Aug  4 06:26:22 servername postfix/qmgr[21396]: 8DF37250E8: from=<grobderliasebel=site.com@bounces.sitename.com>, size=32489, nrcpt=1 (queue active)
Aug  4 06:26:23 servername postfix/pipe[4699]: 8DF37250E8: to=<grobderliasebel@site.com>, relay=myhook, delay=0.62, delays=0.42/0/0/0.2, dsn=2.0.0, status=sent (delivered via myhook service (Saved (32135 bytes) from: [hello@sitename.com] to: [grobderliasebel@site.com]))
Aug  4 06:26:23 servername postfix/qmgr[21396]: 8DF37250E8: removed
Aug  4 06:26:23 servername postfix/smtpd[4497]: disconnect from smtp2-2.bur.sitename.com[X.X.123.37] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Aug  4 06:26:30 servername postfix/smtpd[4607]: connect from localhost[127.0.0.1]

The numbers in square brackets are the process id and hases like "07C82250E8" - it is mail identifier. On them you can track the entire process of delivery.

I think it would be nice to do the same. For example, before level= add a client number / mail identifier.
I can hardly do this, but if there is a simple way to hack the log, please tell about it.

[flashmob]

Thanks. Understand. Would need to add this to the list of things to do in the Logger refortor here: #116

[lord-alfred]

Yes, that would be great!
But judging by the code that is now there in PR, I don’t know how I can help. Is there any way to make this easier?

[lord-alfred]

And I think that words like time=, level= and msg= are not needed on every line.

Now it looks like this:

time="2019-08-06T23:21:56+03:00" level=debug msg="Client sent: QUIT"

But it would be prettier like this:

2019-08-06T23:21:56+03:00 debug: Client sent: QUIT

This is 18 characters less for each line.

And if you fantasize how it should look with mail identifiers, it would be better if it were like this:

2019-08-06T23:21:56+03:00 debug[8DF372]: Client sent: QUIT

8DF372 - is mail ID (not complete, because it's probably not necessary here)