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.
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.
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
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.
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
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.
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(
I am having the exact same issue on basically a brand new install of invoice ninja v5 (I am on latest version but its been occurring on earlier versions as well).
I also use it as a docker container on an unraid server
Tried to inscrease the memory to 256mb but it still crash after much longer time
[2021-07-04T16:40:00+00:00] Execution #1135 output:
[2021-07-04T16:40:00+00:00] Running scheduled command: App\Jobs\Util\SchedulerCheck
[2021-07-04 16:40:00][2623] Processing: App\Jobs\Util\SchedulerCheck
PHP Fatal error: Allowed memory size of 268435456 bytes exhausted (tried to allocate 413696 bytes) in /var/www/app/vendor/laravel/framework/src/Illuminate/Filesystem/Filesystem.php on line 54
PHP Fatal error: Allowed memory size of 268435456 bytes exhausted (tried to allocate 32768 bytes) in /var/www/app/vendor/symfony/string/AbstractUnicodeString.php on line 48
2021-07-04 16:40:01,494 INFO exited: queue-worker_01 (exit status 255; not expected)
2021-07-04 16:40:02,496 INFO spawned: 'queue-worker_01' with pid 8060
2021-07-04 16:40:02,496 WARN received SIGQUIT indicating exit request
2021-07-04 16:40:02,496 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-07-04 16:40:02,497 INFO stopped: scheduler (terminated by SIGTERM)
2021-07-04 16:40:02,503 INFO stopped: queue-worker_00 (terminated by SIGTERM)
2021-07-04 16:40:05,507 INFO waiting for shutdown, nginx_00, php-fpm, queue-worker_01 to die
2021-07-04 16:40:08,510 INFO waiting for shutdown, nginx_00, php-fpm, queue-worker_01 to die
2021-07-04 16:40:11,514 INFO waiting for shutdown, nginx_00, php-fpm, queue-worker_01 to die
2021-07-04 16:40:12,515 WARN killing 'queue-worker_01' (8060) with SIGKILL
2021-07-04 16:40:12,517 INFO stopped: queue-worker_01 (terminated by SIGKILL)
[04-Jul-2021 16:40:12] NOTICE: Terminating ...
[04-Jul-2021 16:40:12] NOTICE: exiting, bye-bye!
2021-07-04 16:40:12,524 INFO stopped: php-fpm (exit status 0)
2021-07-04 16:40:12,540 INFO stopped: nginx_00 (exit status 0)
2021-07-04 16:40:12,540 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(