piknik icon indicating copy to clipboard operation
piknik copied to clipboard

Published 20 hours ago • verified publisher icon jedisct1

Improve logging

Open paolobarbolini opened this issue 3 years ago • 4 comments

Currently debugging the SMTP implementation is very hard and leads to issues like #442 and #554.

Improving our tracing should fix this issue.

paolobarbolini avatar Feb 27 '21 17:02 paolobarbolini

Is there a reason why only the SmtpTransport transport module writes logs using tracing?

finga avatar Jan 14 '23 11:01 finga

Is there a reason why only the SmtpTransport transport module writes logs using tracing?

There's no reason in particular. Nobodycame forward to putting it in other modules

paolobarbolini avatar Jan 14 '23 11:01 paolobarbolini

Is there a reason for not using it?

No, absolutely not, I meant the question the other way around. I would like to have tracing also in the other transport modules and wanted to know if there is a reason for why there are not any yet. If there is no reason I would try to add some log messages.

finga avatar Jan 14 '23 20:01 finga

For troubleshooting any provider and connectivity issue a complete communication trace is crucial. It should be something comprehensive like this:

$ node index.js
[2024-01-26 05:50:55] DEBUG Creating transport: nodemailer (6.9.8; +https://nodemailer.com/; SMTP/6.9.8[client:6.9.8])
[2024-01-26 05:50:55] DEBUG Sending mail using SMTP/6.9.8[client:6.9.8]
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] Resolved smtp-mail.outlook.com as 52.98.20.150 [cache miss]
[2024-01-26 05:50:55] INFO  [3FZZBB0pfY] Connection established to 52.98.20.150:587
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 220 JNAP275CA0020.outlook.office365.com Microsoft ESMTP MAIL Service ready at Fri, 26 Jan 2024 05:50:55 +0000
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] C: EHLO [127.0.0.1]
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-JNAP275CA0020.outlook.office365.com Hello [102.16.119.150]
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-SIZE 157286400
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-PIPELINING
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-DSN
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-ENHANCEDSTATUSCODES
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-STARTTLS
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-8BITMIME
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-BINARYMIME
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250-CHUNKING
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 250 SMTPUTF8
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] C: STARTTLS
[2024-01-26 05:50:55] DEBUG [3FZZBB0pfY] S: 220 2.0.0 SMTP server ready
[2024-01-26 05:50:56] INFO  [3FZZBB0pfY] Connection upgraded with STARTTLS
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] C: EHLO [127.0.0.1]
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-JNAP275CA0020.outlook.office365.com Hello [102.16.119.150]
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-SIZE 157286400
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-PIPELINING
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-DSN
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-ENHANCEDSTATUSCODES
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-AUTH LOGIN XOAUTH2
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-8BITMIME
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-BINARYMIME
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250-CHUNKING
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] S: 250 SMTPUTF8
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] SMTP handshake finished
[2024-01-26 05:50:56] DEBUG [3FZZBB0pfY] C: AUTH LOGIN
[2024-01-26 05:50:57] DEBUG [3FZZBB0pfY] S: 334 <server_challenge>
[2024-01-26 05:50:57] DEBUG [3FZZBB0pfY] C: <client_answer>
[2024-01-26 05:50:57] DEBUG [3FZZBB0pfY] S: 334 <server_challenge>
[2024-01-26 05:50:57] DEBUG [3FZZBB0pfY] C: <client_answer>
[2024-01-26 05:51:00] DEBUG [3FZZBB0pfY] S: 235 2.7.0 Authentication successful
[2024-01-26 05:51:00] INFO  [3FZZBB0pfY] User "[email protected]" authenticated
[2024-01-26 05:51:00] INFO  Sending message <[email protected]> to <[email protected]>
[2024-01-26 05:51:00] DEBUG [3FZZBB0pfY] C: MAIL FROM:<[email protected]>
[2024-01-26 05:51:00] DEBUG [3FZZBB0pfY] S: 250 2.1.0 Sender OK
[2024-01-26 05:51:00] DEBUG [3FZZBB0pfY] C: RCPT TO:<[email protected]>
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] S: 250 2.1.5 Recipient OK
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] C: DATA
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] S: 354 Start mail input; end with <CRLF>.<CRLF>
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] Content-Type: text/plain; charset=utf-8
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] From: [email protected]
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] To: [email protected]
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] Subject: Sending Email using Node.js
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] Message-ID: <[email protected]>
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] Content-Transfer-Encoding: 7bit
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] Date: Fri, 26 Jan 2024 05:50:55 +0000
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] MIME-Version: 1.0
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] 
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] That was easy!
[2024-01-26 05:51:01] DEBUG [3FZZBB0pfY] .
[2024-01-26 05:51:01] INFO  [3FZZBB0pfY] <311 bytes encoded mime message (source size 308 bytes)>
[2024-01-26 05:51:02] DEBUG [3FZZBB0pfY] S: 250 2.0.0 OK <AS4PR08MB75540650817E022237A16E19E7792@AS4PR08MB7554.eurprd08.prod.outlook.com> [Hostname=AS4PR08MB7554.eurprd08.prod.outlook.com]
[2024-01-26 05:51:02] DEBUG [3FZZBB0pfY] Closing connection to the server using "end"
Email sent: 250 2.0.0 OK <AS4PR08MB75540650817E022237A16E19E7792@AS4PR08MB7554.eurprd08.prod.outlook.com> [Hostname=AS4PR08MB7554.eurprd08.prod.outlook.com]
[2024-01-26 05:51:02] INFO  [3FZZBB0pfY] Connection closed

to troubleshoot a failed communication like:

$ ./index.js
[2024-01-26 05:55:47] DEBUG Creating transport: nodemailer (6.9.8; +https://nodemailer.com/; SMTP/6.9.8[client:6.9.8])
[2024-01-26 05:55:47] DEBUG Sending mail using SMTP/6.9.8[client:6.9.8]
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] Resolved smtp-mail.outlook.com as 52.98.18.22 [cache miss]
[2024-01-26 05:55:47] INFO  [0PgqL5Qwp60] Connection established to 52.98.18.22:587
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 220 JN2P275CA0006.outlook.office365.com Microsoft ESMTP MAIL Service ready at Fri, 26 Jan 2024 05:55:47 +0000
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] C: EHLO thebrain
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-JN2P275CA0006.outlook.office365.com Hello [102.16.119.150]
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-SIZE 157286400
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-PIPELINING
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-DSN
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-ENHANCEDSTATUSCODES
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-STARTTLS
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-8BITMIME
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-BINARYMIME
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250-CHUNKING
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] S: 250 SMTPUTF8
[2024-01-26 05:55:47] DEBUG [0PgqL5Qwp60] C: STARTTLS
[2024-01-26 05:55:48] DEBUG [0PgqL5Qwp60] S: 220 2.0.0 SMTP server ready
[2024-01-26 05:55:48] INFO  [0PgqL5Qwp60] Connection upgraded with STARTTLS
[2024-01-26 05:55:48] DEBUG [0PgqL5Qwp60] C: EHLO <hostname>
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-JN2P275CA0006.outlook.office365.com Hello [102.16.119.150]
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-SIZE 157286400
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-PIPELINING
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-DSN
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-ENHANCEDSTATUSCODES
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-AUTH LOGIN XOAUTH2
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-8BITMIME
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-BINARYMIME
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250-CHUNKING
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 250 SMTPUTF8
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] SMTP handshake finished
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] C: AUTH LOGIN
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 334 <challenge>
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] C: <response>
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] S: 334 <challenge>
[2024-01-26 05:55:49] DEBUG [0PgqL5Qwp60] C: <response>
[2024-01-26 05:55:52] DEBUG [0PgqL5Qwp60] S: 235 2.7.0 Authentication successful
[2024-01-26 05:55:52] INFO  [0PgqL5Qwp60] User "[email protected]" authenticated
[2024-01-26 05:55:52] INFO  Sending message <[email protected]> to <[email protected]>
[2024-01-26 05:55:52] DEBUG [0PgqL5Qwp60] C: MAIL FROM:<[email protected]>
[2024-01-26 05:55:52] DEBUG [0PgqL5Qwp60] S: 250 2.1.0 Sender OK
[2024-01-26 05:55:52] DEBUG [0PgqL5Qwp60] C: RCPT TO:<[email protected]>
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] S: 250 2.1.5 Recipient OK
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] C: DATA
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] S: 354 Start mail input; end with <CRLF>.<CRLF>
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] Content-Type: text/plain; charset=utf-8
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] From: [email protected]
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] To: [email protected]
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] Subject: Sending Email using Node.js No. 2
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] Message-ID: <[email protected]>
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] Content-Transfer-Encoding: 7bit
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] Date: Fri, 26 Jan 2024 05:55:47 +0000
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] MIME-Version: 1.0
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] 
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] That was easy!
[2024-01-26 05:55:53] DEBUG [0PgqL5Qwp60] .
[2024-01-26 05:55:53] INFO  [0PgqL5Qwp60] <308 bytes encoded mime message (source size 305 bytes)>
[2024-01-26 05:55:54] DEBUG [0PgqL5Qwp60] S: 554 5.2.252 SendAsDenied; [email protected] not allowed to send as [email protected]; STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message
[BeginDiagnosticData]Cannot submit message. 
# ...
[EndDiagnosticData] 
[Hostname=AS4PR08MB7554.eurprd08.prod.outlook.com]
[2024-01-26 05:55:54] DEBUG [0PgqL5Qwp60] Closing connection to the server using "end"
[2024-01-26 05:55:54] ERROR Send error for <[email protected]>: Message failed: 554 5.2.252 SendAsDenied; [email protected] not allowed to send as [email protected]; STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message
[BeginDiagnosticData]Cannot submit message. 
# ...
[EndDiagnosticData] 
[Hostname=AS4PR08MB7554.eurprd08.prod.outlook.com]
[2024-01-26 05:55:54] ERROR Send Error: Message failed: 554 5.2.252 SendAsDenied; [email protected] not allowed to send as [email protected]; STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message
[BeginDiagnosticData]Cannot submit message. 
# ...
[EndDiagnosticData] 
[Hostname=AS4PR08MB7554.eurprd08.prod.outlook.com]
[2024-01-26 05:55:54] INFO  [0PgqL5Qwp60] Connection closed

Please, Is there already an option I can get some insights like this?

bodo-hugo-barwich avatar Jan 26 '24 07:01 bodo-hugo-barwich