Mail: Could not classify incoming message importance: Could not deserialize persisted classifier 4

[ovv]

Expected behavior

No error

Actual behavior

An error get logged
{"reqId":"VqvqceS8aD2X7sMLt47l","level":3,"time":"2020-06-26T19:20:22+00:00","remoteAddr":"","user":"--","app":"mail","method":"","url":"--","message":"{\"Exception\":\"OCA\\\\Mail\\\\Exception\\\\ServiceException\",\"Message\":\"Could not deserialize persisted classifier 4: File /tmp/oc_tmp_CEbWuG does not contain any data.\",\"Code\":0,\"Trace\":[{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/PersistenceService.php\",\"line\":156,\"function\":\"load\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\PersistenceService\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/ImportanceClassifier.php\",\"line\":289,\"function\":\"loadLatest\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\PersistenceService\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Listener/NewMessageClassificationListener.php\",\"line\":73,\"function\":\"classifyImportance\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\ImportanceClassifier\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/private/EventDispatcher/ServiceEventListener.php\",\"line\":76,\"function\":\"handle\",\"class\":\"OCA\\\\Mail\\\\Listener\\\\NewMessageClassificationListener\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php\",\"line\":247,\"function\":\"__invoke\",\"class\":\"OC\\\\EventDispatcher\\\\ServiceEventListener\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php\",\"line\":73,\"function\":\"callListeners\",\"class\":\"Symfony\\\\Component\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/private/EventDispatcher/EventDispatcher.php\",\"line\":80,\"function\":\"dispatch\",\"class\":\"Symfony\\\\Component\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":308,\"function\":\"dispatch\",\"class\":\"OC\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":202,\"function\":\"runPartialSync\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":114,\"function\":\"sync\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/BackgroundJob/SyncJob.php\",\"line\":92,\"function\":\"syncAccount\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/public/BackgroundJob/Job.php\",\"line\":79,\"function\":\"run\",\"class\":\"OCA\\\\Mail\\\\BackgroundJob\\\\SyncJob\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/public/BackgroundJob/TimedJob.php\",\"line\":61,\"function\":\"execute\",\"class\":\"OCP\\\\BackgroundJob\\\\Job\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/cron.php\",\"line\":125,\"function\":\"execute\",\"class\":\"OCP\\\\BackgroundJob\\\\TimedJob\",\"type\":\"->\"}],\"File\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/PersistenceService.php\",\"Line\":193,\"Previous\":{\"Exception\":\"RuntimeException\",\"Message\":\"File /tmp/oc_tmp_CEbWuG does not contain any data.\",\"Code\":0,\"Trace\":[{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/PersistenceService.php\",\"line\":191,\"function\":\"load\",\"class\":\"Rubix\\\\ML\\\\Persisters\\\\Filesystem\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/PersistenceService.php\",\"line\":156,\"function\":\"load\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\PersistenceService\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Classification/ImportanceClassifier.php\",\"line\":289,\"function\":\"loadLatest\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\PersistenceService\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Listener/NewMessageClassificationListener.php\",\"line\":73,\"function\":\"classifyImportance\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Classification\\\\ImportanceClassifier\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/private/EventDispatcher/ServiceEventListener.php\",\"line\":76,\"function\":\"handle\",\"class\":\"OCA\\\\Mail\\\\Listener\\\\NewMessageClassificationListener\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php\",\"line\":247,\"function\":\"__invoke\",\"class\":\"OC\\\\EventDispatcher\\\\ServiceEventListener\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php\",\"line\":73,\"function\":\"callListeners\",\"class\":\"Symfony\\\\Component\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/private/EventDispatcher/EventDispatcher.php\",\"line\":80,\"function\":\"dispatch\",\"class\":\"Symfony\\\\Component\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":308,\"function\":\"dispatch\",\"class\":\"OC\\\\EventDispatcher\\\\EventDispatcher\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":202,\"function\":\"runPartialSync\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php\",\"line\":114,\"function\":\"sync\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/apps/mail/lib/BackgroundJob/SyncJob.php\",\"line\":92,\"function\":\"syncAccount\",\"class\":\"OCA\\\\Mail\\\\Service\\\\Sync\\\\ImapToDbSynchronizer\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/public/BackgroundJob/Job.php\",\"line\":79,\"function\":\"run\",\"class\":\"OCA\\\\Mail\\\\BackgroundJob\\\\SyncJob\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/lib/public/BackgroundJob/TimedJob.php\",\"line\":61,\"function\":\"execute\",\"class\":\"OCP\\\\BackgroundJob\\\\Job\",\"type\":\"->\"},{\"file\":\"/opt/nextcloud/cron.php\",\"line\":125,\"function\":\"execute\",\"class\":\"OCP\\\\BackgroundJob\\\\TimedJob\",\"type\":\"->\"}],\"File\":\"/opt/nextcloud/apps/mail/vendor/rubix/ml/src/Persisters/Filesystem.php\",\"Line\":122},\"CustomMessage\":\"Could not classify incoming message importance: Could not deserialize persisted classifier 4: File /tmp/oc_tmp_CEbWuG does not contain any data.\"}","userAgent":"--","version":"18.0.6.0"}

Mail app

Mail app version: 1.4.0
Mailserver or service: Various

Server configuration

Operating system: Debian 9 on LXC

Web server: Nginx

Database: Postgres

PHP version: 7.4

Nextcloud Version: 18.0.6

Client configuration

N/A

[BMerz]

I have the same log error.
See here:
https://help.nextcloud.com/t/log-error-could-not-deserialize-persisted-classifier/85845

Mail app version: 1.4.0
Mailserver or service: dovecot (local)
Operating system: Debian 10.4 (Raspbian)
Web server: Nginx
Database: MariaDB
PHP version: 7.3.14
Nextcloud Version: 18.0.6

[muranava]

getting same problem

[ChristophWurst]

@muranava use the :+1: reaction on the original ticket. Your comment does not provide any value to us, but generates a notification (email) to everyone subscribed to this ticket. Please refrain from this in the future.

[ChristophWurst]

File /tmp/oc_tmp_CEbWuG does not contain any data.

This either means

• The original serialized classifier was invalid
• There was an issue when the serialized classifier is written to disk (memory to tmp dir or temp dir to app data)
• There was an issue when the serialized classifier is read from disk (app data to tmp dir or temp dir to memory)

I'll therefore add some more debug logs to https://github.com/nextcloud/mail/blob/master/lib/Service/Classification/PersistenceService.php so we can localize the issue.

[ChristophWurst]

Turns out I did this already: https://github.com/nextcloud/mail/blob/8b406bce8794016b7454b600d9aa0d00e7cab6d2/lib/Service/Classification/PersistenceService.php#L181

So please set your log level to 0/debug, reproduce the issue and check for debug logs before the error log in nextcloud.log and post it here. Is the size 0?

[ChristophWurst]

And please check the file manually. You'll find it at <data dir>/appdata_<instance id>/mail/classifiers/<classfifier ID>, e.g. /var/www/nextcloud/data//appdata_abcdefg1234/mail/classifiers/4

[ChristophWurst]

See https://github.com/nextcloud/mail/pull/3331 for the extended logging. I'll backport to v1.4.x

[oldnomad]

In my case (I have the same exception message) mail/classifiers contains 137 numbered files, and _all_ of them have zero size. Timestamps on files seem to be close to the times when I got the exceptions (sometimes preceding them by 10-20 minutes).

Right now I got an exception at 12:21, and now I have 138th file, created at 12:11, zero size again.

[ChristophWurst]

Ok, thanks, that helps a lot. So it's about the data that is written.

I turns out this is only an issue with Nextcloud 18, thus I could never reproduce. https://github.com/nextcloud/mail/pull/3331 now contains also a fix (see second commit). Please test the full patch.

[ovv]

@ChristophWurst I can't see your second commit. Are you sure you push the changes ? There is an open github incident so it might appear later https://www.githubstatus.com/

[ChristophWurst]

Right, that didn't show up. I rebased and pushed again. Now it's there :)

[oldnomad]

I can confirm that after applying commit 37097de37702e3a4033dc8bcba5e8533d8b449b0 I've finally got a non-empty classifier file 140.

[ovv]

Same for me, error looks gone with the patch. thanks :tada:

[BMerz]

@ChristophWurst : Unfortunately I get the error message even after updating.

Mail-App version 1.4.1
Mailserver or service: dovecot (local)
Operating system: Debian 10.4 (Raspbian)
Web server: Nginx
Database: MariaDB
PHP version: 7.3.19
Nextcloud Version: 18.0.7

It seems that the error is shown when cron-job is triggered but not with every execution.

I have activated debug-messages for mail app in nextcloud config.

Error with two debug messages before and after the error:

[mail] Debug: partial sync 3:INBOX - persist new messages took 0s

at 2020-07-24T18:00:19+00:00

[mail] Debug: partial sync 3:INBOX - classified a chunk of new messages took 0s

at 2020-07-24T18:00:19+00:00

[mail] Error: OCA\Mail\Exception\ServiceException: Could not deserialize persisted classifier 3: File /tmp/oc_tmp_Wj4tg3 does not contain any data. at <>

1. /var/www/nextcloud/apps/mail/lib/Service/Classification/PersistenceService.php line 162
   OCA\Mail\Service\Classification\PersistenceService->load(3)
2. /var/www/nextcloud/apps/mail/lib/Service/Classification/ImportanceClassifier.php line 296
   OCA\Mail\Service\Classification\PersistenceService->loadLatest(OCA\Mail\Account {})
3. /var/www/nextcloud/apps/mail/lib/Listener/NewMessageClassificationListener.php line 73
   OCA\Mail\Service\Classification\ImportanceClassifier->classifyImportance(OCA\Mail\Account {}, OCA\Mail\Db\Mailbox {id: 11}, [OCA\Mail\Db\Mes ... }])
4. /var/www/nextcloud/lib/private/EventDispatcher/ServiceEventListener.php line 76
   OCA\Mail\Listener\NewMessageClassificationListener->handle(OCA\Mail\Events\ ... {})
5. /var/www/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php line 247
   OC\EventDispatcher\ServiceEventListener->__invoke(OCA\Mail\Events\ ... {}, "OCA\Mail\Even ... d", Symfony\Componen ... {})
6. /var/www/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php line 73
   Symfony\Component\EventDispatcher\EventDispatcher->callListeners([Closure {}], "OCA\Mail\Even ... d", OCA\Mail\Events\ ... {})
7. /var/www/nextcloud/lib/private/EventDispatcher/EventDispatcher.php line 80
   Symfony\Component\EventDispatcher\EventDispatcher->dispatch(OCA\Mail\Events\ ... {}, "OCA\Mail\Even ... d")
8. /var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php line 308
   OC\EventDispatcher\EventDispatcher->dispatch("OCA\Mail\Even ... d", OCA\Mail\Events\ ... {})
9. /var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php line 202
   OCA\Mail\Service\Sync\ImapToDbSynchronizer->runPartialSync(OCA\Mail\Account {}, OCA\Mail\Db\Mailbox {id: 11}, 42, null)
10. /var/www/nextcloud/apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php line 114
    OCA\Mail\Service\Sync\ImapToDbSynchronizer->sync(OCA\Mail\Account {}, OCA\Mail\Db\Mailbox {id: 11}, 42, null, false)
    
    
    
    1. /var/www/nextcloud/apps/mail/lib/BackgroundJob/SyncJob.php line 92
       
       OCA\Mail\Service\Sync\ImapToDbSynchronizer->syncAccount(OCA\Mail\Account {})
    
    
    2. /var/www/nextcloud/lib/public/BackgroundJob/Job.php line 79
       
       OCA\Mail\BackgroundJob\SyncJob->run({accountId: 3})
    
    
    3. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 61
       
       OCP\BackgroundJob\Job->execute(OC\BackgroundJob\JobList {}, OC\Log {})
    
    
    4. /var/www/nextcloud/cron.php line 125
       
       OCP\BackgroundJob\TimedJob->execute(OC\BackgroundJob\JobList {}, OC\Log {})
    
    

at 2020-07-24T18:00:19+00:00

[mail] Debug: Serialized classifier loaded (size=0)

at 2020-07-24T18:00:19+00:00

[mail] Debug: Loading serialized classifier from app data

at 2020-07-24T18:00:19+00:00

I can provide more logs if needed.

[BMerz]

@ovv : Could you please check my comment above and reopen the issue? Thank you!

[ovv]

@ChristophWurst error looks to be the same, reopening for @BMerz

[ChristophWurst]

@BMerz please also check manually as per https://github.com/nextcloud/mail/issues/3327#issuecomment-650986269

[BMerz]

@ChristophWurst file "3" has (among others) size of zero.
Older files (named 1 to 9) have size of zero with creation date in June. Other files (10 to 42) have around 700kB with creation date in July.

[ChristophWurst]

Could you please run the training from the CLI like I did below? I hope that gives some insights. You can find the account_id from your oc_mail_accounts table.

$ php occ mail:account:train 1227
[debug] found 8 incoming mailbox(es)
[debug] found 1 outgoing mailbox(es)
[debug] found 321 messages of which 0 are important
[info] not enough messages to train a classifier
9MB of memory used

[BMerz]

Hi @ChristophWurst,
I have executed it for all three accounts with configured mail app:

[debug] found 10 incoming mailbox(es)
[debug] found 1 outgoing mailbox(es)
[debug] found 1000 messages of which 8 are important
[warning] not enough messages to train a classifier
24MB of memory used

[debug] found 5 incoming mailbox(es)
[debug] found 1 outgoing mailbox(es)
[debug] found 1000 messages of which 15 are important
[warning] not enough messages to train a classifier
26MB of memory used

[debug] found 4 incoming mailbox(es)
[debug] found 1 outgoing mailbox(es)
[debug] found 885 messages of which 12 are important
[warning] not enough messages to train a classifier
24MB of memory used



md5-870b7090d1e4bc75b123d91eafe76a9d



-rw-r--r-- 1 www-data www-data   0 Jun 21 21:31 2
-rw-r--r-- 1 www-data www-data   0 Jun 24 13:40 5
-rw-r--r-- 1 www-data www-data   0 Jun 24 14:45 6
-rw-r--r-- 1 www-data www-data   0 Jun 24 15:50 7
-rw-r--r-- 1 www-data www-data   0 Jun 24 15:51 8
-rw-r--r-- 1 www-data www-data   0 Jul 19 21:55 4
-rw-r--r-- 1 www-data www-data 737 Jul 22 14:41 13
-rw-r--r-- 1 www-data www-data 737 Jul 22 15:45 14
-rw-r--r-- 1 www-data www-data 736 Jul 22 17:51 16
-rw-r--r-- 1 www-data www-data 734 Jul 22 18:56 17
-rw-r--r-- 1 www-data www-data 732 Jul 22 21:06 19
-rw-r--r-- 1 www-data www-data 732 Jul 22 22:11 20
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 27
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 26
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 25
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 24
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 23
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 22
-rw-r--r-- 1 www-data www-data 733 Jul 23 05:31 21
-rw-r--r-- 1 www-data www-data 732 Jul 23 05:31 18
-rw-r--r-- 1 www-data www-data 736 Jul 23 05:31 15
-rw-r--r-- 1 www-data www-data 740 Jul 23 05:31 11
-rw-r--r-- 1 www-data www-data 740 Jul 23 05:31 10
-rw-r--r-- 1 www-data www-data 733 Jul 23 06:41 28
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 40
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 39
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 38
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 37
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 36
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 35
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 34
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 33
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 32
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 31
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 30
-rw-r--r-- 1 www-data www-data 730 Jul 24 05:31 29
-rw-r--r-- 1 www-data www-data 730 Aug  8 14:11 41
-rw-r--r-- 1 www-data www-data   0 Aug 25 09:15 3
-rw-r--r-- 1 www-data www-data 730 Aug 25 11:26 42
-rw-r--r-- 1 www-data www-data   0 Aug 25 14:35 9
-rw-r--r-- 1 www-data www-data 740 Aug 25 20:29 12
-rw-r--r-- 1 www-data www-data   0 Aug 25 20:29 1

The time I executed the train command was 20:47.
The error OCA\Mail\Exception\ServiceException: Could not deserialize persisted classifier 3: File /tmp/oc_tmp_oA0URv does not contain any data. is still in the logs but with a later time (20:55).

[ChristophWurst]

Thanks a lot for the test.

So your three accounts do not have enought important messages to train a classified – fine. And it looks like the empty files are old ones? Every training run will create a new classifier and we currently do not yet clean them up. So only the latest per account_id will be used.

Could you check the oc_mail_classifiers table to find out which account ID has empty files (the classified id is the file name)? Like SELECT account_id from oc_mail_classifiers where id=3.

[BMerz]

ok, in the logs I have classifiers 3 and 9.
With the statement above I get account_id 3 and account_id 4.

SELECT account_id from oc_mail_classifiers where id = 3;
+------------+
| account_id |
+------------+
|          3 |
+------------+
1 row in set (0.000 sec)

SELECT account_id from oc_mail_classifiers where id = 9;
+------------+
| account_id |
+------------+
|          4 |
+------------+
1 row in set (0.000 sec)

What can I do with the accounts?

[ChristophWurst]

Set them on :fire:

Just kidding. Nothing in particular. The accounts are not a problem. The problem is that something lead to incorrect classifiers when their training was run. You can try to re-run the training from the CLI for those specifically. Though the cron should train every account once a day automatically.

[BMerz]

Now I am confused. I thought the re-run of the training was done with the command php occ mail:account:train [account_id]. This I had done already for all accounts two days before ?!

[ChristophWurst]

You left out the account IDs for the training runs, so I did not know which accounts you trained.

For now I would suggest that you set enabled to 0 for all oc_mail_classifier rows where the id corresponds to an empty file in the filesystem.

[BMerz]

OK, this worked - error is gone :-) Thanks!

Table name was oc_mail_classifiers and row active instead of enabled.
One hint: all empty classifiers had app_version 1.4.0; all non-empty classifiers had app_version 1.4.1.

[ChristophWurst]

all empty classifiers had app_version 1.4.0; all non-empty classifiers had app_version 1.4.1.

Ah that actually makes sense! There was a bug in v1.4.0 with Nextcloud 18, fixed via https://github.com/nextcloud/mail/pull/3331