Totem schuduler works fine but command not being executed?

[kanhaiyam]

I am using Laravel 8 and PHP 7.4

I have a bunch of Commands scheduled in totem. Totem works fine on the surface firing the commands, but it doesn't executes the actual command. It logs the executing and executed stages of the task, but the actual command doesn't gets executed. Also there is no entry for the task in task_results. Totem executed the task successfully according to logs but it didn't actually execute it.

Excerpt from the log

[2021-07-10 13:33:28] local.INFO: Broadcasting [Studio\Totem\Events\Executing] on channels [private-task.events] with payload:
{
"task": {
"id": 4,
"description": "Update Wit Status",
"command": "command:refreshWitStatus",
"parameters": null,
"expression": "* * * * *",
"timezone": "Asia\/Kolkata",
"is_active": 1,
"dont_overlap": 1,
"run_in_maintenance": 0,
"notification_email_address": null,
"notification_phone_number": null,
"notification_slack_webhook": null,
"created_at": "2021-07-09T09:36:17.000000Z",
"updated_at": "2021-07-10T05:06:29.000000Z",
"auto_cleanup_num": 0,
"auto_cleanup_type": "days",
"run_on_one_server": 0,
"run_in_background": 0,
"activated": 1,
"upcoming": "2021-07-11 00:00:00",
"last_result": {
"id": 18,
"task_id": 4,
"ran_at": "2021-07-09T13:02:06.000000Z",
"result": "",
"created_at": "2021-07-09T18:32:06.000000Z",
"updated_at": "2021-07-09T18:32:06.000000Z",
"duration": "57330.58381080600000"
},
"average_runtime": "57330.583810806000000000"
},
"socket": null
}  
[2021-07-10 13:33:28] local.INFO: Broadcasting [Studio\Totem\Events\Executed] on channels [private-task.events] with payload:
{
"task": {
"id": 4,
"description": "Update Wit Status",
"command": "command:refreshWitStatus",
"parameters": null,
"expression": "* * * * *",
"timezone": "Asia\/Kolkata",
"is_active": 1,
"dont_overlap": 1,
"run_in_maintenance": 0,
"notification_email_address": null,
"notification_phone_number": null,
"notification_slack_webhook": null,
"created_at": "2021-07-09T09:36:17.000000Z",
"updated_at": "2021-07-10T05:06:29.000000Z",
"auto_cleanup_num": 0,
"auto_cleanup_type": "days",
"run_on_one_server": 0,
"run_in_background": 0,
"activated": 1,
"upcoming": "2021-07-11 00:00:00",
"last_result": {
"id": 18,
"task_id": 4,
"ran_at": "2021-07-09T13:02:06.000000Z",
"result": "",
"created_at": "2021-07-09T18:32:06.000000Z",
"updated_at": "2021-07-09T18:32:06.000000Z",
"duration": "57330.58381080600000"
},
"average_runtime": "57330.583810806000000000"
},
"socket": null
}  
[2021-07-10 13:34:28] local.INFO: Broadcasting [Studio\Totem\Events\Executing] on channels [private-task.events] with payload:
{
"task": {
"id": 4,
"description": "Update Wit Status",
"command": "command:refreshWitStatus",
"parameters": null,
"expression": "* * * * *",
"timezone": "Asia\/Kolkata",
"is_active": 1,
"dont_overlap": 1,
"run_in_maintenance": 0,
"notification_email_address": null,
"notification_phone_number": null,
"notification_slack_webhook": null,
"created_at": "2021-07-09T09:36:17.000000Z",
"updated_at": "2021-07-10T05:06:29.000000Z",
"auto_cleanup_num": 0,
"auto_cleanup_type": "days",
"run_on_one_server": 0,
"run_in_background": 0,
"activated": 1,
"upcoming": "2021-07-11 00:00:00",
"last_result": {
"id": 18,
"task_id": 4,
"ran_at": "2021-07-09T13:02:06.000000Z",
"result": "",
"created_at": "2021-07-09T18:32:06.000000Z",
"updated_at": "2021-07-09T18:32:06.000000Z",
"duration": "57330.58381080600000"
},
"average_runtime": "57330.583810806000000000"
},
"socket": null
}  
[2021-07-10 13:34:28] local.INFO: Broadcasting [Studio\Totem\Events\Executed] on channels [private-task.events] with payload:
{
"task": {
"id": 4,
"description": "Update Wit Status",
"command": "command:refreshWitStatus",
"parameters": null,
"expression": "* * * * *",
"timezone": "Asia\/Kolkata",
"is_active": 1,
"dont_overlap": 1,
"run_in_maintenance": 0,
"notification_email_address": null,
"notification_phone_number": null,
"notification_slack_webhook": null,
"created_at": "2021-07-09T09:36:17.000000Z",
"updated_at": "2021-07-10T05:06:29.000000Z",
"auto_cleanup_num": 0,
"auto_cleanup_type": "days",
"run_on_one_server": 0,
"run_in_background": 0,
"activated": 1,
"upcoming": "2021-07-11 00:00:00",
"last_result": {
"id": 18,
"task_id": 4,
"ran_at": "2021-07-09T13:02:06.000000Z",
"result": "",
"created_at": "2021-07-09T18:32:06.000000Z",
"updated_at": "2021-07-09T18:32:06.000000Z",
"duration": "57330.58381080600000"
},
"average_runtime": "57330.583810806000000000"
},
"socket": null
}  

[qschmick]

@kanhaiyam Which version of Totem are you running? I've seen this once before and it had to do with cache. There was an update to Totem a little while ago to bust the cache. As a quick suggestion try running the following on the server:

php artisan cache:clear

[kanhaiyam]

@qschmick I am using v8.1.4

it is not an issue with cache. The BustCache and BuildCache events are working fine as expected. The result for php artisan schedule:list is as expected with all the scheduled tasks being listed.

[kanhaiyam]

@qschmick Found the solution.

Actually what was happening was totem while executing tasks creates a temp log file at storage/app/totem/, which shell didn't have access for. Fixed the file/folder permission and the totem scheduler started working.

What I don't get is why it is creating a file in the first place if it is mean to be deleted later after execution.