Passbolt emails are created in DB but not sent [incorrect server time]

MartinS · June 20, 2023, 10:20am

Checklist
[y] I have read intro post: About the Installation Issues category
[y] I have read the tutorials, help and searched for similar issues
[y] I provide relevant information about my server (component names and versions, etc.)
[y] I provide a copy of my logs and healthcheck
[y] I describe the steps I have taken to trouble shoot the problem
[y] I describe the steps on how to reproduce the issue

Server information:

Ubuntu 20.04.6 LTS
*Passbolt 4.0.2

Healthcheck:
____ __ ____
/ __ ____ _____ / / ____ / / /
/ // / __ `/ / / __ / __ / / _/
/ / // ( | ) // / // / / /
// _,///./_//__/

Open source password manager for teams

Healthcheck shell

Environment

[PASS] PHP version 7.4.3-4ubuntu2.18.
[PASS] PCRE compiled with unicode support.
[PASS] The temporary directory and its content are writable and not executable.
[PASS] The logs directory and its content are writable.
[PASS] GD or Imagick extension is installed.
[PASS] Intl extension is installed.
[PASS] Mbstring extension is installed.

Config files

[PASS] The application config file is present
[PASS] The passbolt config file is present

Core config

[PASS] Debug mode is off.
[PASS] Cache is working.
[PASS] Unique value set for security.salt
[PASS] Full base url is set to link
[PASS] App.fullBaseUrl validation OK.
[PASS] /healthcheck/status is reachable.

SSL Certificate

[FAIL] SSL peer certificate does not validate
[FAIL] Hostname does not match when validating certificates.
[WARN] Using a self-signed certificate
[HELP] Check link
[HELP] cURL Error (60) SSL certificate problem: self signed certificate

Database

[PASS] The application is able to connect to the database
[PASS] 30 tables found
[PASS] Some default content is present
[PASS] The database schema up to date.

GPG Configuration

[PASS] PHP GPG Module is installed and loaded.
[PASS] The environment variable GNUPGHOME is set to /var/lib/passbolt/.gnupg.
[PASS] The directory /var/lib/passbolt/.gnupg containing the keyring is writable by the webserver user.
[PASS] The server OpenPGP key is not the default one
[PASS] The public key file is defined in /etc/passbolt/passbolt.php and readable.
[PASS] The private key file is defined in /etc/passbolt/passbolt.php and readable.
[PASS] The server key fingerprint matches the one defined in /etc/passbolt/passbolt.php.
[PASS] The server public key defined in the /etc/passbolt/passbolt.php (or environment variables) is in the keyring.
[PASS] There is a valid email id defined for the server key.
[PASS] The public key can be used to encrypt a message.
[PASS] The private key can be used to sign a message.
[PASS] The public and private keys can be used to encrypt and sign a message.
[PASS] The private key can be used to decrypt a message.
[PASS] The private key can be used to decrypt and verify a message.
[PASS] The public key can be used to verify a signature.
[PASS] The server public key format is Gopengpg compatible.
[PASS] The server private key format is Gopengpg compatible.

Application configuration

[PASS] Using latest passbolt version (4.0.2).
[PASS] Passbolt is configured to force SSL use.
[PASS] App.fullBaseUrl is set to HTTPS.
[PASS] Selenium API endpoints are disabled.
[PASS] Search engine robots are told not to index content.
[INFO] The Self Registration plugin is enabled.
[INFO] Registration is closed, only administrators can add users.
[WARN] The deprecated self registration public setting was found in /etc/passbolt/passbolt.php.
[HELP] You may remove the “passbolt.registration.public” setting.
[WARN] Host availability checking is disabled.
[HELP] Make sure this instance is not publicly available on the internet.
[HELP] Or set the PASSBOLT_EMAIL_VALIDATE_MX environment variable to true.
[HELP] Or set passbolt.email.validate.mx to true in /etc/passbolt/passbolt.php.
[PASS] Serving the compiled version of the javascript app.
[WARN] Some email notifications are disabled by the administrator.

JWT Authentication

[PASS] The JWT Authentication plugin is enabled
[PASS] The /etc/passbolt/jwt/ directory is not writable.
[PASS] A valid JWT key pair was found

SMTP Settings

[PASS] The SMTP Settings plugin is enabled.
[PASS] SMTP Settings coherent. You may send a test email to validate them.
[PASS] The SMTP Settings source is: database.
[WARN] The SMTP Settings plugin endpoints are enabled.
[HELP] It is recommended to disable the plugin endpoints.
[HELP] Set the PASSBOLT_SECURITY_SMTP_SETTINGS_ENDPOINTS_DISABLED environment variable to true.
[HELP] Or set passbolt.security.smtpSettings.endpointsDisabled to true in /etc/passbolt/passbolt.php.

[FAIL] 2 error(s) found. Hang in there!

Troubleshooting so far:
*I have looked in MySQL DB email_queue and found emails are created,
*I have an error in /var/log/passbolt.log, will post in separate post,
*Test emails from OS via cake and via GUI are sent,
*Checked cron job status and is active.

Steps to reproduce:
Trying to reactivate new account does not sent a recovery email but it is created in DB.

Best regards,
Martin

MartinS · June 20, 2023, 10:22am

2023-06-20 07:42:01 Notice: Notice (8): unserialize(): Error at offset 0 of 1240 bytes in [/var/www/passbolt/vendor/lorenzo/cakephp-email-queue/src/Database/Type/SerializeType.php, line 22]

2023-06-20 07:42:01 Notice: Notice (8): unserialize(): Error at offset 0 of 35 bytes in [/var/www/passbolt/vendor/lorenzo/cakephp-email-queue/src/Database/Type/SerializeType.php, line 22]

2023-06-20 07:42:01 Notice: Notice (8): unserialize(): Error at offset 0 of 2 bytes in [/var/www/passbolt/vendor/lorenzo/cakephp-email-queue/src/Database/Type/SerializeType.php, line 22]

2023-06-20 07:42:01 Notice: Notice (8): Undefined variable: body in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 18]

2023-06-20 07:42:01 Notice: Notice (8): Trying to access array offset on value of type null in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 18]

2023-06-20 07:42:01 Notice: Notice (8): Undefined variable: body in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 20]

2023-06-20 07:42:01 Notice: Notice (8): Trying to access array offset on value of type null in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 20]

2023-06-20 07:42:01 Notice: Notice (8): Undefined variable: body in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 21]

2023-06-20 07:42:01 Notice: Notice (8): Trying to access array offset on value of type null in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 21]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘profile’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 24]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘avatar’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 24]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘url’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 24]

2023-06-20 07:42:01 Notice: Notice (8): Trying to access array offset on value of type null in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 24]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘username’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 26]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘profile’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 27]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘first_name’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 27]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘profile’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 28]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘last_name’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 28]

2023-06-20 07:42:01 Notice: Notice (8): Trying to get property ‘created’ of non-object in [/var/www/passbolt/src/Template/Email/html/AN/user_recover.ctp, line 29]

()

You have initiated an account recovery!

clayton · June 20, 2023, 11:47am

hey @MartinS welcome to the forum! Since you took a look at the email_queue table already was there anything in the error column there?

MartinS · June 20, 2023, 12:28pm

Nope, all are NULL, sent 0 , sent tries 0.

Forgot to add. This started happening after upgrading from v2 something. I also had to upgrade Ubuntu from v18 to v20. It probably does have something to do with either of the upgrades.

clayton · June 20, 2023, 12:55pm

You are also using a from source install and not the package, correct?

Could you check the logs for cron here to see if the job is outputting any errors?
The sent and tries both being 0 seems to point to the cronjob not actually running. Another option here is to just trigger the command from the cronjob and see if you get any output that could help?

Otherwise depending on how much time you want to spend digging into this you could always migrate to the package and/or a new vm.

MartinS · June 20, 2023, 1:14pm

Both cron logs are empty and when I manually run the cron command it returns no messages.

Cron command:
sudo -H -u www-data bash -c “/usr/share/php/passbolt/bin/cron”

Initially it was installed via install scripts and I used this guide to upgrade to latest and greatest.

clayton · June 20, 2023, 1:26pm

actually for the email sending could you run:
sudo -H -u www-data bash -c "/usr/share/php/passbolt/bin/cake EmailQueue.sender"

since you followed the migrate process I am surprised that it is still trying to use /var/www/passbolthere

MartinS · June 20, 2023, 1:49pm

Also tried that command with nothing happening. Tho the preview command does find all emails that need to be sent.
sudo -H -u www-data bash -c "/usr/share/php/passbolt/bin/cake EmailQueue.preview"

I did not delete the previous folder /var/www/passbolt as instructed in the guide. Could that be an issue?

garrett · June 20, 2023, 2:28pm

The old cron job was run after setting with crontab. You could maybe find it with sudo crontab - e or maybe mirror the above commands with www-data as it might be under that user crontab.

The new one is found in /etc/cron.d

I’m trying to think how one may be competing with the other on the same database and maybe an error is getting thrown too early in the process for it to produce a mail error.

The old cron job should be removed.

MartinS · June 20, 2023, 2:43pm

Found the old entry in crontab - e and removed it.

Reran the command to send emails with no luck.

MartinS · June 20, 2023, 2:49pm

But sudo journalctl -fu cron.service still shows that its running both:

Jun 20 14:48:01 passbolt CRON[1272175]: pam_unix(cron:session): session opened for user www-data by (uid=0)
Jun 20 14:48:01 passbolt CRON[1272176]: (www-data) CMD ($PASSBOLT_BASE_DIR/bin/cron > $PASSBOLT_LOG_DIR/cron.log 2> $PASSBOLT_LOG_DIR/cron-error.log)
Jun 20 14:48:01 passbolt CRON[1272174]: pam_unix(cron:session): session opened for user www-data by (uid=0)
Jun 20 14:48:01 passbolt CRON[1272177]: (www-data) CMD (/var/www/passbolt/bin/cake EmailQueue.sender >> /var/log/passbolt.log)
Jun 20 14:48:01 passbolt CRON[1272174]: pam_unix(cron:session): session closed for user www-data
Jun 20 14:48:01 passbolt CRON[1272175]: pam_unix(cron:session): session closed for user www-data

garrett · June 20, 2023, 3:29pm

It looks like 3 separate processes actually.

Is there also one found with sudo -u www-data crontab -e?

MartinS · June 21, 2023, 6:31am

As mentioned previously I deleted the job from www-data crontab. I also check admin user and root users crontabs and neither have this job set.

What do you mean 3 processes? I only see 2 separate log entries or did I miss something?

Thanks everyone for all the help so far!

garrett · June 21, 2023, 11:59am

Are you still getting the errors in the passbolt log showing CRON calls to the old path files at /var/www?

Any errors in the php logs? System logs?

MartinS · June 21, 2023, 12:28pm

The current state. I check all users crontabs and no jobs are scheduled.

sudo journalctl -fu cron.service shows:
Jun 21 12:21:01 passbolt CRON[1355567]: pam_unix(cron:session): session opened for user www-data by (uid=0)
Jun 21 12:21:01 passbolt CRON[1355568]: pam_unix(cron:session): session opened for user www-data by (uid=0)
Jun 21 12:21:01 passbolt CRON[1355569]: (www-data) CMD ($PASSBOLT_BASE_DIR/bin/cron > $PASSBOLT_LOG_DIR/cron.log 2> $PASSBOLT_LOG_DIR/cron-error.log)
Jun 21 12:21:01 passbolt CRON[1355570]: (www-data) CMD (/var/www/passbolt/bin/cake EmailQueue.sender >> /var/log/passbolt.log)
Jun 21 12:21:02 passbolt CRON[1355567]: pam_unix(cron:session): session closed for user www-data
Jun 21 12:21:02 passbolt CRON[1355568]: pam_unix(cron:session): session closed for user www-data

syslog is showing:
Jun 21 12:27:57 passbolt multipathd[670]: sda: add missing path
Jun 21 12:27:57 passbolt multipathd[670]: sda: failed to get udev uid: Invalid argument
Jun 21 12:27:57 passbolt multipathd[670]: sda: failed to get sysfs uid: Invalid argument
Jun 21 12:27:57 passbolt multipathd[670]: sda: failed to get sgio uid: No such file or directory
Jun 21 12:28:01 passbolt CRON[1356019]: (www-data) CMD (/var/www/passbolt/bin/cake EmailQueue.sender >> /var/log/passbolt.log)
Jun 21 12:28:01 passbolt CRON[1356021]: (www-data) CMD ($PASSBOLT_BASE_DIR/bin/cron > $PASSBOLT_LOG_DIR/cron.log 2> $PASSBOLT_LOG_DIR/cron-error.log)
Jun 21 12:28:02 passbolt multipathd[670]: sda: add missing path
Jun 21 12:28:02 passbolt multipathd[670]: sda: failed to get udev uid: Invalid argument
Jun 21 12:28:02 passbolt multipathd[670]: sda: failed to get sysfs uid: Invalid argument
Jun 21 12:28:02 passbolt multipathd[670]: sda: failed to get sgio uid: No such file or directory

cron.log and cron-error.log are empty.
passbolt.log shows nothing relevant. Last entry was yesterday (second post here).
php logs are empty.

garrett · June 21, 2023, 1:59pm

Sorry it’s not clear: are the logs showing a job still running?

There should be just the one from /etc/cron.d but it should be calling the path related to the new package, not the old /var/www path.

MartinS · June 22, 2023, 6:20am

As far as I now this tells a job is being ran:

Jun 21 12:21:01 passbolt CRON[1355567]: pam_unix(cron:session): session opened for user www-data by (uid=0)
Jun 21 12:21:01 passbolt CRON[1355568]: pam_unix(cron:session): session opened for user www-data by (uid=0)

Jun 21 12:21:01 passbolt CRON[1355569]: (www-data) CMD ($PASSBOLT_BASE_DIR/bin/cron > $PASSBOLT_LOG_DIR/cron.log 2> $PASSBOLT_LOG_DIR/cron-error.log)

Jun 21 12:21:01 passbolt CRON[1355570]: (www-data) CMD (/var/www/passbolt/bin/cake EmailQueue.sender >> /var/log/passbolt.log)

Jun 21 12:21:02 passbolt CRON[1355567]: pam_unix(cron:session): session closed for user www-data
Jun 21 12:21:02 passbolt CRON[1355568]: pam_unix(cron:session): session closed for user www-data

MartinS · June 22, 2023, 8:20am

I found another entry for the old cron job and managed to remove it. Now I see only one instance of the job running.

Mails are still not going out tho.

clayton · June 22, 2023, 9:17am

and still no errors or sent/tries changes in the email_queue table?

MartinS · June 22, 2023, 9:29am

No errors, no logs, DB is still sent 0, sent tries 0, errors NULL.