search

nextcloud / mail

💌 Mail app for Nextcloud
https://apps.nextcloud.com/apps/mail
GNU Affero General Public License v3.0
848 stars 261 forks source link

"Unable to load the desired message" after update to 0.7.5 #643

Closed Sp1l closed 6 years ago

Sp1l commented 6 years ago

Steps to reproduce

  1. Install mail 0.7.4
  2. Update Nextcloud from 12.0.3 to 13.0.0.6
  3. Update mail to 0.7.5

Expected behaviour

Display message content

Actual behaviour

"Unable to load the desired message :-/" is displayed in the message frame. PHP-FPM log shows

WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children pool not functional, requires restart of the pool

Mail app

Mail app version: 0.7.9

Mailserver or service: Dovecot 2.2.33.2

Transport security - IMAP: None

Transport security - SMTP: smtps (465)

Number of accounts: 10

Mail app version build date: (only if you are using a Nightly Build)

Server configuration

Operating system: FreeBSD 11.1p1 amd64

Web server: Apache 2.4.29

Database: MariaDB 10.2

PHP version: 7.1.12 FPM

Version: (see admin page) Nextcloud 13.0.0 RC3

Updated from an older version or fresh install: 12.0.3, 13.0.0b1, 13.0.0b3, 13.0.0rc1

List of activated apps: Enabled:

The content of config/config.php:

{ "system": { "appstoreenabled": false, "appstoreurl": "https:\/\/api.owncloud.com\/v1", "instanceid": "***REMOVED SENSITIVE VALUE***", "passwordsalt": "***REMOVED SENSITIVE VALUE***", "datadirectory": "***REMOVED SENSITIVE VALUE***", "dbtype": "mysql", "version": "13.0.0.6", "installed": true, "theme": "", "trusted_domains": [ "nc.example.org", "cloud.example.net" ], "dbname": "***REMOVED SENSITIVE VALUE***", "dbhost": "***REMOVED SENSITIVE VALUE***", "dbtableprefix": "oc_", "dbuser": "***REMOVED SENSITIVE VALUE***", "dbpassword": "***REMOVED SENSITIVE VALUE***", "forcessl": true, "ldapIgnoreNamingRules": false, "loglevel": 0, "logfile": "\/var\/log\/nextcloud.log", "user_backends": [ { "class": "OC_User_IMAP", "arguments": [ "{imap.example.net:144\/imap}" ] } ], "secret": "***REMOVED SENSITIVE VALUE***", "trashbin_retention_obligation": "auto", "htaccess.RewriteBase": "\/", "mail_smtpmode": "smtp", "mail_from_address": "***REMOVED SENSITIVE VALUE***", "mail_domain": "***REMOVED SENSITIVE VALUE***", "mail_smtpsecure": "tls", "mail_smtphost": "***REMOVED SENSITIVE VALUE***", "mail_smtpport": "587", "mail_smtpauth": 1, "mail_smtpname": "***REMOVED SENSITIVE VALUE***", "mail_smtppassword": "***REMOVED SENSITIVE VALUE***", "appstore.experimental.enabled": false, "overwrite.cli.url": "https:\/\/nc.example.org", "maintenance": false, "app.mail.accounts.default": { "email": "%USERID%", "imapHost": "imap.example.net", "imapPort": 144, "smtpHost": "smtp.example.net", "smtpPort": 486, "smtpSslMode": "tls" } } } ```

Client configuration

Browser: Firefox 57.0, Chrome 62.0.3202.94

Operating system: Win 10 Pro 1709

Logs

Web server error log
[Fri Nov 17 09:00:07.825110 2017] [mpm_event:notice] [pid 86068:tid 34389188608] AH00491: caught SIGTERM, shutting down
[Fri Nov 17 09:17:48.661439 2017] [http2:info] [pid 16872:tid 34389188608] AH03090: mod_http2 (v1.10.13-git, feats=CHPRIO+SHA256+INVHD+DWINS, nghttp2 1.27.0), initializing...
[Fri Nov 17 09:17:48.663609 2017] [mpm_event:notice] [pid 16872:tid 34389188608] AH00489: Apache/2.4.29 (FreeBSD) LibreSSL/2.6.3 configured -- resuming normal operations
[Fri Nov 17 09:17:48.663699 2017] [core:notice] [pid 16872:tid 34389188608] AH00094: Command line: '/usr/local/sbin/httpd -D NOHTTPACCEPT'
[27-Nov-2017 21:59:20] NOTICE: configuration file /usr/local/etc/php-fpm.conf test is successful
[27-Nov-2017 21:59:20] NOTICE: fpm is running, pid 35511
[27-Nov-2017 21:59:20] NOTICE: ready to handle connections
[27-Nov-2017 21:59:30] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 5 total children
[27-Nov-2017 21:59:31] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 6 total children
[27-Nov-2017 21:59:32] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 7 total children
[27-Nov-2017 21:59:42] WARNING: [pool www] server reached pm.max_children setting (8), consider raising it
[28-Nov-2017 19:20:30] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
[28-Nov-2017 19:22:52] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
[28-Nov-2017 19:23:30] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
[28-Nov-2017 19:23:31] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 7 total children
[28-Nov-2017 19:23:32] WARNING: [pool www] server reached pm.max_children setting (8), consider raising it
[28-Nov-2017 19:29:54] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
[28-Nov-2017 19:30:51] WARNING: [pool www] server reached pm.max_children setting (8), consider raising it
[28-Nov-2017 19:37:49] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
[28-Nov-2017 19:51:48] WARNING: [pool www] server reached pm.max_children setting (8), consider raising it
Server log (data/nextcloud.log)
``` {"reqId":"gCqrETpJKQ3rWeTWqvMs","level":0,"time":"2017-11-28T18:23:22+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/","message":"default config to create a default account found","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"gCqrETpJKQ3rWeTWqvMs","level":1,"time":"2017-11-28T18:23:22+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/","message":"building default account for user testuser","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"gCqrETpJKQ3rWeTWqvMs","level":3,"time":"2017-11-28T18:23:22+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"PHP","method":"GET","url":"\/index.php\/apps\/mail\/","message":"Undefined index: imapSslMode at \/usr\/local\/www\/nextcloud\/apps\/mail\/lib\/Service\/DefaultAccount\/Config.php#73","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"RVMRdWQQriW7g0QRSgEh","level":0,"time":"2017-11-28T18:23:25+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders","message":"default config to create a default account found","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"RVMRdWQQriW7g0QRSgEh","level":1,"time":"2017-11-28T18:23:25+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders","message":"building default account for user testuser","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"RVMRdWQQriW7g0QRSgEh","level":3,"time":"2017-11-28T18:23:25+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"PHP","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders","message":"Undefined index: imapSslMode at \/usr\/local\/www\/nextcloud\/apps\/mail\/lib\/Service\/DefaultAccount\/Config.php#73","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"4FdvJemidpUlS5Dja5G8","level":0,"time":"2017-11-28T18:23:26+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders\/5USCT1g%3D\/messages?filter=","message":"default config to create a default account found","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"4FdvJemidpUlS5Dja5G8","level":1,"time":"2017-11-28T18:23:26+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders\/5USCT1g%3D\/messages?filter=","message":"building default account for user testuser","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"4FdvJemidpUlS5Dja5G8","level":3,"time":"2017-11-28T18:23:26+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"PHP","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders\/5USCT1g%3D\/messages?filter=","message":"Undefined index: imapSslMode at \/usr\/local\/www\/nextcloud\/apps\/mail\/lib\/Service\/DefaultAccount\/Config.php#73","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} {"reqId":"4FdvJemidpUlS5Dja5G8","level":0,"time":"2017-11-28T18:23:26+00:00","remoteAddr":"172.17.2.169","user":"testuser","app":"mail","method":"GET","url":"\/index.php\/apps\/mail\/api\/accounts\/-2\/folders\/5USCT1g%3D\/messages?filter=","message":"loading messages of folder <5USCT1g=>","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"13.0.0.6"} ```
Horde IMAP log (data/horde_imap.log)
``` File not found (not in directory where nextcloud.log is nor in nextcloudroot/data ```
Horde SMTP log (data/horde_smtp.log)
``` File not found (not in directory where nextcloud.log is nor in nextcloudroot/data ```
Browser log
``` Insert your browser log here, this could for example include: a) The javascript console log b) The network log c) ... ```
--- Want to back this issue? **[Post a bounty on it!](https://www.bountysource.com/issues/52069025-unable-to-load-the-desired-message-after-update-to-0-7-5?utm_campaign=plugin&utm_content=tracker%2F44154351&utm_medium=issues&utm_source=github)** We accept bounties via [Bountysource](https://www.bountysource.com/?utm_campaign=plugin&utm_content=tracker%2F44154351&utm_medium=issues&utm_source=github).
ChristophWurst commented 6 years ago

pool not functional, requires restart of the pool

I'm not a php-fpm expert, but this looks suspicious.

Sp1l commented 6 years ago

pool not functional, requires restart of the pool

That happens after (because of?) opening a message. PHP-FPM runs fine until I enable the mail app and open it, that's when these pool not functional errors appear

ChristophWurst commented 6 years ago

Operating system: FreeBSD 11.1p1 amd64

Btw, I don't think we support anything other than Linux 😞

Sp1l commented 6 years ago

Don't really need to generally, it's just another platform to run PHP on 😄

Any clue where I should find the logfiles? https://github.com/nextcloud/mail/blob/master/lib/Account.php#L148 shows that they should appear in <datadirectory> but I haven't found the logfiles there. Permissions on the directory show that apache can write there.

ChristophWurst commented 6 years ago

Did you enable debug mode via config.php?

Sp1l commented 6 years ago

Yes, loglevel is set to 0

'loglevel' => 0,

ChristophWurst commented 6 years ago

No, I mean "debug" => true 😉

ChristophWurst commented 6 years ago

https://github.com/nextcloud/mail/blob/fad0eb67266c29882abad60b2a7462fe50826996/lib/Account.php#L147 😉

Sp1l commented 6 years ago

Oeps! Hadn't found that one. Now enabled and I have the logs. No apparent errors in the IMAP log

S: 5 OK Fetch completed (0.004 + 0.000 + 0.003 secs).
>> Command 5 took 0.2285 seconds.
C: 6 LOGOUT
S: * OK [CLOSED] Previous mailbox closed.
S: * BYE LOGOUT received
S: 6 OK Completed
>> Command 6 took 0.0015 seconds.
ChristophWurst commented 6 years ago

Unassigning this from the current release milestone as I don't know what's going on here. Could be the unsupported platform, a misconfiguration of php-fpm or a bug in the app. I can't tell.

Sp1l commented 6 years ago

Just verified that the issue is still there in 0.7.6. Any timeline for 13.0.0beta2?

ChristophWurst commented 6 years ago

Any timeline for 13.0.0beta2?

Soon https://github.com/nextcloud/server/pull/7425 😉

Sp1l commented 6 years ago

Saw the notification too late 😄 Just tested with 13.0.0beta2, error still the same. FreeBSD port for nextcloud-mail updated Nextcloud 13 is still only a PR

Sp1l commented 6 years ago

Updated the FreeBSD port to 0.7.9 Running Nextcloud 13.0.0-RC1

Problem persists (still running via fpm)

Sp1l commented 6 years ago

Problem persists in 13.0.0-RC3 with Mail 0.7.9. Found some entries in the Nextcoud logs:

Error | PHP | Undefined index: imapSslMode at /usr/local/www/nextcloud/apps/mail/lib/Service/DefaultAccount/Config.php#73 | 2018-01-26T21:52:06+0100
-- | -- | -- | --
Error | PHP | Undefined index: imapSslMode at /usr/local/www/nextcloud/apps/mail/lib/Service/DefaultAccount/Config.php#73 | 2018-01-26T21:52:05+0100
Error | PHP | Undefined index: imapSslMode at /usr/local/www/nextcloud/apps/mail/lib/Service/DefaultAccount/Config.php#73 | 2018-01-26T21:52:04+0100
ChristophWurst commented 6 years ago

/usr/local/www/nextcloud/apps/mail/lib/Service/DefaultAccount/Config.php

Oh, you're using a default account. I overlooked that.

ChristophWurst commented 6 years ago

As a start, please see the admin docs for a minimal configuration: https://github.com/nextcloud/mail/blob/ecf34360a7d14f0593deb4033714c1b894d3c778/doc/admin.md#minimal-configuration

ChristophWurst commented 6 years ago

Can this issue be closed?

Sp1l commented 6 years ago

Late response... Just updated to 0.8.2 and all seems well now.

Already closed and that's a good thing. Thanks Christoph!

ChristophWurst commented 6 years ago

Thanks for your feedback :smiley:

lock[bot] commented 5 years ago

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and questions.