Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

E-mail is re-sent again on each background job update #6540

Closed
snyssen opened this issue May 24, 2022 · 26 comments · Fixed by #6602
Closed

E-mail is re-sent again on each background job update #6540

snyssen opened this issue May 24, 2022 · 26 comments · Fixed by #6602

Comments

@snyssen
Copy link

snyssen commented May 24, 2022

Steps to reproduce

Unfortunately this issue seems to have spawned randomly as I use the mail client everyday and it has just happened once without me being able to pinpoint the actual cause.

  1. Send an e-mail normally
  2. Close the web page maybe too soon ? It might be the only thing that changed from what I usually do.

Expected behavior

The e-mail is sent only once.

Actual behavior

The same e-mail seems to get re-sent on every Nextcloud background job. It was sent precisely each 5 minutes, which corresponds to the frequency of the cron job I set to manage NextCloud.

Mail app version

1.12.0 (I think, I can't look right now)

Mailserver or service

mailfence

Operating system

Fedora

PHP engine version

No response

Web server

No response

Database

PostgreSQL

Additional info

I had to shutdown my Nextcloud instance for now as it was spamming my recipient. Is there any way I can cancel an "in transit" e-mail ? I am guessing it gets sent to a queue somewhere but isn't removed correctly afterwards, which would explain the loop ?

@ChristophWurst
Copy link
Member

Sounds a lot like #6538.

Could you check your logs? The message must trigger some kind of error, thus it remains in the queue.

@ChristophWurst
Copy link
Member

As a user you should be able to see the message in your Outbox and delete it from there.

@snyssen
Copy link
Author

snyssen commented May 24, 2022

Seems like it is the same issue indeed as I didn't think of it but there were 4 files added to my mail. Will check the logs and update.

@snyssen
Copy link
Author

snyssen commented May 24, 2022

Okay here is the log:

{
    "reqId": "iYOLdVI0oCnd6sll2719",
    "level": 2,
    "time": "2022-05-24T09:10:17+00:00",
    "remoteAddr": "",
    "user": "snyssen",
    "app": "mail",
    "method": "",
    "url": "--",
    "message": "Could not send outbox message 13: Could not send message: Error when communicating with the server.",
    "userAgent": "--",
    "version": "22.2.6.2",
    "exception": {
        "Exception": "OCA\\Mail\\Exception\\ServiceException",
        "Message": "Could not send message: Error when communicating with the server.",
        "Code": 2,
        "Trace": [
            {
                "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                "line": 271,
                "function": "sendMessage",
                "class": "OCA\\Mail\\Service\\MailTransmission",
                "type": "->",
                "args": [
                    {
                        "__class__": "OCA\\Mail\\Model\\NewMessageData"
                    },
                    null,
                    null
                ]
            },
            {
                "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                "line": 129,
                "function": "sendLocalMessage",
                "class": "OCA\\Mail\\Service\\MailTransmission",
                "type": "->",
                "args": [
                    {
                        "__class__": "OCA\\Mail\\Account"
                    },
                    {
                        "id": 13,
                        "__class__": "OCA\\Mail\\Db\\LocalMessage"
                    }
                ]
            },
            {
                "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                "line": 196,
                "function": "sendMessage",
                "class": "OCA\\Mail\\Service\\OutboxService",
                "type": "->",
                "args": [
                    {
                        "id": 13,
                        "__class__": "OCA\\Mail\\Db\\LocalMessage"
                    },
                    {
                        "__class__": "OCA\\Mail\\Account"
                    }
                ]
            },
            {
                "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
                "line": 55,
                "function": "flush",
                "class": "OCA\\Mail\\Service\\OutboxService",
                "type": "->",
                "args": []
            },
            {
                "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
                "line": 79,
                "function": "run",
                "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
                "type": "->",
                "args": [
                    null
                ]
            },
            {
                "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                "line": 95,
                "function": "execute",
                "class": "OCP\\BackgroundJob\\Job",
                "type": "->",
                "args": [
                    {
                        "__class__": "OC\\BackgroundJob\\JobList"
                    },
                    {
                        "__class__": "OC\\Log"
                    }
                ]
            },
            {
                "file": "/var/www/html/cron.php",
                "line": 149,
                "function": "execute",
                "class": "OCP\\BackgroundJob\\TimedJob",
                "type": "->",
                "args": [
                    {
                        "__class__": "OC\\BackgroundJob\\JobList"
                    },
                    {
                        "__class__": "OC\\Log"
                    }
                ]
            }
        ],
        "File": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
        "Line": 210,
        "Previous": {
            "Exception": "Horde_Mime_Exception",
            "Message": "Error when communicating with the server.",
            "Code": 2,
            "Trace": [
                {
                    "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
                    "line": 479,
                    "function": "send",
                    "class": "Horde_Mime_Part",
                    "type": "->",
                    "args": [
                        "[REDACTED RECIPIENT ADDRESS], \"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\" <[REDACTED CC ADDRESS]>",
                        {
                            "__class__": "Horde_Mime_Headers"
                        },
                        {
                            "send8bit": false,
                            "sep": "\r\n",
                            "__class__": "Horde_Mail_Transport_Smtphorde"
                        }
                    ]
                },
                {
                    "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                    "line": 208,
                    "function": "send",
                    "class": "Horde_Mime_Mail",
                    "type": "->",
                    "args": [
                        {
                            "send8bit": false,
                            "sep": "\r\n",
                            "__class__": "Horde_Mail_Transport_Smtphorde"
                        },
                        false,
                        false
                    ]
                },
                {
                    "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                    "line": 271,
                    "function": "sendMessage",
                    "class": "OCA\\Mail\\Service\\MailTransmission",
                    "type": "->",
                    "args": [
                        {
                            "__class__": "OCA\\Mail\\Model\\NewMessageData"
                        },
                        null,
                        null
                    ]
                },
                {
                    "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                    "line": 129,
                    "function": "sendLocalMessage",
                    "class": "OCA\\Mail\\Service\\MailTransmission",
                    "type": "->",
                    "args": [
                        {
                            "__class__": "OCA\\Mail\\Account"
                        },
                        {
                            "id": 13,
                            "__class__": "OCA\\Mail\\Db\\LocalMessage"
                        }
                    ]
                },
                {
                    "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                    "line": 196,
                    "function": "sendMessage",
                    "class": "OCA\\Mail\\Service\\OutboxService",
                    "type": "->",
                    "args": [
                        {
                            "id": 13,
                            "__class__": "OCA\\Mail\\Db\\LocalMessage"
                        },
                        {
                            "__class__": "OCA\\Mail\\Account"
                        }
                    ]
                },
                {
                    "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
                    "line": 55,
                    "function": "flush",
                    "class": "OCA\\Mail\\Service\\OutboxService",
                    "type": "->",
                    "args": []
                },
                {
                    "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
                    "line": 79,
                    "function": "run",
                    "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
                    "type": "->",
                    "args": [
                        null
                    ]
                },
                {
                    "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                    "line": 95,
                    "function": "execute",
                    "class": "OCP\\BackgroundJob\\Job",
                    "type": "->",
                    "args": [
                        {
                            "__class__": "OC\\BackgroundJob\\JobList"
                        },
                        {
                            "__class__": "OC\\Log"
                        }
                    ]
                },
                {
                    "file": "/var/www/html/cron.php",
                    "line": 149,
                    "function": "execute",
                    "class": "OCP\\BackgroundJob\\TimedJob",
                    "type": "->",
                    "args": [
                        {
                            "__class__": "OC\\BackgroundJob\\JobList"
                        },
                        {
                            "__class__": "OC\\Log"
                        }
                    ]
                }
            ],
            "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
            "Line": 1642,
            "Previous": {
                "Exception": "Horde_Mail_Exception",
                "Message": "Error when communicating with the server.",
                "Code": 2,
                "Trace": [
                    {
                        "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
                        "line": 1620,
                        "function": "send",
                        "class": "Horde_Mail_Transport_Smtphorde",
                        "type": "->",
                        "args": [
                            "[REDACTED RECIPIENT ADDRESS], \"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\" <[REDACTED CC ADDRESS]>",
                            {
                                "From": "Simon Nyssen <[REDACTED SENDER]>",
                                "To": "[REDACTED RECIPIENT ADDRESS]",
                                "Cc": "\"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\"\n <[REDACTED CC ADDRESS]>",
                                "Subject": "[REDACTED SUBJECT]",
                                "Message-ID": "<20220524091009.Horde.eBwVMFBOPqCRSs3dHElUdYs@b00a8430f2d1>",
                                "0": "And 5 more entries, set log level to debug to see all entries"
                            },
                            null
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
                        "line": 479,
                        "function": "send",
                        "class": "Horde_Mime_Part",
                        "type": "->",
                        "args": [
                            "[REDACTED RECIPIENT ADDRESS], \"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\" <[REDACTED CC ADDRESS]>",
                            {
                                "__class__": "Horde_Mime_Headers"
                            },
                            {
                                "send8bit": false,
                                "sep": "\r\n",
                                "__class__": "Horde_Mail_Transport_Smtphorde"
                            }
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                        "line": 208,
                        "function": "send",
                        "class": "Horde_Mime_Mail",
                        "type": "->",
                        "args": [
                            {
                                "send8bit": false,
                                "sep": "\r\n",
                                "__class__": "Horde_Mail_Transport_Smtphorde"
                            },
                            false,
                            false
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                        "line": 271,
                        "function": "sendMessage",
                        "class": "OCA\\Mail\\Service\\MailTransmission",
                        "type": "->",
                        "args": [
                            {
                                "__class__": "OCA\\Mail\\Model\\NewMessageData"
                            },
                            null,
                            null
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                        "line": 129,
                        "function": "sendLocalMessage",
                        "class": "OCA\\Mail\\Service\\MailTransmission",
                        "type": "->",
                        "args": [
                            {
                                "__class__": "OCA\\Mail\\Account"
                            },
                            {
                                "id": 13,
                                "__class__": "OCA\\Mail\\Db\\LocalMessage"
                            }
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                        "line": 196,
                        "function": "sendMessage",
                        "class": "OCA\\Mail\\Service\\OutboxService",
                        "type": "->",
                        "args": [
                            {
                                "id": 13,
                                "__class__": "OCA\\Mail\\Db\\LocalMessage"
                            },
                            {
                                "__class__": "OCA\\Mail\\Account"
                            }
                        ]
                    },
                    {
                        "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
                        "line": 55,
                        "function": "flush",
                        "class": "OCA\\Mail\\Service\\OutboxService",
                        "type": "->",
                        "args": []
                    },
                    {
                        "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
                        "line": 79,
                        "function": "run",
                        "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
                        "type": "->",
                        "args": [
                            null
                        ]
                    },
                    {
                        "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                        "line": 95,
                        "function": "execute",
                        "class": "OCP\\BackgroundJob\\Job",
                        "type": "->",
                        "args": [
                            {
                                "__class__": "OC\\BackgroundJob\\JobList"
                            },
                            {
                                "__class__": "OC\\Log"
                            }
                        ]
                    },
                    {
                        "file": "/var/www/html/cron.php",
                        "line": 149,
                        "function": "execute",
                        "class": "OCP\\BackgroundJob\\TimedJob",
                        "type": "->",
                        "args": [
                            {
                                "__class__": "OC\\BackgroundJob\\JobList"
                            },
                            {
                                "__class__": "OC\\Log"
                            }
                        ]
                    }
                ],
                "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mail/Horde/Mail/Transport/Smtphorde.php",
                "Line": 145,
                "Previous": {
                    "Exception": "Horde_Smtp_Exception",
                    "Message": "Error when communicating with the server.",
                    "Code": 2,
                    "Trace": [
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
                            "line": 1028,
                            "function": "read",
                            "class": "Horde_Smtp_Connection",
                            "type": "->",
                            "args": []
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
                            "line": 1094,
                            "function": "_getResponse",
                            "class": "Horde_Smtp",
                            "type": "->",
                            "args": [
                                250,
                                {
                                    "error": "reset",
                                    "exception": "Horde_Smtp_Exception"
                                }
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
                            "line": 739,
                            "function": "_processData",
                            "class": "Horde_Smtp",
                            "type": "->",
                            "args": [
                                [
                                    "[REDACTED RECIPIENT ADDRESS]",
                                    "[REDACTED CC ADDRESS]"
                                ]
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mail/Horde/Mail/Transport/Smtphorde.php",
                            "line": 143,
                            "function": "send",
                            "class": "Horde_Smtp",
                            "type": "->",
                            "args": [
                                {
                                    "comment": [],
                                    "mailbox": "simon.nyssen",
                                    "__class__": "Horde_Mail_Rfc822_Address"
                                },
                                {
                                    "__class__": "Horde_Mail_Rfc822_List"
                                },
                                null
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
                            "line": 1620,
                            "function": "send",
                            "class": "Horde_Mail_Transport_Smtphorde",
                            "type": "->",
                            "args": [
                                "[REDACTED RECIPIENT ADDRESS], \"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\" <[REDACTED CC ADDRESS]>",
                                {
                                    "From": "Simon Nyssen <[REDACTED SENDER]>",
                                    "To": "[REDACTED RECIPIENT ADDRESS]",
                                    "Cc": "\"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\"\n <[REDACTED CC ADDRESS]>",
                                    "Subject": "[REDACTED SUBJECT]",
                                    "Message-ID": "<20220524091009.Horde.eBwVMFBOPqCRSs3dHElUdYs@b00a8430f2d1>",
                                    "0": "And 5 more entries, set log level to debug to see all entries"
                                },
                                null
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
                            "line": 479,
                            "function": "send",
                            "class": "Horde_Mime_Part",
                            "type": "->",
                            "args": [
                                "[REDACTED RECIPIENT ADDRESS], \"[REDACTED CC NAME] ([REDACTED CC ADDRESS])\" <[REDACTED CC ADDRESS]>",
                                {
                                    "__class__": "Horde_Mime_Headers"
                                },
                                {
                                    "send8bit": false,
                                    "sep": "\r\n",
                                    "__class__": "Horde_Mail_Transport_Smtphorde"
                                }
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                            "line": 208,
                            "function": "send",
                            "class": "Horde_Mime_Mail",
                            "type": "->",
                            "args": [
                                {
                                    "send8bit": false,
                                    "sep": "\r\n",
                                    "__class__": "Horde_Mail_Transport_Smtphorde"
                                },
                                false,
                                false
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
                            "line": 271,
                            "function": "sendMessage",
                            "class": "OCA\\Mail\\Service\\MailTransmission",
                            "type": "->",
                            "args": [
                                {
                                    "__class__": "OCA\\Mail\\Model\\NewMessageData"
                                },
                                null,
                                null
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                            "line": 129,
                            "function": "sendLocalMessage",
                            "class": "OCA\\Mail\\Service\\MailTransmission",
                            "type": "->",
                            "args": [
                                {
                                    "__class__": "OCA\\Mail\\Account"
                                },
                                {
                                    "id": 13,
                                    "__class__": "OCA\\Mail\\Db\\LocalMessage"
                                }
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
                            "line": 196,
                            "function": "sendMessage",
                            "class": "OCA\\Mail\\Service\\OutboxService",
                            "type": "->",
                            "args": [
                                {
                                    "id": 13,
                                    "__class__": "OCA\\Mail\\Db\\LocalMessage"
                                },
                                {
                                    "__class__": "OCA\\Mail\\Account"
                                }
                            ]
                        },
                        {
                            "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
                            "line": 55,
                            "function": "flush",
                            "class": "OCA\\Mail\\Service\\OutboxService",
                            "type": "->",
                            "args": []
                        },
                        {
                            "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
                            "line": 79,
                            "function": "run",
                            "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
                            "type": "->",
                            "args": [
                                null
                            ]
                        },
                        {
                            "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                            "line": 95,
                            "function": "execute",
                            "class": "OCP\\BackgroundJob\\Job",
                            "type": "->",
                            "args": [
                                {
                                    "__class__": "OC\\BackgroundJob\\JobList"
                                },
                                {
                                    "__class__": "OC\\Log"
                                }
                            ]
                        },
                        {
                            "file": "/var/www/html/cron.php",
                            "line": 149,
                            "function": "execute",
                            "class": "OCP\\BackgroundJob\\TimedJob",
                            "type": "->",
                            "args": [
                                {
                                    "__class__": "OC\\BackgroundJob\\JobList"
                                },
                                {
                                    "__class__": "OC\\Log"
                                }
                            ]
                        }
                    ],
                    "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp/Connection.php",
                    "Line": 130
                }
            }
        },
        "CustomMessage": "Could not send outbox message 13: Could not send message: Error when communicating with the server."
    }
}

It might still be a problem with Mailfence, I have had a lot of problem with this provider that I still cannot fix, mostly mails that I can't open in Nextcloud.

@snyssen
Copy link
Author

snyssen commented May 24, 2022

As a user you should be able to see the message in your Outbox and delete it from there.

The outbox folder does indeed indicate that there is an e-mail in it, but no e-mail is loaded when I try to get into it:
image

I think this is the related log line:

{
    "reqId": "tw2AFFLiwefGk9MpqEK0",
    "level": 3,
    "time": "2022-05-24T13:36:56+00:00",
    "remoteAddr": "172.20.0.4",
    "user": "snyssen",
    "app": "PHP",
    "method": "POST",
    "url": "/apps/mail/api/mailboxes/48/sync",
    "message": "Undefined array key 18661 at /var/www/html/custom_apps/mail/lib/Cache/Cache.php#147",
    "userAgent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.162 Safari/537.36",
    "version": "22.2.6.2",
    "exception": {
        "Exception": "Error",
        "Message": "Undefined array key 18661 at /var/www/html/custom_apps/mail/lib/Cache/Cache.php#147",
        "Code": 0,
        "Trace": [
            {
                "file": "/var/www/html/custom_apps/mail/lib/Cache/Cache.php",
                "line": 147,
                "function": "onError",
                "class": "OC\\Log\\ErrorHandler",
                "type": "::",
                "args": [
                    2,
                    "Undefined array key 18661",
                    "/var/www/html/custom_apps/mail/lib/Cache/Cache.php",
                    147
                ]
            },
            {
                "function": "save",
                "class": "OCA\\Mail\\Cache\\Cache",
                "type": "->",
                "args": []
            }
        ],
        "File": "/var/www/html/lib/private/Log/ErrorHandler.php",
        "Line": 92,
        "CustomMessage": "--"
    }
}

Is there another way I could remove the offending e-mail ?

@ChristophWurst
Copy link
Member

ChristophWurst commented May 24, 2022

SELECT * FROM oc_mail_local_messages WHERE account_id=<id> to find the row for your account

@ChristophWurst
Copy link
Member

Error when communicating with the server.

Has it always logged that for each resend?

Your inbox might not show due to a front-end issue. Open the browser console to check. I suspect something like to.map is not a function.

We will release v1.12.1 in a few minutes. It should help with this front-end issue.

@ChristophWurst
Copy link
Member

The bug I had in mind happened when the message has CC/BCC recipients.

@snyssen
Copy link
Author

snyssen commented May 24, 2022

I was able to remove the e-mail with DELETE FROM oc_mail_local_messages WHERE account_id=<id> since the only record coming out of your query was for the offending e-mail, thank you. I then refreshed the e-mail app and it worked as expected, so I can't tell if there were any error in the browser console, sorry.

Error when communicating with the server.

Has it always logged that for each resend?

Seems like it did:
image
Though a strange thing is that if you look at the screenshot, the first time it tried to send the e-mail it registered an error, while every other time it only registered as a warning. And well, I say "tried to send the e-mail", but each time the e-mail was actually sent, this is how I actually realized something was wrong, because the recipient called me asking why I was spamming their inbox ^^"

The bug I had in mind happened when the message has CC/BCC recipients.

There was actually someone in CC, so it might be it.

@ChristophWurst
Copy link
Member

because the recipient called me asking why I was spamming their inbox

I'm so sorry 🙈

@ChristophWurst
Copy link
Member

The error happens at https://github.com/horde/Smtp/blob/master/lib/Horde/Smtp/Connection.php#L128-L134. This is after sending the message to SMTP, when the Horde libs check for the server response.

So right at the end of sending the connection must time out each time.

@ChristophWurst
Copy link
Member

Are you possibly able to trigger the error loop another time with an email to yourself? I am wondering how this could be reproducible. Was there anything specific about the message? Size, perhaps? @michal0202 yours was a larger one, right? And the app ran into the same SMTP read error.

If you can reproduce, please enable debug mode until the next cron execution, then check data/horde_smtp.log contents for the SMTP communication log.

@snyssen
Copy link
Author

snyssen commented May 24, 2022

because the recipient called me asking why I was spamming their inbox

I'm so sorry see_no_evil

Haha no worry I found it actually quite funny 😁

@snyssen
Copy link
Author

snyssen commented May 24, 2022

Are you possibly able to trigger the error loop another time with an email to yourself? I am wondering how this could be reproducible. Was there anything specific about the message? Size, perhaps? @michal0202 yours was a larger one, right? And the app ran into the same SMTP read error.

If you can reproduce, please enable debug mode until the next cron execution, then check data/horde_smtp.log contents for the SMTP communication log.

Yes of course, I'll try to do this tonight or tomorrow 😄

@michal0202
Copy link

michal0202 commented May 25, 2022

Are you possibly able to trigger the error loop another time with an email to yourself? I am wondering how this could be reproducible. Was there anything specific about the message? Size, perhaps? @michal0202 yours was a larger one, right? And the app ran into the same SMTP read error.

If you can reproduce, please enable debug mode until the next cron execution, then check data/horde_smtp.log contents for the SMTP communication log.

I can trigger error loops to send messages to myself. The only requirement is that the server of one of the recipients cannot receive such a large message. I sent a message to myself with an attachment of 321MB. My first account[TO] accepts these attachments, but 2 on gmail[UDW] do not. The error loop has started. Now all the time this message is sent to both the account that accepts it and the account that it rejects. I don't have the file data/horde_smtp.log after turning on debug mode. However, I have a database record of this message and a debug log nextcloud file.

obraz
obraz
nextcloud_mail.log

@snyssen
Copy link
Author

snyssen commented May 30, 2022

I had a busy week so I wasn't able to try to trigger the bug again until today.

I first tried to simply have a CC'd email but this does not seem to trigger the issue (and I should have guessed as it would have happened to me a lot then). Then I tried 4 attached images, each between 3 and 5 MB in size, and this time the loop was triggered "correctly", so it indeed seems to be linked to attachments. However, as for @michal0202, the horde_smtp.log file did not contain any useful log. The only log I saw there was from a previous test where I attached a 357 MB zip file, but this one never got through as it was obviously way to big (that makes me think that the client should maybe have a warning when trying to send files that are obviously too big for any email server).

I don't know if it can helps as I guess it is still the same error as before, but here is the error log from my test:

{
  "reqId": "aW0ozprtTNhrp5ae3V4a",
  "level": 2,
  "time": "2022-05-30T06:35:19+00:00",
  "remoteAddr": "",
  "user": "--",
  "app": "mail",
  "method": "",
  "url": "--",
  "message": "Could not send outbox message 21: Could not send message: Error when communicating with the server.",
  "userAgent": "--",
  "version": "23.0.5.1",
  "exception": {
    "Exception": "OCA\\Mail\\Exception\\ServiceException",
    "Message": "Could not send message: Error when communicating with the server.",
    "Code": 2,
    "Trace": [
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
        "line": 277,
        "function": "sendMessage",
        "class": "OCA\\Mail\\Service\\MailTransmission",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Model\\NewMessageData"
          },
          null,
          null
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
        "line": 129,
        "function": "sendLocalMessage",
        "class": "OCA\\Mail\\Service\\MailTransmission",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Account"
          },
          {
            "__class__": "OCA\\Mail\\Db\\LocalMessage",
            "id": 21
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
        "line": 196,
        "function": "sendMessage",
        "class": "OCA\\Mail\\Service\\OutboxService",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Db\\LocalMessage",
            "id": 21
          },
          {
            "__class__": "OCA\\Mail\\Account"
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
        "line": 55,
        "function": "flush",
        "class": "OCA\\Mail\\Service\\OutboxService",
        "type": "->",
        "args": []
      },
      {
        "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
        "line": 79,
        "function": "run",
        "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
        "type": "->",
        "args": [
          null
        ]
      },
      {
        "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
        "line": 95,
        "function": "execute",
        "class": "OCP\\BackgroundJob\\Job",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\BackgroundJob\\JobList"
          },
          {
            "__class__": "OC\\Log"
          }
        ]
      },
      {
        "file": "/var/www/html/cron.php",
        "line": 151,
        "function": "execute",
        "class": "OCP\\BackgroundJob\\TimedJob",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\BackgroundJob\\JobList"
          },
          {
            "__class__": "OC\\Log"
          }
        ]
      }
    ],
    "File": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
    "Line": 211,
    "Previous": {
      "Exception": "Horde_Mime_Exception",
      "Message": "Error when communicating with the server.",
      "Code": 2,
      "Trace": [
        {
          "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
          "line": 479,
          "function": "send",
          "class": "Horde_Mime_Part",
          "type": "->",
          "args": [
            "simon.nyssen@outlook.com",
            {
              "__class__": "Horde_Mime_Headers"
            },
            {
              "__class__": "Horde_Mail_Transport_Smtphorde",
              "send8bit": false,
              "sep": "\r\n"
            }
          ]
        },
        {
          "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
          "line": 209,
          "function": "send",
          "class": "Horde_Mime_Mail",
          "type": "->",
          "args": [
            {
              "__class__": "Horde_Mail_Transport_Smtphorde",
              "send8bit": false,
              "sep": "\r\n"
            },
            false,
            false
          ]
        },
        {
          "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
          "line": 277,
          "function": "sendMessage",
          "class": "OCA\\Mail\\Service\\MailTransmission",
          "type": "->",
          "args": [
            {
              "__class__": "OCA\\Mail\\Model\\NewMessageData"
            },
            null,
            null
          ]
        },
        {
          "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
          "line": 129,
          "function": "sendLocalMessage",
          "class": "OCA\\Mail\\Service\\MailTransmission",
          "type": "->",
          "args": [
            {
              "__class__": "OCA\\Mail\\Account"
            },
            {
              "__class__": "OCA\\Mail\\Db\\LocalMessage",
              "id": 21
            }
          ]
        },
        {
          "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
          "line": 196,
          "function": "sendMessage",
          "class": "OCA\\Mail\\Service\\OutboxService",
          "type": "->",
          "args": [
            {
              "__class__": "OCA\\Mail\\Db\\LocalMessage",
              "id": 21
            },
            {
              "__class__": "OCA\\Mail\\Account"
            }
          ]
        },
        {
          "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
          "line": 55,
          "function": "flush",
          "class": "OCA\\Mail\\Service\\OutboxService",
          "type": "->",
          "args": []
        },
        {
          "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
          "line": 79,
          "function": "run",
          "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
          "type": "->",
          "args": [
            null
          ]
        },
        {
          "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
          "line": 95,
          "function": "execute",
          "class": "OCP\\BackgroundJob\\Job",
          "type": "->",
          "args": [
            {
              "__class__": "OC\\BackgroundJob\\JobList"
            },
            {
              "__class__": "OC\\Log"
            }
          ]
        },
        {
          "file": "/var/www/html/cron.php",
          "line": 151,
          "function": "execute",
          "class": "OCP\\BackgroundJob\\TimedJob",
          "type": "->",
          "args": [
            {
              "__class__": "OC\\BackgroundJob\\JobList"
            },
            {
              "__class__": "OC\\Log"
            }
          ]
        }
      ],
      "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
      "Line": 1642,
      "Previous": {
        "Exception": "Horde_Mail_Exception",
        "Message": "Error when communicating with the server.",
        "Code": 2,
        "Trace": [
          {
            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
            "line": 1620,
            "function": "send",
            "class": "Horde_Mail_Transport_Smtphorde",
            "type": "->",
            "args": [
              "simon.nyssen@outlook.com",
              {
                "0": "And 5 more entries, set log level to debug to see all entries",
                "From": "Simon Nyssen <simon.nyssen@mailfence.com>",
                "To": "simon.nyssen@outlook.com",
                "Cc": "",
                "Subject": "[TEST] E-mail is re-sent again on each background job update #6540",
                "Message-ID": "<20220530063509.Horde.sE5hNtUNOI-htnH00oNjkiM@f874f6636a18>"
              },
              null
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
            "line": 479,
            "function": "send",
            "class": "Horde_Mime_Part",
            "type": "->",
            "args": [
              "simon.nyssen@outlook.com",
              {
                "__class__": "Horde_Mime_Headers"
              },
              {
                "__class__": "Horde_Mail_Transport_Smtphorde",
                "send8bit": false,
                "sep": "\r\n"
              }
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
            "line": 209,
            "function": "send",
            "class": "Horde_Mime_Mail",
            "type": "->",
            "args": [
              {
                "__class__": "Horde_Mail_Transport_Smtphorde",
                "send8bit": false,
                "sep": "\r\n"
              },
              false,
              false
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
            "line": 277,
            "function": "sendMessage",
            "class": "OCA\\Mail\\Service\\MailTransmission",
            "type": "->",
            "args": [
              {
                "__class__": "OCA\\Mail\\Model\\NewMessageData"
              },
              null,
              null
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
            "line": 129,
            "function": "sendLocalMessage",
            "class": "OCA\\Mail\\Service\\MailTransmission",
            "type": "->",
            "args": [
              {
                "__class__": "OCA\\Mail\\Account"
              },
              {
                "__class__": "OCA\\Mail\\Db\\LocalMessage",
                "id": 21
              }
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
            "line": 196,
            "function": "sendMessage",
            "class": "OCA\\Mail\\Service\\OutboxService",
            "type": "->",
            "args": [
              {
                "__class__": "OCA\\Mail\\Db\\LocalMessage",
                "id": 21
              },
              {
                "__class__": "OCA\\Mail\\Account"
              }
            ]
          },
          {
            "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
            "line": 55,
            "function": "flush",
            "class": "OCA\\Mail\\Service\\OutboxService",
            "type": "->",
            "args": []
          },
          {
            "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
            "line": 79,
            "function": "run",
            "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
            "type": "->",
            "args": [
              null
            ]
          },
          {
            "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
            "line": 95,
            "function": "execute",
            "class": "OCP\\BackgroundJob\\Job",
            "type": "->",
            "args": [
              {
                "__class__": "OC\\BackgroundJob\\JobList"
              },
              {
                "__class__": "OC\\Log"
              }
            ]
          },
          {
            "file": "/var/www/html/cron.php",
            "line": 151,
            "function": "execute",
            "class": "OCP\\BackgroundJob\\TimedJob",
            "type": "->",
            "args": [
              {
                "__class__": "OC\\BackgroundJob\\JobList"
              },
              {
                "__class__": "OC\\Log"
              }
            ]
          }
        ],
        "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mail/Horde/Mail/Transport/Smtphorde.php",
        "Line": 145,
        "Previous": {
          "Exception": "Horde_Smtp_Exception",
          "Message": "Error when communicating with the server.",
          "Code": 2,
          "Trace": [
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
              "line": 1028,
              "function": "read",
              "class": "Horde_Smtp_Connection",
              "type": "->",
              "args": []
            },
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
              "line": 1094,
              "function": "_getResponse",
              "class": "Horde_Smtp",
              "type": "->",
              "args": [
                250,
                {
                  "error": "reset",
                  "exception": "Horde_Smtp_Exception"
                }
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp.php",
              "line": 739,
              "function": "_processData",
              "class": "Horde_Smtp",
              "type": "->",
              "args": [
                [
                  "simon.nyssen@outlook.com"
                ]
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mail/Horde/Mail/Transport/Smtphorde.php",
              "line": 143,
              "function": "send",
              "class": "Horde_Smtp",
              "type": "->",
              "args": [
                {
                  "__class__": "Horde_Mail_Rfc822_Address",
                  "comment": [],
                  "mailbox": "simon.nyssen"
                },
                {
                  "__class__": "Horde_Mail_Rfc822_List"
                },
                null
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Part.php",
              "line": 1620,
              "function": "send",
              "class": "Horde_Mail_Transport_Smtphorde",
              "type": "->",
              "args": [
                "simon.nyssen@outlook.com",
                {
                  "0": "And 5 more entries, set log level to debug to see all entries",
                  "From": "Simon Nyssen <simon.nyssen@mailfence.com>",
                  "To": "simon.nyssen@outlook.com",
                  "Cc": "",
                  "Subject": "[TEST] E-mail is re-sent again on each background job update #6540",
                  "Message-ID": "<20220530063509.Horde.sE5hNtUNOI-htnH00oNjkiM@f874f6636a18>"
                },
                null
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Mime/Horde/Mime/Mail.php",
              "line": 479,
              "function": "send",
              "class": "Horde_Mime_Part",
              "type": "->",
              "args": [
                "simon.nyssen@outlook.com",
                {
                  "__class__": "Horde_Mime_Headers"
                },
                {
                  "__class__": "Horde_Mail_Transport_Smtphorde",
                  "send8bit": false,
                  "sep": "\r\n"
                }
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
              "line": 209,
              "function": "send",
              "class": "Horde_Mime_Mail",
              "type": "->",
              "args": [
                {
                  "__class__": "Horde_Mail_Transport_Smtphorde",
                  "send8bit": false,
                  "sep": "\r\n"
                },
                false,
                false
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
              "line": 277,
              "function": "sendMessage",
              "class": "OCA\\Mail\\Service\\MailTransmission",
              "type": "->",
              "args": [
                {
                  "__class__": "OCA\\Mail\\Model\\NewMessageData"
                },
                null,
                null
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
              "line": 129,
              "function": "sendLocalMessage",
              "class": "OCA\\Mail\\Service\\MailTransmission",
              "type": "->",
              "args": [
                {
                  "__class__": "OCA\\Mail\\Account"
                },
                {
                  "__class__": "OCA\\Mail\\Db\\LocalMessage",
                  "id": 21
                }
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
              "line": 196,
              "function": "sendMessage",
              "class": "OCA\\Mail\\Service\\OutboxService",
              "type": "->",
              "args": [
                {
                  "__class__": "OCA\\Mail\\Db\\LocalMessage",
                  "id": 21
                },
                {
                  "__class__": "OCA\\Mail\\Account"
                }
              ]
            },
            {
              "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
              "line": 55,
              "function": "flush",
              "class": "OCA\\Mail\\Service\\OutboxService",
              "type": "->",
              "args": []
            },
            {
              "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
              "line": 79,
              "function": "run",
              "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
              "type": "->",
              "args": [
                null
              ]
            },
            {
              "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
              "line": 95,
              "function": "execute",
              "class": "OCP\\BackgroundJob\\Job",
              "type": "->",
              "args": [
                {
                  "__class__": "OC\\BackgroundJob\\JobList"
                },
                {
                  "__class__": "OC\\Log"
                }
              ]
            },
            {
              "file": "/var/www/html/cron.php",
              "line": 151,
              "function": "execute",
              "class": "OCP\\BackgroundJob\\TimedJob",
              "type": "->",
              "args": [
                {
                  "__class__": "OC\\BackgroundJob\\JobList"
                },
                {
                  "__class__": "OC\\Log"
                }
              ]
            }
          ],
          "File": "/var/www/html/custom_apps/mail/vendor/pear-pear.horde.org/Horde_Smtp/Horde/Smtp/Connection.php",
          "Line": 130
        }
      }
    },
    "CustomMessage": "Could not send outbox message 21: Could not send message: Error when communicating with the server."
  },
  "id": "629465a8053ca"
}

@ChristophWurst
Copy link
Member

that makes me think that the client should maybe have a warning when trying to send files that are obviously too big for any email server

https://github.com/nextcloud/mail/blob/main/doc/admin.md#attachment-size-limit but it's not set by default.

@cappuMUC
Copy link

I had the same issue today. My health insurance called me and asked why I've sent them my filled out form over 200 times over the last weekend. 😁 In my case, I dont't think it has something to do with the size of my attached PDF document (about 3.5MB). It seems more likely that there went something wrong with the recipients email address.

{
  "reqId": "RlpvI0rS1Kl0NEksvM1R",
  "level": 2,
  "time": "2022-05-30T04:45:05+00:00",
  "remoteAddr": "",
  "user": "--",
  "app": "mail",
  "method": "",
  "url": "--",
  "message": "Error while collecting mail addresses: TypeError: OCA\\Mail\\Db\\CollectedAddressMapper::exists(): Argument #1 ($userId) must be of type string, null given, called in /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php on line 85 and defined in /var/www/html/custom_apps/mail/lib/Db/CollectedAddressMapper.php:68\nStack trace:\n#0 /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php(85): OCA\\Mail\\Db\\CollectedAddressMapper->exists(NULL, 'sandra.brauer@b...')\n#1 /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php(65): OCA\\Mail\\Service\\AutoCompletion\\AddressCollector->saveAddress(Object(OCA\\Mail\\Address))\n#2 /var/www/html/custom_apps/mail/lib/Listener/AddressCollectionListener.php(71): OCA\\Mail\\Service\\AutoCompletion\\AddressCollector->addAddresses(Object(OCA\\Mail\\AddressList))\n#3 /var/www/html/lib/private/EventDispatcher/ServiceEventListener.php(87): OCA\\Mail\\Listener\\AddressCollectionListener->handle(Object(OCA\\Mail\\Events\\MessageSentEvent))\n#4 /var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php(251): OC\\EventDispatcher\\ServiceEventListener->__invoke(Object(OCA\\Mail\\Events\\MessageSentEvent), 'OCA\\\\Mail\\\\Events...', Object(Symfony\\Component\\EventDispatcher\\EventDispatcher))\n#5 /var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php(73): Symfony\\Component\\EventDispatcher\\EventDispatcher->callListeners(Array, 'OCA\\\\Mail\\\\Events...', Object(OCA\\Mail\\Events\\MessageSentEvent))\n#6 /var/www/html/lib/private/EventDispatcher/EventDispatcher.php(88): Symfony\\Component\\EventDispatcher\\EventDispatcher->dispatch(Object(OCA\\Mail\\Events\\MessageSentEvent), 'OCA\\\\Mail\\\\Events...')\n#7 /var/www/html/lib/private/EventDispatcher/EventDispatcher.php(100): OC\\EventDispatcher\\EventDispatcher->dispatch('OCA\\\\Mail\\\\Events...', Object(OCA\\Mail\\Events\\MessageSentEvent))\n#8 /var/www/html/custom_apps/mail/lib/Service/MailTransmission.php(219): OC\\EventDispatcher\\EventDispatcher->dispatchTyped(Object(OCA\\Mail\\Events\\MessageSentEvent))\n#9 /var/www/html/custom_apps/mail/lib/Service/MailTransmission.php(277): OCA\\Mail\\Service\\MailTransmission->sendMessage(Object(OCA\\Mail\\Model\\NewMessageData), NULL, NULL)\n#10 /var/www/html/custom_apps/mail/lib/Service/OutboxService.php(129): OCA\\Mail\\Service\\MailTransmission->sendLocalMessage(Object(OCA\\Mail\\Account), Object(OCA\\Mail\\Db\\LocalMessage))\n#11 /var/www/html/custom_apps/mail/lib/Service/OutboxService.php(196): OCA\\Mail\\Service\\OutboxService->sendMessage(Object(OCA\\Mail\\Db\\LocalMessage), Object(OCA\\Mail\\Account))\n#12 /var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php(55): OCA\\Mail\\Service\\OutboxService->flush()\n#13 /var/www/html/lib/public/BackgroundJob/Job.php(79): OCA\\Mail\\BackgroundJob\\OutboxWorkerJob->run(NULL)\n#14 /var/www/html/lib/public/BackgroundJob/TimedJob.php(95): OCP\\BackgroundJob\\Job->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#15 /var/www/html/cron.php(151): OCP\\BackgroundJob\\TimedJob->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#16 {main}",
  "userAgent": "--",
  "version": "24.0.0.12",
  "exception": {
    "Exception": "TypeError",
    "Message": "OCA\\Mail\\Db\\CollectedAddressMapper::exists(): Argument #1 ($userId) must be of type string, null given, called in /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php on line 85",
    "Code": 0,
    "Trace": [
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php",
        "line": 85,
        "function": "exists",
        "class": "OCA\\Mail\\Db\\CollectedAddressMapper",
        "type": "->",
        "args": [
          null,
          "email@address.to"
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php",
        "line": 65,
        "function": "saveAddress",
        "class": "OCA\\Mail\\Service\\AutoCompletion\\AddressCollector",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Address"
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Listener/AddressCollectionListener.php",
        "line": 71,
        "function": "addAddresses",
        "class": "OCA\\Mail\\Service\\AutoCompletion\\AddressCollector",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\AddressList"
          }
        ]
      },
      {
        "file": "/var/www/html/lib/private/EventDispatcher/ServiceEventListener.php",
        "line": 87,
        "function": "handle",
        "class": "OCA\\Mail\\Listener\\AddressCollectionListener",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          }
        ]
      },
      {
        "file": "/var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
        "line": 251,
        "function": "__invoke",
        "class": "OC\\EventDispatcher\\ServiceEventListener",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          },
          "OCA\\Mail\\Events\\MessageSentEvent",
          {
            "__class__": "Symfony\\Component\\EventDispatcher\\EventDispatcher"
          }
        ]
      },
      {
        "file": "/var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
        "line": 73,
        "function": "callListeners",
        "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          [
            {
              "__class__": "Closure"
            },
            {
              "__class__": "Closure"
            },
            {
              "__class__": "Closure"
            },
            {
              "__class__": "Closure"
            }
          ],
          "OCA\\Mail\\Events\\MessageSentEvent",
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          }
        ]
      },
      {
        "file": "/var/www/html/lib/private/EventDispatcher/EventDispatcher.php",
        "line": 88,
        "function": "dispatch",
        "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          },
          "OCA\\Mail\\Events\\MessageSentEvent"
        ]
      },
      {
        "file": "/var/www/html/lib/private/EventDispatcher/EventDispatcher.php",
        "line": 100,
        "function": "dispatch",
        "class": "OC\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          "OCA\\Mail\\Events\\MessageSentEvent",
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
        "line": 219,
        "function": "dispatchTyped",
        "class": "OC\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Events\\MessageSentEvent"
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/MailTransmission.php",
        "line": 277,
        "function": "sendMessage",
        "class": "OCA\\Mail\\Service\\MailTransmission",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Model\\NewMessageData"
          },
          null,
          null
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
        "line": 129,
        "function": "sendLocalMessage",
        "class": "OCA\\Mail\\Service\\MailTransmission",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Account"
          },
          {
            "__class__": "OCA\\Mail\\Db\\LocalMessage",
            "id": 2
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/Service/OutboxService.php",
        "line": 196,
        "function": "sendMessage",
        "class": "OCA\\Mail\\Service\\OutboxService",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Mail\\Db\\LocalMessage",
            "id": 2
          },
          {
            "__class__": "OCA\\Mail\\Account"
          }
        ]
      },
      {
        "file": "/var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php",
        "line": 55,
        "function": "flush",
        "class": "OCA\\Mail\\Service\\OutboxService",
        "type": "->",
        "args": []
      },
      {
        "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
        "line": 79,
        "function": "run",
        "class": "OCA\\Mail\\BackgroundJob\\OutboxWorkerJob",
        "type": "->",
        "args": [
          null
        ]
      },
      {
        "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
        "line": 95,
        "function": "execute",
        "class": "OCP\\BackgroundJob\\Job",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\BackgroundJob\\JobList"
          },
          {
            "__class__": "OC\\Log"
          }
        ]
      },
      {
        "file": "/var/www/html/cron.php",
        "line": 151,
        "function": "execute",
        "class": "OCP\\BackgroundJob\\TimedJob",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\BackgroundJob\\JobList"
          },
          {
            "__class__": "OC\\Log"
          }
        ]
      }
    ],
    "File": "/var/www/html/custom_apps/mail/lib/Db/CollectedAddressMapper.php",
    "Line": 68,
    "CustomMessage": "Error while collecting mail addresses: TypeError: OCA\\Mail\\Db\\CollectedAddressMapper::exists(): Argument #1 ($userId) must be of type string, null given, called in /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php on line 85 and defined in /var/www/html/custom_apps/mail/lib/Db/CollectedAddressMapper.php:68\nStack trace:\n#0 /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php(85): OCA\\Mail\\Db\\CollectedAddressMapper->exists(NULL, 'sandra.brauer@b...')\n#1 /var/www/html/custom_apps/mail/lib/Service/AutoCompletion/AddressCollector.php(65): OCA\\Mail\\Service\\AutoCompletion\\AddressCollector->saveAddress(Object(OCA\\Mail\\Address))\n#2 /var/www/html/custom_apps/mail/lib/Listener/AddressCollectionListener.php(71): OCA\\Mail\\Service\\AutoCompletion\\AddressCollector->addAddresses(Object(OCA\\Mail\\AddressList))\n#3 /var/www/html/lib/private/EventDispatcher/ServiceEventListener.php(87): OCA\\Mail\\Listener\\AddressCollectionListener->handle(Object(OCA\\Mail\\Events\\MessageSentEvent))\n#4 /var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php(251): OC\\EventDispatcher\\ServiceEventListener->__invoke(Object(OCA\\Mail\\Events\\MessageSentEvent), 'OCA\\\\Mail\\\\Events...', Object(Symfony\\Component\\EventDispatcher\\EventDispatcher))\n#5 /var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php(73): Symfony\\Component\\EventDispatcher\\EventDispatcher->callListeners(Array, 'OCA\\\\Mail\\\\Events...', Object(OCA\\Mail\\Events\\MessageSentEvent))\n#6 /var/www/html/lib/private/EventDispatcher/EventDispatcher.php(88): Symfony\\Component\\EventDispatcher\\EventDispatcher->dispatch(Object(OCA\\Mail\\Events\\MessageSentEvent), 'OCA\\\\Mail\\\\Events...')\n#7 /var/www/html/lib/private/EventDispatcher/EventDispatcher.php(100): OC\\EventDispatcher\\EventDispatcher->dispatch('OCA\\\\Mail\\\\Events...', Object(OCA\\Mail\\Events\\MessageSentEvent))\n#8 /var/www/html/custom_apps/mail/lib/Service/MailTransmission.php(219): OC\\EventDispatcher\\EventDispatcher->dispatchTyped(Object(OCA\\Mail\\Events\\MessageSentEvent))\n#9 /var/www/html/custom_apps/mail/lib/Service/MailTransmission.php(277): OCA\\Mail\\Service\\MailTransmission->sendMessage(Object(OCA\\Mail\\Model\\NewMessageData), NULL, NULL)\n#10 /var/www/html/custom_apps/mail/lib/Service/OutboxService.php(129): OCA\\Mail\\Service\\MailTransmission->sendLocalMessage(Object(OCA\\Mail\\Account), Object(OCA\\Mail\\Db\\LocalMessage))\n#11 /var/www/html/custom_apps/mail/lib/Service/OutboxService.php(196): OCA\\Mail\\Service\\OutboxService->sendMessage(Object(OCA\\Mail\\Db\\LocalMessage), Object(OCA\\Mail\\Account))\n#12 /var/www/html/custom_apps/mail/lib/BackgroundJob/OutboxWorkerJob.php(55): OCA\\Mail\\Service\\OutboxService->flush()\n#13 /var/www/html/lib/public/BackgroundJob/Job.php(79): OCA\\Mail\\BackgroundJob\\OutboxWorkerJob->run(NULL)\n#14 /var/www/html/lib/public/BackgroundJob/TimedJob.php(95): OCP\\BackgroundJob\\Job->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#15 /var/www/html/cron.php(151): OCP\\BackgroundJob\\TimedJob->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#16 {main}"
  },
  "id": "6294d029f2d6c"
}

@ChristophWurst
Copy link
Member

@cappuMUC I'm sorry this happened. Your error should be a lot easier to catch. We "just" have to store the state at which the error occurred. Here it was after the SMTP part. So we can assume safely assume the SMTP part to have worked already. If there is anything to resume/retry it's the parts after.

@ChristophWurst
Copy link
Member

I've stepped through your error @cappuMUC and the exception happens and gets logged, but doesn't error out the overall background send job.

@ChristophWurst
Copy link
Member

#6602 will help. I didn't test with large attachments but a simple wrong recipient. The email is now only sent one time until the user manually resends.

This kills the original idea that the background job works around temporary delivery failures but let's keep that feature aside for now and rather fix the repeatedly sent emails.

@snyssen
Copy link
Author

snyssen commented May 31, 2022

On a failed attempt the e-mail would stay in the outbox, wouldn't it? Meaning that if there is a temporary delivery failure the end user could still try to resend the e-mail manually, right? I think that would be okay for now at least

@ChristophWurst
Copy link
Member

Exactly. They will see that the message is "stuck" and can trigger another attempt.

@nilskamm
Copy link

nilskamm commented Jun 1, 2022

Hey! I have the same problem.
Our hosting partner uses an antivirus software to scan every mail before sending.
That process takes like 23 second.
Meanwhile all tested clients (Webmail, Thunderbird, BlueMail) show something like "Send mail... please wait".
The Nextcloud App instead just throws the mail into the Outbox and sends it every 10 minutes without moving it to the Sent folder.
In the postfix/smtp log from our hosting partner it shows this details about delays:

delay=25, delays=23/0/0.05/2, dsn=2.0.0, status=sent (250 OK id=ID)

I guess the problem for us is that it takes 23 seconds until the mail is queued ("delays=23").
In my case the mails are almost empty. Just a few words. No attachments.

Hope this information helps somehow.

@ChristophWurst
Copy link
Member

@nilskamm https://github.com/nextcloud/mail/blob/main/doc/admin.md#smtp-timeout will help your setup.

@nilskamm
Copy link

nilskamm commented Jun 1, 2022

I could solve my problem by changing the smtp-timeout. Thanks a lot!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Development

Successfully merging a pull request may close this issue.

5 participants