Re: [pmg-devel] applied: [PATCH v3 log-tracker] close #2106: show outgoing TLS connection in tracking center

[Stoiko Ivanov <s.ivanov@proxmox.com>]

On Tue, 23 Mar 2021 12:05:31 +0100
Mira Limbeck <m.limbeck@proxmox.com> wrote:

> This is a best effort try to add the outgoing TLS connection information
> to the output of pmg-log-tracker. The only thing we can match on is the
> PID of the 'smtp' process. In the code we asumme that the TLS log entry
> always happens before the actual smtp send entry that has a QID. This means
> we save the TLS log entry in a map with the PID as key and then, once the
> send entry happens, we look it up and add the log entry to the QEntry's
> logs.
applied - huge thanks!

> 
> Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
> ---
> v3:
>  - fixed tests
>  - added sorting to QMGR logs
> v2:
>  - added 'Untrusted' line match as well
> 
>  src/main.rs                                   | 24 +++++++++++++++++++
>  tests/test_output_after_queue                 |  1 +
>  tests/test_output_after_queue_host            |  1 +
>  ...before_queue_mixed_accept_block_quarantine |  1 +
>  4 files changed, 27 insertions(+)
> 
> diff --git a/src/main.rs b/src/main.rs
> index 5069252..9594b18 100644
> --- a/src/main.rs
> +++ b/src/main.rs
> @@ -378,6 +378,18 @@ fn handle_qmgr_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8]) {
>  
>  // handle log entries for 'lmtp', 'smtp', 'error' and 'local'
>  fn handle_lmtp_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8]) {
> +    if msg.starts_with(b"Trusted TLS connection established to")
> +        || msg.starts_with(b"Untrusted TLS connection established to")
> +    {
> +        // the only way to match outgoing TLS connections is by smtp pid
> +        // this message has to appear before the 'qmgr: <QID>: removed' entry in the log
> +        parser.smtp_tls_log_by_pid.insert(
> +            parser.current_record_state.pid,
> +            (complete_line.into(), parser.lines),
> +        );
> +        return;
> +    }
> +
>      let (qid, data) = match parse_qid(msg, 15) {
>          Some((q, t)) => (q, t),
>          None => return,
> @@ -393,6 +405,14 @@ fn handle_lmtp_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8]) {
>          .log
>          .push((complete_line.into(), parser.lines));
>  
> +    // assume the TLS log entry always appears before as it is the same process
> +    if let Some(log_line) = parser
> +        .smtp_tls_log_by_pid
> +        .remove(&parser.current_record_state.pid)
> +    {
> +        qe.borrow_mut().log.push(log_line);
> +    }
> +
>      let data = &data[2..];
>      if !data.starts_with(b"to=<") {
>          return;
> @@ -1594,6 +1614,7 @@ impl QEntry {
>  
>              if !self.log.is_empty() {
>                  parser.write_all_ok(b"QMGR:\n");
> +                self.log.sort_by(|a, b| a.1.cmp(&b.1));
>                  print_log(parser, &self.log);
>              }
>          }
> @@ -1668,6 +1689,8 @@ struct Parser {
>      fentries: HashMap<Box<[u8]>, Rc<RefCell<FEntry>>>,
>      qentries: HashMap<Box<[u8]>, Rc<RefCell<QEntry>>>,
>  
> +    smtp_tls_log_by_pid: HashMap<u64, (Box<[u8]>, u64)>,
> +
>      current_record_state: RecordState,
>      rel_line_nr: u64,
>  
> @@ -1705,6 +1728,7 @@ impl Parser {
>              sentries: HashMap::new(),
>              fentries: HashMap::new(),
>              qentries: HashMap::new(),
> +            smtp_tls_log_by_pid: HashMap::new(),
>              current_record_state: Default::default(),
>              rel_line_nr: 0,
>              current_year: years,
> diff --git a/tests/test_output_after_queue b/tests/test_output_after_queue
> index ec2fc65..b93d4c4 100644
> --- a/tests/test_output_after_queue
> +++ b/tests/test_output_after_queue
> @@ -70,6 +70,7 @@ L00000018 Dec 18 15:50:38 proxmox-new postfix/smtpd[13179]: disconnect from loca
>  QMGR:
>  L00000016 Dec 18 15:50:38 proxmox-new postfix/cleanup[13173]: 88F2E42667: message-id=<xyz>
>  L00000017 Dec 18 15:50:38 proxmox-new postfix/qmgr[18171]: 88F2E42667: from=<test@test.localdomain>, size=8037, nrcpt=4 (queue active)
> +L0000001D Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: Untrusted TLS connection established to 192.168.22.40[192.168.22.40]:25: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>  L00000024 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test1@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
>  L00000025 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test2@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
>  L00000026 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test3@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
> diff --git a/tests/test_output_after_queue_host b/tests/test_output_after_queue_host
> index ead669c..219bdb9 100644
> --- a/tests/test_output_after_queue_host
> +++ b/tests/test_output_after_queue_host
> @@ -41,6 +41,7 @@ L00000018 Dec 18 15:50:38 proxmox-new postfix/smtpd[13179]: disconnect from loca
>  QMGR:
>  L00000016 Dec 18 15:50:38 proxmox-new postfix/cleanup[13173]: 88F2E42667: message-id=<xyz>
>  L00000017 Dec 18 15:50:38 proxmox-new postfix/qmgr[18171]: 88F2E42667: from=<test@test.localdomain>, size=8037, nrcpt=4 (queue active)
> +L0000001D Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: Untrusted TLS connection established to 192.168.22.40[192.168.22.40]:25: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>  L00000024 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test1@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
>  L00000025 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test2@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
>  L00000026 Dec 18 15:50:38 proxmox-new postfix/smtp[13180]: 88F2E42667: to=<test3@localhost>, relay=192.168.22.40[192.168.22.40]:25, delay=0.15, delays=0.05/0/0.04/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C928BF624F6)
> diff --git a/tests/test_output_before_queue_mixed_accept_block_quarantine b/tests/test_output_before_queue_mixed_accept_block_quarantine
> index 7495a78..637b40a 100644
> --- a/tests/test_output_before_queue_mixed_accept_block_quarantine
> +++ b/tests/test_output_before_queue_mixed_accept_block_quarantine
> @@ -30,6 +30,7 @@ L00000013 Apr 30 15:40:41 pmg6 pmg-smtp-filter[21528]: 611D85EAAD6477B053: proce
>  QMGR:
>  L0000000E Apr 30 15:40:40 pmg6 postfix/cleanup[21632]: E1C6561393: message-id=<20200430134439.GE6794@test@localdomain>
>  L0000000F Apr 30 15:40:41 pmg6 postfix/qmgr[23452]: E1C6561393: from=<senduser@test@localdomain>, size=1436, nrcpt=1 (queue active)
> +L00000012 Apr 30 15:40:41 pmg6 postfix/smtp[21626]: Untrusted TLS connection established to 192.0.2.69[192.0.2.69]:25: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)
>  L00000015 Apr 30 15:40:41 pmg6 postfix/smtp[21626]: E1C6561393: to=<reject@test.recipient.example>, relay=192.0.2.69[192.0.2.69]:25, delay=0.73, delays=0.19/0/0.05/0.5, dsn=5.7.1, status=bounced (host 192.0.2.69[192.0.2.69] said: 554 5.7.1 <reject@test.recipient.example>: Recipient address rejected: no mail for reject@ (in reply to RCPT TO command))
>  L00000019 Apr 30 15:40:42 pmg6 postfix/qmgr[23452]: E1C6561393: removed
>