V5 on docker restarting and health check pending jobs

I just installed V5 on docker and migrated my v4 install to v5. I had a few issues with expenses where payment methods just seem to be random but otherwise everything seems to have migrated fine.

But watching the docker logs my app service restarts every 5 minutes, it looks like artisan runs queue:restart and then everything shuts down and starts back up, is that normal? that seems like it would cause issues if im in the middle of a request when it happens?

The health check also shows some pending jobs that I can find no indication of what they are or how to correct it. It was at 7 this morning and is up to 9 pending jobs now.

Hi,

@david any thoughts?

I’m just realizing the logs might be helpful for the restarting. I’m not where I can ssh into the server right now when I get to where I can i’ll reply with them as well.

1 Like

app_1 | Configuration cache cleared!
app_1 | Configuration cached successfully!
app_1 | Configuration cache cleared!
app_1 | Configuration cached successfully!
app_1 | Route cache cleared!
app_1 | Routes cached successfully!
app_1 | Files cached successfully!
app_1 | Nothing to migrate.
app_1 | 2021-06-08 18:55:17,440 WARN For [program:php-fpm], redirect_stderr=true but stderr_logfile has also been set to a filename, the filename has been ignored
app_1 | 2021-06-08 18:55:17,440 WARN For [program:scheduler], redirect_stderr=true but stderr_logfile has also been set to a filename, the filename has been ignored
app_1 | 2021-06-08 18:55:17,440 WARN For [program:queue-worker], redirect_stderr=true but stderr_logfile has also been set to a filename, the filename has been igno
red
app_1 | 2021-06-08 18:55:17,440 WARN For [program:queue-worker], redirect_stderr=true but stderr_logfile has also been set to a filename, the filename has been igno
red
app_1 | 2021-06-08 18:55:17,443 INFO supervisord started with pid 1
app_1 | 2021-06-08 18:55:18,448 INFO spawned: ‘shutdown’ with pid 67
app_1 | 2021-06-08 18:55:18,451 INFO spawned: ‘php-fpm’ with pid 68
app_1 | 2021-06-08 18:55:18,454 INFO spawned: ‘queue-worker_00’ with pid 69
app_1 | 2021-06-08 18:55:18,458 INFO spawned: ‘queue-worker_01’ with pid 70
app_1 | 2021-06-08 18:55:18,460 INFO spawned: ‘scheduler’ with pid 71
app_1 | READY
app_1 | [08-Jun-2021 18:55:18] NOTICE: [pool www] ‘user’ directive is ignored when FPM is not running as root
app_1 | [08-Jun-2021 18:55:18] NOTICE: [pool www] ‘user’ directive is ignored when FPM is not running as root
app_1 | [08-Jun-2021 18:55:18] NOTICE: [pool www] ‘group’ directive is ignored when FPM is not running as root
app_1 | [08-Jun-2021 18:55:18] NOTICE: [pool www] ‘group’ directive is ignored when FPM is not running as root
app_1 | [08-Jun-2021 18:55:18] NOTICE: fpm is running, pid 68
app_1 | [08-Jun-2021 18:55:18] NOTICE: ready to handle connections
app_1 | Schedule worker started successfully.
app_1 | 2021-06-08 18:55:19,769 INFO success: shutdown entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
app_1 | 2021-06-08 18:55:19,770 INFO success: php-fpm entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
app_1 | 2021-06-08 18:55:19,771 INFO success: queue-worker_00 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
app_1 | 2021-06-08 18:55:19,771 INFO success: queue-worker_01 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
app_1 | 2021-06-08 18:55:19,771 INFO success: scheduler entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
app_1 |
app_1 | [2021-06-08T18:56:00+00:00] Execution #1 output:
app_1 | No scheduled commands are ready to run.
app_1 |
app_1 | [2021-06-08T18:57:00+00:00] Execution #2 output: app_1 | No scheduled commands are ready to run.
app_1 | app_1 | [2021-06-08T18:58:00+00:00] Execution #3 output:
app_1 | No scheduled commands are ready to run.
app_1 |
app_1 | [2021-06-08T18:59:00+00:00] Execution #4 output:
app_1 | No scheduled commands are ready to run.
app_1 |
app_1 | [2021-06-08T19:00:00+00:00] Execution #5 output:
app_1 | Running scheduled command: App\Jobs\Cron\RecurringInvoicesCron
app_1 | Running scheduled command: App\Jobs\Util\SchedulerCheck
app_1 | Running scheduled command: ‘/usr/local/bin/php’ ‘artisan’ queue:restart > ‘/dev/null’ 2>&1
app_1 | 2021-06-08 19:00:02,160 INFO exited: queue-worker_00 (exit status 0; expected)
app_1 | 2021-06-08 19:00:02,160 INFO exited: queue-worker_01 (exit status 0; expected)
app_1 | 2021-06-08 19:00:03,168 INFO spawned: ‘queue-worker_00’ with pid 134
app_1 | 2021-06-08 19:00:03,173 INFO spawned: ‘queue-worker_01’ with pid 135
app_1 | 2021-06-08 19:00:03,174 WARN received SIGQUIT indicating exit request
app_1 | 2021-06-08 19:00:03,174 INFO waiting for shutdown, php-fpm, queue-worker_00, queue-worker_01, scheduler to die
app_1 | Processing Event: ver:3.0 server:supervisor serial:0 pool:shutdown poolserial:0 eventname:PROCESS_STATE_EXITED len:87
app_1 | [2021-06-08 19:00:03][301] Processing: App\Jobs\Util\SchedulerCheck
app_1 | 2021-06-08 19:00:03,527 INFO stopped: scheduler (terminated by SIGTERM)
app_1 | 2021-06-08 19:00:03,531 INFO stopped: queue-worker_01 (terminated by SIGTERM)
app_1 | 2021-06-08 19:00:03,532 INFO stopped: queue-worker_00 (terminated by SIGTERM)
app_1 | [08-Jun-2021 19:00:03] NOTICE: Terminating …
app_1 | [08-Jun-2021 19:00:03] NOTICE: exiting, bye-bye!
app_1 | 2021-06-08 19:00:03,539 INFO stopped: php-fpm (exit status 0)
app_1 | 2021-06-08 19:00:03,540 INFO stopped: shutdown (terminated by SIGTERM)
invoiceninja_app_1 exited with code 0

I think i know the issue on this one, i’ll check in a fix.

Just updated to 5.1.74 and over the past hour no restarts so the restarting issue looks completely solved. Health Check is still showing 25 “pending jobs” is that something I need to worry about?

I see a bunch of stuff was updated to migration with the past two versions as well. I’m probably going to try a redo on the migration as well.

Are emails being sent?

I was able to email a quote without issue. I don’t have any reoccuring invoices or reminders scheduled to go out for a bit so I dont know of the auto stuff is working. I’ll schedule an invoice for tomorrow to test

@david do you have any other suggestions to debug?

I think the queue count has been throwing bogus numbers for a range of users - we may need to remove this.

Is there a way to check the count manually?

I have the same crash on a fresh install of the v5 on my unraid server using docker. In my case, it’s not restarting once it crash.

[2021-06-17T03:05:00+00:00] Execution #4 output:
Running scheduled command: App\Jobs\Util\SchedulerCheck
Running scheduled command: '/usr/local/bin/php' 'artisan' queue:restart > '/dev/null' 2>&1
2021-06-17 03:05:00,491 INFO exited: queue-worker_00 (exit status 0; expected)
2021-06-17 03:05:01,493 INFO spawned: 'queue-worker_00' with pid 169
2021-06-17 03:05:01,493 INFO exited: queue-worker_01 (exit status 0; expected)
Processing Event: ver:3.0 server:supervisor serial:0 pool:shutdown poolserial:0 eventname:PROCESS_STATE_EXITED len:87
2021-06-17 03:05:01,494 INFO spawned: 'queue-worker_01' with pid 170
2021-06-17 03:05:01,494 WARN received SIGQUIT indicating exit request
2021-06-17 03:05:01,495 INFO waiting for shutdown, nginx_00, php-fpm, queue-worker_00, queue-worker_01, scheduler to die
2021-06-17 03:05:01,497 INFO stopped: scheduler (terminated by SIGTERM)
2021-06-17 03:05:01,498 INFO stopped: queue-worker_01 (terminated by SIGTERM)
2021-06-17 03:05:01,498 INFO stopped: queue-worker_00 (terminated by SIGTERM)
[17-Jun-2021 03:05:01] NOTICE: Terminating ...
[17-Jun-2021 03:05:01] NOTICE: exiting, bye-bye!
2021-06-17 03:05:01,505 INFO stopped: php-fpm (exit status 0)
2021-06-17 03:05:01,532 INFO stopped: nginx_00 (exit status 0)
2021-06-17 03:05:01,532 INFO stopped: shutdown (terminated by SIGTERM)
/usr/lib/python3.8/site-packages/supervisor/options.py:473: UserWarning: Supervisord is running as root and it is searching for its configuration file in default locations (including its current working directory); you probably want to specify a "-c" argument specifying an absolute path to a configuration file for improved security.
self.warnings.warn(

The latest v5 release no longer calls queue:restart in docker so that issue should be fixed, are you sure you’re up to date? The actual restart was handled by docker, so mine was restarting once it shut down because i had my docker restart policy set to always.

I updated to the last version.

It seems like it was stable at first but, it stills crash with almost the same error. The only difference is that I get this crash a few hours after I started the docker.

[2021-06-23T21:05:00+00:00] Execution #454 output:
[2021-06-23T21:05:00+00:00] Running scheduled command: App\Jobs\Util\SchedulerCheck
[2021-06-23 21:05:01][1019] Processing: App\Jobs\Util\SchedulerCheck
PHP Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 20480 bytes) in /var/www/app/vendor/laravel/framework/src/Illuminate/Foundation/PackageManifest.php on line 123

PHP Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 20480 bytes) in /var/www/app/vendor/laravel/framework/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php on line 129

2021-06-23 21:05:02,325 INFO exited: queue-worker_00 (exit status 255; not expected)
2021-06-23 21:05:03,327 INFO spawned: 'queue-worker_00' with pid 3294
2021-06-23 21:05:03,328 WARN received SIGQUIT indicating exit request
2021-06-23 21:05:03,328 INFO waiting for shutdown, nginx_00, php-fpm, queue-worker_00, queue-worker_01, scheduler to die
Processing Event: ver:3.0 server:supervisor serial:0 pool:shutdown poolserial:0 eventname:PROCESS_STATE_EXITED len:87
2021-06-23 21:05:03,331 INFO stopped: scheduler (terminated by SIGTERM)
2021-06-23 21:05:03,331 INFO stopped: queue-worker_00 (terminated by SIGTERM)
2021-06-23 21:05:03,336 INFO stopped: queue-worker_01 (terminated by SIGTERM)
[23-Jun-2021 21:05:03] NOTICE: Terminating ...
[23-Jun-2021 21:05:03] NOTICE: exiting, bye-bye!
2021-06-23 21:05:03,343 INFO stopped: php-fpm (exit status 0)
2021-06-23 21:05:03,374 INFO stopped: nginx_00 (exit status 0)
2021-06-23 21:05:03,374 INFO stopped: shutdown (terminated by SIGTERM)
/usr/lib/python3.8/site-packages/supervisor/options.py:473: UserWarning: Supervisord is running as root and it is searching for its configuration file in default locations (including its current working directory); you probably want to specify a "-c" argument specifying an absolute path to a configuration file for improved security.
self.warnings.warn(