Mail: Infinite MailboxLockedError (error on INSERT into oc_mail_messages )

Created on 16 Apr 2020  ·  18Comments  ·  Source: nextcloud/mail

Expected behavior

I should have see my mails in the UI

Actual behavior

The spinner sticks there forever and I can see some infinite MailboxLockedError errors in the browser console.

I also see that in the server logs:

{"reqId":"YyhTlSOUGbMUTPVBMi8g","level":3,"time":"2020-04-16T18:02:45+00:00","remoteAddr":"************","user":"moz","app":"mail","method":"POST","url":"/apps/mail/api/accounts/1/folders/SU5CT1g%3D/sync","message":{"Exception":"OCA\\Mail\\Exception\\ServiceException","Message":"Sync failed for 1:INBOX: An exception occurred while executing 'INSERT INTO `oc_mail_messages` (`uid`, `message_id`, `mailbox_id`, `subject`, `sent_at`, `flag_answered`, `flag_deleted`, `flag_draft`, `flag_flagged`, `flag_seen`, `flag_forwarded`, `flag_junk`, `flag_notjunk`) VALUES(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)' with params [62445, \"<*******************@webgridb225.emsecure.net>\", 52, \"L'alliance, la bague de votre vie \\ud83d\\udc8d\", 1583253112, false, false, false, false, true, false, false, false]:\n\nSQLSTATE[22007]: Invalid datetime format: 1366 Incorrect string value: '\\xF0\\x9F\\x92\\x8D' for column `cloud`.`oc_mail_messages`.`subject` at row 1","Code":0,"Trace":[{"file":"/var/www/html/apps/mail/lib/Service/Sync/SyncService.php","line":107,"function":"sync","class":"OCA\\Mail\\Service\\Sync\\ImapToDbSynchronizer","type":"->" [...]

I guess the emoji in the subject breaks the script, which returns an HTTP 500 (I saw that in the console) and let the mailbox locked :(

Mail app

Mail app version: (see apps admin page, e.g. 0.5.3)

1.3.2

Mailserver or service: (e.g. Outlook, Yahoo, Gmail, Exchange,...)

Gandi

Server configuration

Operating system: (e.g. Debian 8)

Official Docker image

Database: (e.g. MariaDB, SQLite or PostgreSQL)

MariaDB 10.4.12

Nextcloud Version: (see admin page, e.g. 13.0.2)

18.0.1

Client configuration

Browser: (e.g. Firefox 48)

Firefox 75

Operating system: (e.g. Arch Linux)

Fedora

0. to triage bug
Source
picture GuillaumeAmat

All 18 comments

Invalid datetime format: 1366 Incorrect string value: '\xF0\x9F\x92\x8D' for column cloud.oc_mail_messages.subject

Ai. That is strange. Might be an encoding or casting issue.

ChristophWurst picture ChristophWurst on 16 Apr 2020

I'm getting this message in browser console (also Mailbox locked)

Failed to load resource: the server responded with a status of 409 (Conflict)
[INFO] mail: Mailbox is locked 
error: MailboxLockedError at t.convertAxiosError (https://nextcloud.ipz.hr/apps/mail/js/mail.js?v=babc828f-8:1526:291) at https://nextcloud.ipz.hr/apps/mail/js/mail.js?v=babc828f-8:692:8802 at async Promise.all (index 0)

In Nextcloud log

Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE "oc_mail_mailboxes" SET "sync_new_lock" = ?, "sync_changed_lock" = ?, "sync_vanished_lock" = ? WHERE "id" = ?' with params [1587063605, 1587063605, null, 677]: SQLSTATE[25P02]: In failed sql transaction: 7 ERROR: current transaction is aborted, commands ignored until end of transaction block
/var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php - line 169:

Doctrine\DBAL\Driver\AbstractPostgreSQLDriver->convertException("An exceptio ... k", Doctrine\DBA ... ]})

/var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php - line 145:

Doctrine\DBAL\DBALException::wrapException(Doctrine\DBA ... {}, Doctrine\DBA ... ]}, "An exceptio ... k")

/var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php - line 1063:

Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBA ... {}, Doctrine\DBA ... ]}, "UPDATE \"oc ... ?", { 1: 1587063 ... 7})

/var/www/nextcloud/lib/private/DB/Connection.php - line 220:

Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc ... ?", [ 1587063605 ... 7], [ 1,1,1,1])

/var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php - line 203:

OC\DB\Connection->executeUpdate("UPDATE \"oc ... 4", { dcValue1: ... 7}, { dcValue1: ... 1})

/var/www/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php - line 215:

Doctrine\DBAL\Query\QueryBuilder->execute()

/var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php - line 197:

OC\DB\QueryBuilder\QueryBuilder->execute()

/var/www/nextcloud/apps/mail/lib/Db/MailboxMapper.php - line 195:

OCP\AppFramework\Db\QBMapper->update("*** sensiti ... *")

/var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php - line 157:

OCA\Mail\Db\MailboxMapper->unlockFromVanishedSync("*** sensiti ... *")

/var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php - line 106:

OCA\Mail\Service\Sync\ImapToDbSynchronizer->sync(OCA\Mail\Account {}, "*** sensiti ... *", 42, null, false)

/var/www/nextcloud/apps/mail/lib/BackgroundJob/SyncJob.php - line 86:

OCA\Mail\Service\Sync\ImapToDbSynchronizer->syncAccount(OCA\Mail\Account {})

/var/www/nextcloud/lib/public/BackgroundJob/Job.php - line 79:

OCA\Mail\BackgroundJob\SyncJob->run({ accountId: 36})

/var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php - line 61:

OCP\BackgroundJob\Job->execute(OC\BackgroundJob\JobList {}, OC\Log {})

/var/www/nextcloud/cron.php - line 125:

OCP\BackgroundJob\TimedJob->execute(OC\BackgroundJob\JobList {}, OC\Log {})

MAIL v.1.3.2

zpintar picture zpintar on 16 Apr 2020

I can confirm i am facing the same problem with one of my mail accounts

scanno picture scanno on 16 Apr 2020

transaction is aborted, commands ignored until end of transaction block

@zpintar no necessarily the same issue. But could you please check for the previous error? Postgres fails here because the transaction was aborted. This means another command failed before that. This is not the actual issue.

ChristophWurst picture ChristophWurst on 17 Apr 2020

Invalid datetime format: 1366 Incorrect string value: 'xF0x9Fx92x8D' for column cloud.oc_mail_messages.subject

Ai. That is strange. Might be an encoding or casting issue.

On a second thought please make sure you are following https://docs.nextcloud.com/server/stable/admin_manual/configuration_database/mysql_4byte_support.html. A lack of multi byte support could explain why the db can't insert this data.

ChristophWurst picture ChristophWurst on 17 Apr 2020

transaction is aborted, commands ignored until end of transaction block

@zpintar no necessarily the same issue. But could you please check for the previous error? Postgres fails here because the transaction was aborted. This means another command failed before that. This is not the actual issue.

Ok, I'll check this, but why previous version of Mail app works well, and after this update to v1.3.x inbox doesn't work? What can be wrong on the same Nextcloud installation?

zpintar picture zpintar on 17 Apr 2020

Three errors always come at the same time in log: cron, core, and mail (in this order). There are listings:

[cron] Error: Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE "oc_jobs" SET "reserved_at" = '0' WHERE "id" = ?' with params [2833]:

SQLSTATE[25P02]: In failed sql transaction: 7 ERROR:  current transaction is aborted, commands ignored until end of transaction block at <<closure>>

0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 169
   Doctrine\DBAL\Driver\AbstractPostgreSQLDriver->convertException("An exception oc ... k", Doctrine\DBAL\Dr ... ]})
1. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 145
   Doctrine\DBAL\DBALException::wrapException(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "An exception oc ... k")
2. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php line 1063
   Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "UPDATE \"oc_job ... ?", {1: 2833})
3. /var/www/nextcloud/lib/private/DB/Connection.php line 220
   Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc_job ... ?", [2833], [1])
4. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php line 203
   OC\DB\Connection->executeUpdate("UPDATE \"oc_job ... 1", {dcValue1: 2833}, {dcValue1: 1})
5. /var/www/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php line 215
   Doctrine\DBAL\Query\QueryBuilder->execute()
6. /var/www/nextcloud/lib/private/BackgroundJob/JobList.php line 309
   OC\DB\QueryBuilder\QueryBuilder->execute()
7. /var/www/nextcloud/lib/private/BackgroundJob/JobList.php line 294
   OC\BackgroundJob\JobList->unlockJob(OCA\Mail\BackgroundJob\SyncJob {})
8. /var/www/nextcloud/cron.php line 129
   OC\BackgroundJob\JobList->setLastJob(OCA\Mail\BackgroundJob\SyncJob {})

at 2020-04-17T06:35:03+00:00


[core] Error: Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE "oc_jobs" SET "execution_duration" = ? WHERE "id" = ?' with params [2, 2833]:

SQLSTATE[25P02]: In failed sql transaction: 7 ERROR:  current transaction is aborted, commands ignored until end of transaction block at <<closure>>

0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 169
   Doctrine\DBAL\Driver\AbstractPostgreSQLDriver->convertException("An exception oc ... k", Doctrine\DBAL\Dr ... ]})
1. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 145
   Doctrine\DBAL\DBALException::wrapException(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "An exception oc ... k")
2. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php line 1063
   Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "UPDATE \"oc_job ... ?", {1: 2,2: 2833})
3. /var/www/nextcloud/lib/private/DB/Connection.php line 220
   Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc_job ... ?", [2,2833], [1,1])
4. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php line 203
   OC\DB\Connection->executeUpdate("UPDATE \"oc_job ... 2", {dcValue1: 2,dcValue2: 2833}, {dcValue1: 1,dcValue2: 1})
5. /var/www/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php line 215
   Doctrine\DBAL\Query\QueryBuilder->execute()
6. /var/www/nextcloud/lib/private/BackgroundJob/JobList.php line 346
   OC\DB\QueryBuilder\QueryBuilder->execute()
7. /var/www/nextcloud/lib/public/BackgroundJob/Job.php line 83
   OC\BackgroundJob\JobList->setExecutionTime(OCA\Mail\BackgroundJob\SyncJob {}, 2)
8. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 61
   OCP\BackgroundJob\Job->execute(OC\BackgroundJob\JobList {}, OC\Log {})
9. /var/www/nextcloud/cron.php line 125
   OCP\BackgroundJob\TimedJob->execute(OC\BackgroundJob\JobList {}, OC\Log {})

at 2020-04-17T06:35:03+00:00



md5-5e494f97e676c84e678992b6ea4a35fd



[mail] Error: Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE "oc_mail_mailboxes" SET "sync_new_lock" = ?, "sync_changed_lock" = ?, "sync_vanished_lock" = ? WHERE "id" = ?' with params [1587105302, 1587105302, null, 154]:

SQLSTATE[25P02]: In failed sql transaction: 7 ERROR:  current transaction is aborted, commands ignored until end of transaction block at <<closure>>

 0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 169
    Doctrine\DBAL\Driver\AbstractPostgreSQLDriver->convertException("An exception oc ... k", Doctrine\DBAL\Dr ... ]})
 1. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 145
    Doctrine\DBAL\DBALException::wrapException(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "An exception oc ... k")
 2. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php line 1063
    Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBAL\Driver\PDOPgSql\Driver {}, Doctrine\DBAL\Dr ... ]}, "UPDATE \"oc_mai ... ?", {1: 1587105302,2 ... 4})
 3. /var/www/nextcloud/lib/private/DB/Connection.php line 220
    Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc_mai ... ?", [1587105302,1587105302,null,154], [1,1,1,1])
 4. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php line 203
    OC\DB\Connection->executeUpdate("UPDATE \"oc_mai ... 4", {dcValue1: 15871 ... 4}, {dcValue1: 1,dcV ... 1})
 5. /var/www/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php line 215
    Doctrine\DBAL\Query\QueryBuilder->execute()
 6. /var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php line 197
    OC\DB\QueryBuilder\QueryBuilder->execute()
 7. /var/www/nextcloud/apps/mail/lib/Db/MailboxMapper.php line 195
    OCP\AppFramework\Db\QBMapper->update("*** sensitive parameters replaced ***")
 8. /var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php line 157
    OCA\Mail\Db\MailboxMapper->unlockFromVanishedSync("*** sensitive parameter replaced ***")
 9. /var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php line 106
    OCA\Mail\Service\Sync\ImapToDbSynchronizer->sync(OCA\Mail\Account {}, "*** sensitive parameter replaced ***", 42, null, false)
10. /var/www/nextcloud/apps/mail/lib/BackgroundJob/SyncJob.php line 86
    OCA\Mail\Service\Sync\ImapToDbSynchronizer->syncAccount(OCA\Mail\Account {})
11. /var/www/nextcloud/lib/public/BackgroundJob/Job.php line 79
    OCA\Mail\BackgroundJob\SyncJob->run({accountId: 10})
12. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 61
    OCP\BackgroundJob\Job->execute(OC\BackgroundJob\JobList {}, OC\Log {})
13. /var/www/nextcloud/cron.php line 125
    OCP\BackgroundJob\TimedJob->execute(OC\BackgroundJob\JobList {}, OC\Log {})

at 2020-04-17T06:35:03+00:00
zpintar picture zpintar on 17 Apr 2020

Ok, I'll check this, but why previous version of Mail app works well, and after this update to v1.3.x inbox doesn't work? What can be wrong on the same Nextcloud installation?

Because things changed. Please read the docs and ensure your installation is valid.

ChristophWurst picture ChristophWurst on 17 Apr 2020

Ok, I'll check this, but why previous version of Mail app works well, and after this update to v1.3.x inbox doesn't work? What can be wrong on the same Nextcloud installation?

Because things changed. Please read the docs and ensure your installation is valid.

OK, I will

zpintar picture zpintar on 17 Apr 2020

If there really is no other error then I'm out of ideas. Your database could also act weird and abort the transaction for whatever reason. Check its logs. Anything showing up there?

ChristophWurst picture ChristophWurst on 17 Apr 2020

[cron] Error: DoctrineDBALExceptionDriverException: An exception occurred while executing 'UPDATE "oc_jobs" SET "reserved_at" = '0' WHERE "id" = ?' with params [2833]:

SQLSTATE[25P02]: In failed sql transaction: 7 ERROR: current transaction is aborted, commands ignored until end of transaction block at <>

Since the error also shows up for core code, I'm not even sure if this is a problem of the Mail application. Any unhandled exception would show up in the logs. If it does not, then we could handle it. There are, however, no database error that we catch. Hence those will definitely bubble up and trigger a log entry.

ChristophWurst picture ChristophWurst on 17 Apr 2020

If there really is no other error then I'm out of ideas. Your database could also act weird and abort the transaction for whatever reason. Check its logs. Anything showing up there?

No, In log are always only this three errors and nothing else.

zpintar picture zpintar on 17 Apr 2020
👀1

I forwarded this thread to our server administrators and I'm waiting answers of them.

zpintar picture zpintar on 17 Apr 2020
👍1

Once we know more please open a new ticket. Your problem shows the same symptoms as @GuillaumeAmat's, but it's a different cause.

ChristophWurst picture ChristophWurst on 17 Apr 2020
👍1

Invalid datetime format: 1366 Incorrect string value: 'xF0x9Fx92x8D' for column cloud.oc_mail_messages.subject

Ai. That is strange. Might be an encoding or casting issue.

On a second thought please make sure you are following https://docs.nextcloud.com/server/stable/admin_manual/configuration_database/mysql_4byte_support.html. A lack of multi byte support could explain why the db can't insert this data.

On a third though, whoever proposed to you, broke your Mail app

Bildschirmfoto von 2020-04-17 09-03-41

:ring: :see_no_evil:

So, yeah, just fix your db and you'll be able to insert emojis :)

ChristophWurst picture ChristophWurst on 17 Apr 2020

@zpintar some hopefully useful links: https://docs.nextcloud.com/server/18/admin_manual/configuration_database/linux_database_configuration.html#database-read-committed-transaction-isolation-level https://docs.nextcloud.com/server/18/admin_manual/configuration_database/linux_database_configuration.html?highlight=postgres but see also https://help.nextcloud.com/ for related issues with postgres.

ChristophWurst picture ChristophWurst on 17 Apr 2020
👍1

On a third though, whoever proposed to you, broke your Mail app

Ah ah, I didn't mask the subject to give you the real informations but yeah, I'm glad my girlfriend isn't a developer. Massive spoiler!

I'll check my DB and let you know ASAP, thanks @ChristophWurst

GuillaumeAmat picture GuillaumeAmat on 17 Apr 2020

It works! 🤙

GuillaumeAmat picture GuillaumeAmat on 17 Apr 2020
🚀1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

clem-bcc picture clem-bcc  ·  4Comments
b1f17773 picture b1f17773  ·  5Comments
sscherfke picture sscherfke  ·  5Comments
MariusBluem picture MariusBluem  ·  3Comments
jancborchardt picture jancborchardt  ·  4Comments