Adding new mail account or starting mail app with huge number of folders failed

pongraczi commented 1 year ago

Steps to reproduce

Similar situation as #2577 and #2688 #8318 Pretty same as: #8028

There is a remote imap server with shared mailboxes (cyrus-imapd) and a lot of mailboxes (folders).
Existing mail account cannot show any emails or folders, due to timeout.
When I deleted the account and added again, after clicking on to Connect, it started to read from the imap server (horde_imap.log) but after about 14300 commands it just run into time out and I got a message: Error happened during the connection.

Expected behavior

I expect the mailboxes appears, connection established.

Actual behavior

General

app will be unresponsible for a while and after that just show an empty folder list, no messages, nothing. I was able to modify the account settings, sieve script was visible. I deleted the account to start over.
after I added the account and started to Connect by clicking on Connect, the app started to work, Testing authentication (I checked the horde_imap.log it started to read all folders on the imap server), but after a long time I got message: Error happened and the screen remained on the account settings page and clickable Connect button.
I clicked again on Connect, it started again, it is running from the beginning as I can see.

horde_imap.log

S: * MYRIGHTS user/johndoe/Archives/2010 lrswipkxtecda
S: 14310 OK Completed
>> Command 14310 took 0.0329 seconds.
C: 14311 MYRIGHTS user/janedoe/Megosztott
S: * MYRIGHTS user/janedoe/Megosztott lrs
S: 14311 OK Completed
>> Command 14311 took 0.0329 seconds.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
C: 14312 LOGOUT
S: * BYE LOGOUT received
S: 14312 OK Completed
>> Command 14312 took 0.0328 seconds.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.004 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.004 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.

This part keep adding continuously:

Slow Command: 5.005 seconds ERROR: read/timeout error.

Mail app version

3.2.3

Mailserver or service

Cyrus imap 3.6.0

Operating system

Linux Debian

PHP engine version

PHP 8.1

Web server

Apache (supported)

Database

MariaDB

Additional info

When I first added this mail account, it contained less folders than now.
I have to use lot of shared folders with tons of emails.

After I added more shared folders from other users, mail app stopped working for me.

Other accounts on the very same environment (except the numbers of folders) working fine.

ChristophWurst commented 1 year ago

Exchange?

Sounds like this might be fixed with https://github.com/nextcloud/mail/pull/8494

pongraczi commented 1 year ago

I try to increase the php-fpm timout.

pongraczi commented 1 year ago

Exchange?

Sounds like this might be fixed with #8494

Not really, cyrus imap 3.6.

pongraczi commented 1 year ago

@ChristophWurst thanks for the hint, yes, I can see lot of similarities with #8494

Lots of MYRIGHTS, as we heavily use ACLs and shared folder features.

Now I just doubled the max_execution_time etc. to see any difference.

pongraczi commented 1 year ago

Seems increasing the execution time did not help.

I am wondering, the script could read everything, but somehow lost some connection after completed the task.

C: 14311 MYRIGHTS user/janedoe/Megosztott
S: * MYRIGHTS user/janedoe/Megosztott lrs
S: 14311 OK Completed
>> Command 14311 took 0.0329 seconds.
C: 14312 LOGOUT
S: * BYE LOGOUT received
S: 14312 OK Completed
>> Command 14312 took 0.0327 seconds.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.005 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.004 seconds
>> ERROR: read/timeout error.
>> Slow Command: 5.004 seconds
>> ERROR: read/timeout error.

pongraczi commented 1 year ago

It seems I getting closer.

In DbalException.php line 71:

  An exception occurred while executing a query: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/XXX/2...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'  

In ExceptionConverter.php line 64:

  An exception occurred while executing a query: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/XXX/2...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'  

In Exception.php line 30:

  SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/XXX/2...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'                                                                                                                                                                                 

In Statement.php line 101:

  SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/XXX/2...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'

pongraczi commented 1 year ago

Unfortunately, I am not closer at all.

ChristophWurst commented 1 year ago

Yeah. It is the IMAP server that rate limits the connection.

pongraczi commented 1 year ago

Hmmmm, I check it on the imap server side, thanks for the hint.

Anyway, is it a normal behaviour, it seems in the log, everything went well, logout and bye-bye happened, but in overall the action fails?

ChristophWurst commented 1 year ago

As far as I understand there is a bunch of commands dispatched for the server but the server ends the communication prematurely, hence some wait time is added.

https://github.com/nextcloud/mail/pull/8494 will improve this.

pongraczi commented 1 year ago

I tried the latest mail, which included the #8494

I think, my problem caused by a totally other problem, which related to the folder structure itself.
I still got the following error message, when I synced manuall (occ):

In DbalException.php line 71:
  An exception occurred while executing a query: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/xxxxx/xxxxxx/Archive/fxxxxxx/Archives/Exxxxxt/20...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'  

In ExceptionConverter.php line 64:
  An exception occurred while executing a query: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/xxxxx/xxxxxx/Archive/fxxxxxx/Archives/Exxxxxt/20...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'  

In Exception.php line 30:
  SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/xxxxx/xxxxxx/Archive/fxxxxxx/Archives/Exxxxxt/20...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'  

In Statement.php line 101:
  SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '17-user/xxxxx/xxxxxx/Archive/fxxxxxx/Archives/Exxxxxt/20...' for key 'UNIQ_22DEBD839B6B5FBA5E237E06'

Should I log all the sql invocation via the mysql or can I set some debug in the sourcecode to catch, which folder do I have problem? Because now the folder path is longer than what is visible in the error message.

pongraczi commented 1 year ago

Ok, it seems I found the root of my problems.

There is a user, who use his email folders like a catalog and for years, her mail folders grown to a really huge mess (for others, she was fine with it).
Anyway, her folder name rules were strange and there were several mail folders, which have exactly the same name (folder pairs, doubled), except, one of the pair has a space at the end of its name.
Example:

"Folder 1 just for fun"
"Folder 1 just for fun "

That means, when the mail app tried to write the same name with an extra space into the database, it trimmed the last space (and I guess the leading), which result exactly the same name, so, duplicity entry happened.

Now I manually find and rename these duplicated folder names to fix this.

After several renaming, when I think I fixed, I run an ./occ manual sync again and based on the error message, I search and fix other, similar problems.

Nightmare, but seems the problem is more PEBCAK than software bug.
Anyway, hard to tell, trailing spaces are legitimate in folder names or just stupid.

pongraczi commented 1 year ago

Hmmm, maybe these names with trailing space born by manual recovering deleted folders/emails on the email server, using cyrus imapd tool.
I did not check this, but it is a possible scenario (instead of user intendid to create same folder names with trailing space in their names).

pongraczi commented 1 year ago

After I eliminated all these anomalies and sync could happen quickly (by using manual sync with occ), I get empty mail app.

I mean, I do not find any sign of problem, but the app does not appear on the screen. I got the following after a long time of wheel rotating (progress).
Kijelölés_464

nextcloud / mail