mails from Linux cron or other system generated messages.

[wintpe]

Hi , This is my first post, ive joined here because I have a problem with roundcube and I cant find the specific problem , using google.
I have a postfix daemon delivering mail into a Dovecote imap server, and connected to those two daemons via smtp/imap are aquamail on phones and tables,
Thunderbird on Desktops and every thing is fine with those, they dont have this specific problem at all.
when reading mails ive recieved from outside of my systems, ie from the internet, roundcube displays the mails without a problem.
but any system generated mails from any of my linux PC's which display on all other clients fine , just gives :
Oops... something went wrong!
An internal error has occurred. Your request cannot be processed at this time.

For administrators: Please check the application and/or server error logs for more information.

Also if i use the right click on those mails and more edit as new, it displays the mails without a problem, heres one just as an example.

/etc/cron.hourly/clamscan:

ClamAV update process started at Mon Mar 11 18:01:01 2024
daily.cld database is up-to-date (version: 27211, sigs: 2054718, f-level: 90, builder: raynman)
main.cvd database is up-to-date (version: 62, sigs: 6647427, f-level: 90, builder: sigmgr)
bytecode.cld database is up-to-date (version: 335, sigs: 86, f-level: 90, builder: raynman)

----------- SCAN SUMMARY -----------
Known viruses: 8686419
Engine version: 0.103.11
Scanned directories: 7006
Scanned files: 26516
Infected files: 0
Data scanned: 323.52 MB
Data read: 206.80 MB (ratio 1.56:1)
Time: 127.423 sec (2 m 7 s)
Start Date: 2024:03:11 18:01:01
End Date:   2024:03:11 18:03:08

if I now send that mail to myself from the edit as new form, via roundcube, the new mail received from it displays without a problem.

what imap actually sees in the logs is the following. (edited for privacy  -- where host is used)
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] S: Return-Path: <root@host>\x0d
Mar 11 17:55:46 host roundcube[55967]: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09host; h=cc:content-type:content-type:date:from:from\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09:message-id:mime-version:reply-to:subject:subject:to:to; s=mail;\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09 bh=kE2FNeuIgLSwxYBi/xjg0JxPhWwQJl0G8ckc2WzOtHQ=; b=op38e2sBam+8\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09SgD50vYW5sL9ez6s3NWmwsRQVtlOCyojnM67AbbsYQbRXZshYUwe2MtnuP6WBQE4\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09M4YhO9AS44Tsq/TG4yYpDakawv4HxYFR8FIj+geVmnToJCn/2Thnfo7CQDs6o8QZ\x0d
Mar 11 17:55:46 host roundcube[55967]: \x09IfFxZy2ew9uw/E631EWMhEJvgsUUFFw=\x0d
Mar 11 17:55:46 host roundcube[55967]: From: "(Cron Daemon)" <root@host>\x0d
Mar 11 17:55:46 host roundcube[55967]: To: root@host\x0d
Mar 11 17:55:46 host roundcube[55967]: Subject: Cron <root@host> run-parts /etc/cron.hourly\x0d
Mar 11 17:55:46 host roundcube[55967]: Content-Type: text/plain; charset=UTF-8\x0d
Mar 11 17:55:46 host roundcube[55967]: Message-Id: <20240311170309.0DB3160D9@host>\x0d
Mar 11 17:55:46 host roundcube[55967]: Date: Mon, 11 Mar 2024 17:03:09 +0000 (GMT)\x0d
Mar 11 17:55:46 host roundcube[55967]: \x0d
Mar 11 17:55:46 host roundcube[55967]:
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] S: )
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] S: A0004 OK Fetch completed (0.001 + 0.000 secs).
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] C: A0005 UID FETCH 6086 (BODY.PEEK[1])
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] S: * 12 FETCH (UID 6086 BODY[1] {688}
Mar 11 17:55:46 host roundcube[55967]: <4o4dvu76> [327B] S: /etc/cron.hourly/clamscan:\x0d
Mar 11 17:55:46 host roundcube[55967]: \x0d
Mar 11 17:55:46 host roundcube[55967]: ClamAV update process started at Mon Mar 11 17:01:01 2024\x0d
Mar 11 17:55:46 host roundcube[55967]: daily.cld database is up-to-date (version: 27211, sigs: 2054718, f-level: 90, builder: raynman)\x0d
Mar 11 17:55:46 host roundcube[55967]: main.cvd database is up-to-date (version: 62, sigs: 6647427, f-level: 90, builder: sigmgr)\x0d
Mar 11 17:55:46 host roundcube[55967]: bytecode.cld database is up-to-date (version: 335, sigs: 86, f-level: 90, builder: raynman)\x0d
Mar 11 17:55:46 host roundcube[55967]: \x0d
Mar 11 17:55:46 host roundcube[55967]: ----------- SCAN SUMMARY -----------\x0d
Mar 11 17:55:46 host roundcube[55967]: Known viruses: 8686419\x0d
Mar 11 17:55:46 host roundcube[55967]: Engine version: 0.103.11\x0d
Mar 11 17:55:46 host roundcube[55967]: Scanned directories: 7006\x0d
Mar 11 17:55:46 host roundcube[55967]: Scanned files: 26516\x0d
Mar 11 17:55:46 host roundcube[55967]: Infected files: 0\x0d
Mar 11 17:55:46 host roundcube[55967]: Data scanned: 323.52 MB\x0d
Mar 11 17:55:46 host roundcube[55967]: Data read: 206.80 MB (ratio 1.56:1)\x0d
Mar 11 17:55:46 host roundcube[55967]: Time: 127.525 sec (2 m 7 s)\x0d
Mar 11 17:55:46 host roundcube[55967]: Start Date: 2024:03:11 17:01:01\x0d
Mar 11 17:55:46 host roundcube[55967]: End Date:   2024:03:11 17:03:08\x0d
Mar 11 17:55:46 host roundcube[55967]: \x0d

I really want to switch from thunderbird to roundcube, so any help in how to diagnose this would be great.

ive enabled all the debugging suggested by many a forum post, but still cant see where this is happening.

regards peter

ps system is Rocky 8.9, PHP 7.4.33 , apache httpd 2.4.37-62, dovecot-2.3.16-4,

[SKaero]

Whats in the Roundcube error log located at <RC root>/logs/errors.log

[wintpe]

Hi Skaero
Thank you for replying.
the reason i did not post anything from the errors.log was.

cd /var/www/html/webmail/logs/
[root@host logs]# cat errors.log

[root@host logs]# ls -al
total 44248
drwxr-xr-x  2 apache apache     4096 Mar 28  2022 .
drwxr-xr-x 12 apache apache     4096 Mar 11 17:38 ..
-rw-r--r--  1 apache apache        1 Mar  9 09:38 errors.log
-rw-r--r--  1 apache apache      164 Oct 17  2021 .htaccess
-rw-r--r--  1 apache apache 39425705 Mar 11 17:49 imap.log
-rw-r--r--  1 apache apache   205024 Mar 11 17:25 ldap.log
-rw-r--r--  1 apache apache     3318 Mar 11 14:07 sendmail.log
-rw-r--r--  1 apache apache    97772 Mar 11 14:07 smtp.log
-rw-r--r--  1 apache apache  5534301 Mar 11 17:49 sql.log

in addition to your question, ill assume you might want my log settings.

from /var/www/html/webmail/config/config.inc.php

$config['debug_level'] = 10;

// Log SQL queries
$config['sql_debug'] = true;

// Log IMAP conversation
$config['imap_debug'] = true;

// Log LDAP conversation
$config['ldap_debug'] = true;

// Log SMTP conversation
$config['smtp_debug'] = true;
$config['log_driver'] = 'syslog';
$config['syslog_facility'] = LOG_MAIL;

and from php.ini

error_reporting
   Default Value: E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED
   Development Value: E_ALL
   Production Value: E_ALL & ~E_DEPRECATED & ~E_STRICT

log_errors
   Default Value: on
   Development Value: On
   Production Value: On

the logs i gave in my first post come from maillog, but they are pretty much the same as what goes into imap.log.

the apache logs may be off assistance to you, but i cant fathom out where they are comming from, in the maillog there is a line as follows.

Mar 12 10:19:51 host roundcube[108700]: <l9ik2lel> [7B74] C: A0002 ID ("name" "Roundcube" "version" "1.6.6" "php" "7.4.33" "os" "Linux" "command" "/webmail/?_task=mail&_caps=pdf%3D1%2Cflash%3D0%2Ctiff%3D0%2Cwebp%3D1%2Cpgpmime%3D0&_uid=6137&_mbox=INBOX&_framed=1&_action=preview")

and that lines up with the 500 error from httpd as follows.

ipaddress - - [12/Mar/2024:10:19:51 +0000] "GET /webmail/?_task=mail&_caps=pdf%3D1%2Cflash%3D0%2Ctiff%3D0%2Cwebp%3D1%2Cpgpmime%3D0&_uid=6137&_mbox=INBOX&_framed=1&_action=preview HTTP/1.1" 500 634 "http://host:/webmail/?_task=mail&_mbox=INBOX" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36"

the apache error log has no error log matching the event, the last log to it was yesterday when i restarted httpd, so not relevant to today's replay of the error


regards peter

[SKaero]

Right now errors would be in the system log so you could check there or change the "log_driver" config option to "file" and then the error should be posted to the <RC root>/logs/errors.log file.

[wintpe]

OK well as you can see from the output bellow

[root@host logs]# ls -al
total 44400
drwxr-xr-x  2 apache apache     4096 Mar 28  2022 .
drwxr-xr-x 12 apache apache     4096 Mar 11 17:38 ..
-rw-r--r--  1 apache apache        1 Mar  9 09:38 errors.log
-rw-r--r--  1 apache apache      164 Oct 17  2021 .htaccess
-rw-r--r--  1 apache apache 39538157 Mar 12 16:17 imap.log
-rw-r--r--  1 apache apache   206658 Mar 12 16:17 ldap.log
-rw-r--r--  1 apache apache     3318 Mar 11 14:07 sendmail.log
-rw-r--r--  1 apache apache    97772 Mar 11 14:07 smtp.log
-rw-r--r--  1 apache apache  5579817 Mar 12 16:17 sql.log
[root@host logs]# cat ../config/config.inc.php|grep file
$config['log_driver'] = 'file';
[root@host logs]# systemctl restart httpd
[root@host logs]# ls -al
total 44548
drwxr-xr-x  2 apache apache     4096 Mar 28  2022 .
drwxr-xr-x 12 apache apache     4096 Mar 11 17:38 ..
-rw-r--r--  1 apache apache        1 Mar  9 09:38 errors.log
-rw-r--r--  1 apache apache      164 Oct 17  2021 .htaccess
-rw-r--r--  1 apache apache 39669723 Mar 12 16:18 imap.log
-rw-r--r--  1 apache apache   206658 Mar 12 16:17 ldap.log
-rw-r--r--  1 apache apache     3318 Mar 11 14:07 sendmail.log
-rw-r--r--  1 apache apache    97772 Mar 11 14:07 smtp.log
-rw-r--r--  1 apache apache  5600263 Mar 12 16:18 sql.log
[root@host logs]#


I forced the error in the web interface 10 times, and nothing....


regards peter

[wintpe]

ok digging around in /var/log with a find . -type f -exec grep -i roundcube {} \; -print
I found that /var/log/php-fpm/www-error.log
has the following errors every single time the error of somethings went wrong hows.

[12-Mar-2024 16:28:16 UTC] PHP Fatal error:  Uncaught Error: Class 'DKIM_Verify' not found in /var/www/html/webmail/plugins/authres_status/authres_status.php:436
Stack trace:
#0 /var/www/html/webmail/plugins/authres_status/authres_status.php(242): authres_status->get_authentication_status()
#1 /var/www/html/webmail/plugins/authres_status/authres_status.php(247): authres_status->populate_message_headers()
#2 /var/www/html/webmail/program/lib/Roundcube/rcube_plugin_api.php(520): authres_status->message_headers()
#3 /var/www/html/webmail/program/actions/mail/show.php(537): rcube_plugin_api->exec_hook()
#4 /var/www/html/webmail/program/include/rcmail_output_html.php(1484): rcmail_action_mail_show::message_headers()
#5 [internal function]: rcmail_output_html->xml_command()
#6 /var/www/html/webmail/program/include/rcmail_output_html.php(1322): preg_replace_callback()
#7 /var/www/html/webmail/program/include/rcmail_output_html.php(825): rcmail_output_html->parse_xml()
#8 /var/www/html/webmail/program/include/rcmail_output_html.php(654): rcmail_output_html->par in /var/www/html/webmail/plugins/authres_status/authres_status.php on line 436

seems im not the first.......    https://github.com/pimlie/authres_status/issues/49  and this is the latest roundcube version.

removing authres_status plugin fixes the problem.
regards peter

regards peter