Artisan:queue not sending invoice to client, unable to revert setup

Hi there, earlier last month, i have followed the docs to use external queue. Instead of going with cron or supervisord, i went with systemd:

[Unit]
Description=InvoiceNinja queue worker

[Service]
User=www-data
Group=www-data
Restart=on-failure
ExecStart=/usr/bin/php /path/to/ninja/artisan queue:work --daemon --env=production

[Install]
WantedBy=multi-user.target
QUEUE_CONNECTION=database
INTERNAL_QUEUE_ENABLED=false

What i have noticed way too late was that invoices to clients weren’t send… or maybe they did in the beginning, not sure about one invoice. However i’ve received the notification emails! - until later though: earlier this month i have noticed that test-offerings did not send me any emails.
Now i know that i wasn’t paid yet because nothing was sent to my clients (later in december).

I have mistakenly added -d register_argc_argv=On, however correcting the setup last night didn’t change a thing. I am not sure if i also had the schedule cron still there or if i have added it for testing last night.

I yesterday have testwise run artisan queue:work manually to work down the pile of scheduled tasks - it went stuck a bunch of times, sent me my notification emails, followed by the note that it could not send the invoices. Also not new ones for testing! Also a few queue tasks did not get processed. No helpful log output!

I have disabled the systemd service and went with cron, but it didn’t send anything either over the night.


I cannot revert to the “normal” setup

Eventually i have tried to revert my setup to the internal queue this morning. It doesn’t do anything either. I used to use the direct artisan path, but here is the current, only, cron entry under the www-data user:

* * * * * cd /path/ && php artisan schedule:run >> /path/cron.log #/dev/null 2>&1
# other stuff now commented

I have tried:

QUEUE_CONNECTION=database
#INTERNAL_QUEUE_ENABLED=false
QUEUE_CONNECTION=database
INTERNAL_QUEUE_ENABLED=true
# (current)
QUEUE_CONNECTION=sync
INTERNAL_QUEUE_ENABLED=true

I have also tried to force an update, to do queue:restart, to run update tasks i am aware of:

  • sudo -u www-data /usr/bin/php artisan optimize
  • sudo -u www-data /usr/bin/php7.4 artisan config:cache
  • made sure the recent update is complete by running composer, migrate
  • view:clear :man_shrugging:
  • sudo -u www-data /usr/bin/php artisan ninja:post-update # i am not using git though

Recent cron log:

[2022-01-08T09:50:01+00:00] Running scheduled command: Callback
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
[2022-01-08T09:55:01+00:00] Running scheduled command: Callback
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
[2022-01-08T10:00:02+00:00] Running scheduled command: App\Jobs\Util\ReminderJob
[2022-01-08T10:00:02+00:00] Running scheduled command: App\Jobs\Cron\RecurringInvoicesCron
[2022-01-08T10:00:02+00:00] Running scheduled command: Callback
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
[2022-01-08T10:05:01+00:00] Running scheduled command: Callback
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
No scheduled commands are ready to run.
[2022-01-08T10:10:01+00:00] Running scheduled command: Callback

Right now sending invoices times out!

No log generated, even with extended log flag!
TimeoutException after 0:00:30.000000: Future not completed


  • php v7.4.26
  • zip setup

Hi,

As a first step I suggest using the health check option in the app’s about dialog to confirm the changes to the .env file are being applied. You may need to run php artisan optimize to update the config cache.

Hey thanks for your reply. After each config change, i made sure to run the optimize command.

When initially trying to get the external queue working its jobs away, i’ve used this health modal to confirm the queue decrease. Right now it says “Queue not enabled”. There is no warning about crons not running.

@david do you have any suggestions?

@milan

It would be worth removing systemd configurations and ensure using ps aux | grep php that there are no current artisan commands running as a daemon

First thing after this would be to change QUEUE_CONNECTION=sync and confirm emails are sending correctly.

Once confirmed, then change back to QUEUE_CONNECTION=database

I would then follow the steps here to config the queues:

https://laravel.com/docs/8.x/queues#supervisor-configuration

once completed, check that the artisan commands are being run as daemon ps aux | grep php

and then reattempt sending emails.

I am sorry, the first part of your suggestion is pretty much what i did, and i ended up in timeouts :confused:

I have now just for the “fun” reactivated the systemd service with updated flags based on your link to --sleep=3 --tries=3 --max-time=3600, Restart=always (i may try supervisord, just not today and i didn’t understand yet what i might change) - i am now back at “only i receive the mail, rest of the queue is not processed.” Pending jobs: 14. After a restart of this service… silence.

if you are getting problems with

QUEUE_CONNECTION=sync

Then the problems are deeper here and there is something we are missing. It may help to check the failed_jobs table and inspect in there for any errors in the logs.

There i currently have one job with the following exception:

Illuminate\Queue\MaxAttemptsExceededException: App\Jobs\Entity\EmailEntity has been attempted too many times or run too long. The job may have previously timed out. in /path/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:750

Not sure what to check next… mysql/error.log is quiet…php7.4-fpm.log as well

I have looked at my mailservers logs as i find it suspicious that emails receive at my address (which is the same as IN is configured for). It doesn’t look like either Postfix or Rspamd are doing something here, but i find it weird that before it sends the notification for me, there are a few disconnects:

Jan 09 11:46:41 t1 postfix/submission/smtpd[001234]: connect from machine.with.invoiceninja[1.2.3.4]                                                                                                                   
Jan 09 11:46:41 t1 postfix/submission/smtpd[001234]: Anonymous TLS connection established from machine.with.invoiceninja[1.2.3.4]: TLSv1.2 with cipher DHE-RSA-CAMELLIA256-SHA256 (256/256 bits)                       
Jan 09 11:46:41 t1 postfix/submission/smtpd[001234]: 733263E0CA: client=machine.with.invoiceninja[1.2.3.4], sasl_method=LOGIN, sasl_username=hi@milan-ihl.de                                                           
Jan 09 11:46:41 t1 postfix/cleanup[353037]: 733263E0CA: message-id=<hash@swift.generated>
Jan 09 11:47:11 t1 postfix/submission/smtpd[001234]: lost connection after DATA (159510 bytes) from machine.with.invoiceninja[1.2.3.4]
Jan 09 11:47:11 t1 postfix/submission/smtpd[001234]: disconnect from machine.with.invoiceninja[1.2.3.4] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=0/1 commands=6/7
Jan 09 11:47:12 t1 postfix/submission/smtpd[001234]: connect from machine.with.invoiceninja[1.2.3.4]
Jan 09 11:48:42 t1 postfix/submission/smtpd[001234]: lost connection after CONNECT from machine.with.invoiceninja[1.2.3.4]
Jan 09 11:48:42 t1 postfix/submission/smtpd[001234]: disconnect from machine.with.invoiceninja[1.2.3.4] commands=0/0
Jan 09 11:48:43 t1 postfix/submission/smtpd[001234]: connect from machine.with.invoiceninja[1.2.3.4]
Jan 09 11:48:43 t1 postfix/submission/smtpd[001234]: Anonymous TLS connection established from machine.with.invoiceninja[1.2.3.4]: TLSv1.2 with cipher DHE-RSA-CAMELLIA256-SHA256 (256/256 bits)
Jan 09 11:48:44 t1 postfix/submission/smtpd[001234]: 0952A3E190: client=machine.with.invoiceninja[1.2.3.4], sasl_method=LOGIN, sasl_username=hi@milan-ihl.de
# Proceeds properly with this one

Update: i was able to verify that the processed email made it through Rspamd, but i couldn’t find the first ID that was followed by lost connection

Putting the app into debug does not seem to add anything to the laravel logs.

Huh, i somehow missed that there was an invoiceninja.log as well.
Now i have something new:
[2022-01-09 12:23:46] production.INFO: error failed with Unable to open file for reading [https://thatninjaofmine.de/storage/kJMM9VSzVvacFznKVzlMbP1KhyaxIKIFlfgpq24OBMNNheNWJc4B2Ecx5PhSILkf/documents/auyMNL76j1banxrgIF61dqXHfXWg00X0wW50x7h3.skr]

/documents/* is no existing path on the fs at least.

Part of: ./storage/framework/sessions/NE2<snip>OPO:a:3:{s:6:"_token";s:40:"UrE<snip>X5o";s:9:"_previous";a:1:{s:3:"url";s:156:"https://thatninjaofmine.de/storage/kJM<snip>Lkf/documents/auyMNL76j1banxrgIF61dqXHfXWg00X0wW50x7h3.skr?q=";}s:6:"_flash";a:2:{s:3:"old";a:0:{}s:3:"new";a:0:{}}}

I actually could not find any *.skr file in my invoiceninja directory.

I had my public key in .asc format(!!!) sitting under General → Company Info → Documents so it would be attached on invoice emails. After looking through the code, i was able to confirm my suspicion that it may have some sort of relation to this issue.

Selecting “View”, opened a new tab, greeting me with an error 500, for this very auyMNL76j1banxrgIF61dqXHfXWg00X0wW50x7h3.skr at its bad location, name and file extension.
Deleting it succeeded, even tho it locked up the Electron app.

This fixed my Ninja. I will mark this as solution, but i am sure that this is not supposed to happen. (And once again proved that pgp based email encryption is way too rarely used :wink: )