Fetch cycles blocked for 30mins following incomplete fetch cycle

[radarsymphony]

Summary

Fetching does not run during the first 30mins of the hour. We have gone through the Fetching FAQ:

• schedule:run is running,
• only one freescout:fetch-emails process is running,
• IMAP is set up and isn't the block - freescout fetches half the time.

The first fetch cycle of the hour does not complete in its entirety. Instead, it appears to be sent "signal 15" at 2min after the hour (see logs below). For the next 30min, the fetch cycle does not run. At 32mins after the hour, the killed process times out (I think) and for the second half of the hour, all inboxes fetch every 5mins as configured.

Our Environment & Config

• PHP version: 8.2
• FreeScout version: 1.8.80
• Fetching at 5min intervals,
• 66 mailboxes in our instance,
• Fetch cycle takes about 95 seconds to complete,
• Fetching alert sent/checked every 15mins

Fetching Sequence

To illustrate the issue, below is a typical hour ("xx" being any hour of the day):

Typical Sequence

Timeline

- **`xx:00:25` Fetch cycle starts but does not complete (stops xx:02:00)** - `xx:02:00` The process has been signaled with signal "15" appears in logs (logs posted below) - `xx:05:02` Doesn't run - `xx:10:02` Doesn't run - `xx:15:02` Doesn't run - `xx:16:xx` Fetching Problems notice sent/received - `xx:20:02` Doesn't run - `xx:25:02` Doesn't run - `xx:30:02` Doesn't run - `xx:32:00` ([I think a long-running fetch command is killed here based on the code and that fetching starts working again after this point.](https://github.com/freescout-helpdesk/freescout/commit/313cd61975f8d6b65cd809429b2d4379c8355ec2#diff-3e91b9df26f6ed49ead694c97ddcddf5f3c3e878390064d0b8849f22d54e5603R111)) - **`xx:35:02` Starts running again and completes successfully** - `xx:38:xx` Fetching Recovered notice - `xx:40:02` Runs successfully - `xx:45:02` Runs successfully - `xx:50:02` Runs successfully - `xx:55:02` Runs successfully - **`xx:00:25` Fetch cycle starts but does not complete (stops xx:02:00)**

Gantt diagram

```mermaid gantt title Fetch Cycle Timeline dateFormat HH:mm:ss axisFormat %H:%M:%S section Succeeded fetch-emails :00:00:02, 95s section Failed what is delaying the start of the fetch? :00:00:00, 25s fetch-emails :f2, 00:00:25, 95s unfetched mail :after f2, 10s section Other Processes work:queue restarted? :a1, 00:02:00, 2s work:queue restarted? :a2, 00:00:00, 2s ```

Close-up of process list at 2min after hour

#### 15:02:00  #### 15:02:02  #### 15:02:04 

Logs

The process has been signaled with signal "15". {"exception":"[object] (Symfony\\Component\\Process\\Exception\\RuntimeException(code: 0): The process has been signaled with signal \"15\". at /www/html/overrides/symfony/process/Process.php:434)

Full stack trace

``` [2023-06-09 13:02:01] production.ERROR: The process has been signaled with signal "15". {"exception":"[object] (Symfony\\Component\\Process\\Exception\\RuntimeException(code: 0): The process has been signaled with signal \"15\". at /www/html/overrides/symfony/process/Process.php:434) [stacktrace] #0 /www/html/overrides/symfony/process/Process.php(212): Symfony\\Component\\Process\\Process->wait() #1 /www/html/vendor/laravel/framework/src/Illuminate/Console/Scheduling/Event.php(201): Symfony\\Component\\Process\\Process->run() #2 /www/html/vendor/laravel/framework/src/Illuminate/Console/Scheduling/Event.php(176): Illuminate\\Console\\Scheduling\\Event->runCommandInForeground(Object(Illuminate\\Foundation\\Application)) #3 /www/html/vendor/laravel/framework/src/Illuminate/Console/Scheduling/ScheduleRunCommand.php(59): Illuminate\\Console\\Scheduling\\Event->run(Object(Illuminate\\Foundation\\Application)) #4 [internal function]: Illuminate\\Console\\Scheduling\\ScheduleRunCommand->handle() #5 /www/html/overrides/laravel/framework/src/Illuminate/Container/BoundMethod.php(28): call_user_func_array(Array, Array) #6 /www/html/overrides/laravel/framework/src/Illuminate/Container/BoundMethod.php(87): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}() #7 /www/html/overrides/laravel/framework/src/Illuminate/Container/BoundMethod.php(27): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(Illuminate\\Foundation\\Application), Array, Object(Closure)) #8 /www/html/overrides/laravel/framework/src/Illuminate/Container/Container.php(549): Illuminate\\Container\\BoundMethod::call(Object(Illuminate\\Foundation\\Application), Array, Array, NULL) #9 /www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(183): Illuminate\\Container\\Container->call(Array) #10 /www/html/vendor/symfony/console/Command/Command.php(255): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle)) #11 /www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(169): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle)) #12 /www/html/vendor/symfony/console/Application.php(992): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #13 /www/html/vendor/symfony/console/Application.php(255): Symfony\\Component\\Console\\Application->doRunCommand(Object(Illuminate\\Console\\Scheduling\\ScheduleRunCommand), Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #14 /www/html/vendor/symfony/console/Application.php(148): Symfony\\Component\\Console\\Application->doRun(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #15 /www/html/vendor/laravel/framework/src/Illuminate/Console/Application.php(88): Symfony\\Component\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #16 /www/html/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(121): Illuminate\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #17 /www/html/artisan(60): Illuminate\\Foundation\\Console\\Kernel->handle(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput)) #18 {main} "} ```

Potentially related commits

• Kill fetch-emails commands running too long
• Fix issue when background job (queue:work) was not executed
• Make sure fetching is executed even if previous command is killed or throuws an error and does not remove the mutex
• Setting 30min timeout FETCH_MAX_EXECUTION_TIME

Queue retry

• We reviewed the queue retry parameters here
• We reviewed the background job wiki. php artisan freescout:clear-cache did not resolve the issue.
• We experimented with altering the queue retry interval here from 90 to 180 and then php artisan freescout:clear-cache. The thought being that if it takes 95 seconds to fetch mail for our 66 mailboxes, then perhaps there is some hard-coded interval or limit that is not allowing enough time for this process to finish.

Questions

• What additional tests or configuration changes can be made to allow the fetch cycle to complete?
• Why would fetch cycles not run for 30mins?
• Is there a way to specify individual fetch cycles per mailbox? Might be related to this issue related to disabling fetching for some inboxes. We don't need to fetch mail for all inboxes every 5min and perhaps setting some to longer intervals would allow fetch cycles to complete?

[freescout-helpdesk]

The first fetch cycle of the hour does not complete in its entirety.

It means your fetching gets stuck. You need to debug it to figure out why.