Project

General

Profile

Bug #28590

Mail fixes regarding the "to address" and failed attempts

Added by Timur Bakeyev over 1 year ago. Updated about 1 year ago.

Status:
Done
Priority:
Nice to have
Assignee:
William Grzybowski
Category:
Middleware
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
No
Needs Merging:
No
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

One of the users, seems, put invalid or empty(?) e-mail address as the alerts recipient and when his quota got exceeded he only got in the maillog:

Feb 17 00:00:49 storage /middlewared[79163]: sending mail to
Content-Type: text/plain; charset="utf-8" 
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Subject: storage.local: Quota exceeded on data
Feb 17 00:01:50 storage /middlewared[79163]: sending mail to
Content-Type: text/plain; charset="utf-8" 
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Subject: storage.local: Quota exceeded on data

And in the middlewared.log:

[2018/02/18 10:43:17] (WARNING) MailService.send():274 - Failed to send email: {'': (555, b'5.5.2 Syntax error. x186sm18494997itb.6 - gsmtp')}
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py", line 265, in send
    server.sendmail(config['fromemail'], to, msg.as_string())
  File "/usr/local/lib/python3.6/smtplib.py", line 881, in sendmail
    raise SMTPRecipientsRefused(senderrs)
smtplib.SMTPRecipientsRefused: {'': (555, b'5.5.2 Syntax error. x186sm18494997itb.6 - gsmtp')}
[2018/02/18 10:43:46] (DEBUG) MailService.send_mail_queue():319 - Sending message from queue failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py", line 316, in send_mail_queue
    server.sendmail(queue.message['From'], queue.message['To'].split(', '), queue.message.as_string())
  File "/usr/local/lib/python3.6/smtplib.py", line 881, in sendmail
    raise SMTPRecipientsRefused(senderrs)
smtplib.SMTPRecipientsRefused: {'': (555, b'5.5.2 Syntax error. j198sm9667245ioe.15 - gsmtp')}

Please note the truncated logs in the maillog.


Related issues

Related to FreeNAS - Bug #28568: Quota exceeded messagesClosed2018-02-17

Associated revisions

Revision 8a42e8f7 (diff)
Added by William Grzybowski over 1 year ago

fix(middlewared/zfs): send quota email to root if user doesnt have email

Ticket: #28590

Revision 848e6b53 (diff)
Added by William Grzybowski over 1 year ago

fix(middlewared/mail): log failed mail attempts to maillog

Also do not truncate mail in mailog, show only headers.

Ticket: #28590

Revision 3ed5cfc2 (diff)
Added by William Grzybowski over 1 year ago

fix(middlewared/zfs): send quota email to root if user doesnt have email

Ticket: #28590

Revision d053ddb8 (diff)
Added by William Grzybowski over 1 year ago

fix(middlewared/mail): log failed mail attempts to maillog

Also do not truncate mail in mailog, show only headers.

Ticket: #28590

History

#1 Updated by Timur Bakeyev over 1 year ago

  • Related to Bug #28568: Quota exceeded messages added

#2 Updated by Timur Bakeyev over 1 year ago

I could find the real reason and affected dataset only in the middlewared jobs list, which, BTW, got size of 3Mb:

....
  {
    "id": 4252,
    "method": "mail.send",
    "arguments": [
      {
        "to": [
          "" 
        ],
        "subject": "storage.local: Quota exceeded on dataset main/cameras",
        "text": "Quota exceeded on dataset main/cameras.\nUsed 100.00% (966.37 GB of 966.37 GB)\n" 
      }
    ],
    "progress": {
      "percent": null,
      "description": null,
      "extra": null
    },
    "result": null,
    "error": "[EFAULT] Failed to send email: {'': (555, b'5.5.2 Syntax error. r139sm18657107itc.34 - gsmtp')}",
    "exception": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py\", line 265, in send\n    se
rver.sendmail(config['fromemail'], to, msg.as_string())\n  File \"/usr/local/lib/python3.6/smtplib.py\", line 881, in sendmail\n    raise SMTPRecipientsRefuse
d(senderrs)\nsmtplib.SMTPRecipientsRefused: {'': (555, b'5.5.2 Syntax error. r139sm18657107itc.34 - gsmtp')}\n\nDuring handling of the above exception, anothe
r exception occurred:\n\nTraceback (most recent call last):\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/job.py\", line 290, in run\n    await
 self.future\n  File \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/
local/lib/python3.6/site-packages/middlewared/job.py\", line 345, in __run_body\n    rv = await self.middleware.run_in_thread(self.method, *([self] + args))\n
  File \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/local/lib/pyth
on3.6/site-packages/middlewared/main.py\", line 849, in run_in_thread\n    return await self.run_in_thread_pool(self.__threadpool, method, *args, **kwargs)\n
 File \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/local/lib/pytho
n3.6/site-packages/middlewared/main.py\", line 845, in run_in_thread_pool\n    await task\n  File \"/usr/local/lib/python3.6/concurrent/futures/thread.py\", l
ine 56, in run\n    result = self.fn(*self.args, **self.kwargs)\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/schema.py\", line 495, in nf\n
 return f(*args, **kwargs)\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py\", line 278, in send\n    raise CallError(f'Failed to
send email: {e}')\nmiddlewared.service_exception.CallError: [EFAULT] Failed to send email: {'': (555, b'5.5.2 Syntax error. r139sm18657107itc.34 - gsmtp')}\n" 
,
    "state": "FAILED",
    "time_started": {
      "$date": 1518890293670
    },
    },
    "time_finished": {
      "$date": 1518890294202
    }
  },
  {
    "id": 4253,
    "method": "mail.send",
    "arguments": [
      {
        "to": [
          "" 
        ],
        "subject": "storage.local: Quota exceeded on dataset main/cameras",
        "text": "Quota exceeded on dataset main/cameras.\nUsed 100.00% (966.37 GB of 966.37 GB)\n" 
      }
    ],
    "progress": {
      "percent": null,
      "description": null,
      "extra": null
    },
    "result": null,
    "error": "[EFAULT] Failed to send email: {'': (555, b'5.5.2 Syntax error. y6sm20057164iod.7 - gsmtp')}",
    "exception": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py\", line 265, in send\n    se
rver.sendmail(config['fromemail'], to, msg.as_string())\n  File \"/usr/local/lib/python3.6/smtplib.py\", line 881, in sendmail\n    raise SMTPRecipientsRefuse
d(senderrs)\nsmtplib.SMTPRecipientsRefused: {'': (555, b'5.5.2 Syntax error. y6sm20057164iod.7 - gsmtp')}\n\nDuring handling of the above exception, another e
xception occurred:\n\nTraceback (most recent call last):\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/job.py\", line 290, in run\n    await se
lf.future\n  File \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/loc
al/lib/python3.6/site-packages/middlewared/job.py\", line 345, in __run_body\n    rv = await self.middleware.run_in_thread(self.method, *([self] + args))\n  F
ile \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/local/lib/python3
.6/site-packages/middlewared/main.py\", line 849, in run_in_thread\n    return await self.run_in_thread_pool(self.__threadpool, method, *args, **kwargs)\n  Fi
le \"/usr/local/lib/python3.6/asyncio/coroutines.py\", line 128, in throw\n    return self.gen.throw(type, value, traceback)\n  File \"/usr/local/lib/python3.
6/site-packages/middlewared/main.py\", line 845, in run_in_thread_pool\n    await task\n  File \"/usr/local/lib/python3.6/concurrent/futures/thread.py\", line
 56, in run\n    result = self.fn(*self.args, **self.kwargs)\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/schema.py\", line 495, in nf\n    re
turn f(*args, **kwargs)\n  File \"/usr/local/lib/python3.6/site-packages/middlewared/plugins/mail.py\", line 278, in send\n    raise CallError(f'Failed to sen
d email: {e}')\nmiddlewared.service_exception.CallError: [EFAULT] Failed to send email: {'': (555, b'5.5.2 Syntax error. y6sm20057164iod.7 - gsmtp')}\n",
    "state": "FAILED",
    "state": "FAILED",
    "time_started": {
      "$date": 1518890354486
    },
    "time_finished": {
      "$date": 1518890355126
    }
  },
...

And so on, grep -c showed 1001 lines with "id":...

#3 Updated by Dru Lavigne over 1 year ago

  • Assignee changed from Release Council to William Grzybowski
  • Target version set to 11.2-RC2

#4 Updated by William Grzybowski over 1 year ago

  • Status changed from Not Started to Blocked
  • Reason for Blocked set to Waiting for feedback

I dont understanding the problem here. What is it exactly? As far as I can see the errors are being properly reported in the middlewared job list.

Is it that the error is not reported in maillog as well?

#5 Updated by Timur Bakeyev over 1 year ago

William Grzybowski wrote:

I dont understanding the problem here. What is it exactly? As far as I can see the errors are being properly reported in the middlewared job list.

Is it that the error is not reported in maillog as well?

There are multiple issues with that one, IMHO.

1a. Which e-mail address is used for alerts here? I'd assume the one, that specified in the root account, but according to the reporter he has a valid e-mail address there. And he receives some other e-mail notifications as well. But not this one.

1b. If he didn't specify any e-mail address for root - why any attempts to send to an empty address are made at all? I see in the code of send:

        to = message.get('to')
        if not to:
            to = [
                self.middleware.call_sync(
                    'user.query', [('username', '=', 'root')], {'get': True}
                )['email']
            ]
            if not to[0]:
                raise CallError('Email address for root is not configured')

So how that was bypassed at all?

2. The maillog log messages are strangely truncated in the middle of the phrase. From the other ticket:

Feb 12 03:01:03 xx-storage-0 /find_alias_for_smtplib.py[83714]: sending mail to nobody
To: nobody
Subject: xx-storage-0.raw.local daily security run output

xx-storage-0.raw.local changes in mounted filesystems:
10c10
< freena
Feb 12 02:01:03 xx-storage-0 /middlewared[245]: sending mail to xx@yyyyyyyyyyyy.com
Content-Type: text/plain; charset="utf-8" 
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Subject: xx-storage-0.raw.local daily security
Feb 12 03:45:03 xx-storage-0 /find_alias_for_smtplib.py[88371]: sending mail to -FCronDaemon, -odi, -oem, -oi
From: Cron Daemon <root@xx-storage-0.raw.local>
To: root
Subject: Cron <root@xx-storage-0> /usr/local/libexec/nas/scrub -t 7 freenas-boot
X-
Feb 12 02:45:04 xx-storage-0 /middlewared[245]: sending mail to xx@yyyyyyyyyyyy.com
Content-Type: text/plain; charset="utf-8" 
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Subject: Cron <root@xx-storage-0> /usr/local/l
Feb 12 02:45:28 xx-storage-0 /middlewared[245]: sending mail to xx@yyyyyyyyyyyy.com
Content-Type: text/plain; charset="utf-8" 
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Subject: xx-storage-0.raw.local: scrub finishe

3. From maillog it's not clear what went wrong with outgoing mail. Some hints are given by middlewared.log, but it's not the place you'd check for mail issues normally. It's pure luck that debug collection was called while mails were still failing to go out, so we could see the problem in the middlewared jobs logs. But we don't expect end user to list jobs on a regular basis to see if something is wrong.

I think it would be expected to see all those failures with sending and tracebacks in the logs, presumably - in the maillog.

#6 Updated by William Grzybowski over 1 year ago

  • Status changed from Blocked to Not Started
  • Reason for Blocked deleted (Waiting for feedback)

#9 Updated by Timur Bakeyev over 1 year ago

William Grzybowski wrote:

I dont see anything wrong there. What is it?

Neither do I. Still we have the result in the ticket. So I don't know, what else could go wrong here...

Could it be that a generated mail contains wrongful To: field, so it bypassed the emptiness check, but still invalid to make it ""?

#10 Updated by William Grzybowski over 1 year ago

  • Status changed from Not Started to Done
  • Reason for Blocked deleted (Waiting for feedback)
  • Needs Doc changed from Yes to No
  • Needs Merging changed from Yes to No

#11 Updated by Dru Lavigne over 1 year ago

  • Subject changed from Mail to the empty or invalid address break mail plugin and there is no diagnostics to Mail fixes regarding the "to address" and failed attempts
  • Target version changed from 11.2-RC2 to 11.2-BETA1

#12 Updated by Dru Lavigne over 1 year ago

  • Status changed from Done to Ready for Testing

#13 Updated by Dru Lavigne about 1 year ago

  • Status changed from Ready for Testing to Done
  • Severity set to New

#14 Updated by Dru Lavigne about 1 year ago

  • Needs QA changed from Yes to No

Also available in: Atom PDF