Face Clustering Doesn't Schedule Background Jobs Automatically

[ali-essam]

Which version of recognize are you using?

5.0.3

Enabled Modes

Object recognition, Face recognition

TensorFlow mode

Normal mode

Downstream App

Memories App

Which Nextcloud version do you have installed?

27.1.4

Which Operating system do you have installed?

Debian 12

Which database are you running Nextcloud on?

Postgres

Which Docker container are you using to run Nextcloud? (if applicable)

tccr.io/truecharts/nextcloud-fpm:v27.1.4

How much RAM does your server have?

8Gib (Container Memory Limit)

What processor Architecture does your CPU have?

x86_64

Describe the Bug

Face clustering background job doesn't kick in automatically even with 120+ faces left to cluster

However, I had to run

while true; do occ recognize:cluster-faces --batch-size=500; done

For a while to get the initial clustering to work, but after that still new faces don't trigger the background clustering automatically

For context if helpful, I had a conflicting app installed "Suspicious Logins" initially that was preventing the clustering to run correctly, but after I removed it, the CLI is working fine

Expected Behavior

After rescanning all files, recognize should schedule Background Jobs to cluster faces automatically

To Reproduce

• Rescan files or add photos with faces automatically (120+)
• Check last clustering time

Debug log

Nothing helpful much in debug logs

  Debug    PHP                Creation of dynamic property OCA\FirstRunWizard\Settings\Personal::$urlGenerator is deprecated at                 2023-12-10T09:53:00+01:00 
                              /var/www/html/apps/firstrunwizard/lib/Settings/Personal.php#40                                                                              

  Debug    PHP                Creation of dynamic property OCA\FirstRunWizard\Settings\Personal::$urlGenerator is deprecated at                 2023-12-10T09:54:10+01:00 
                              /var/www/html/apps/firstrunwizard/lib/Settings/Personal.php#40                                                                              

  Debug    no app in context  3 well known handlers registered                                                                                  2023-12-10T09:54:11+01:00 

  Debug    no app in context  3 well known handlers registered                                                                                  2023-12-10T09:54:11+01:00 

  Debug    no app in context  Deprecated event type for OCP\IDBConnection::CHECK_MISSING_PRIMARY_KEYS:                                          2023-12-10T09:54:11+01:00 
                              Symfony\Component\EventDispatcher\GenericEvent is used                                                                                      

  Debug    cron               Finished OCA\Files\BackgroundJob\DeleteExpiredOpenLocalEditor job with ID 16 in 0 seconds                         2023-12-10T09:55:02+01:00 

  Debug    cron               Run OCA\Files\BackgroundJob\DeleteExpiredOpenLocalEditor job with ID 16                                           2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 16                                                                         2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 8                                                                          2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 6                                                                          2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 21                                                                         2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 2088                                                                       2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 2262                                                                       2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 26                                                                         2023-12-10T09:55:02+01:00 

  Debug    cron               CLI cron call has selected job with ID 32                                                                         2023-12-10T10:00:04+01:00 

  Debug    cron               CLI cron call has selected job with ID 23                                                                         2023-12-10T10:00:04+01:00 

  Info     admin_audit        Console command executed: preview:pre-generate                                                                    2023-12-10T10:00:04+01:00 

  Debug    cron               Run OCA\Memories\Cron\IndexJob job with ID 50                                                                     2023-12-10T10:00:04+01:00 

  Debug    cron               CLI cron call has selected job with ID 50                                                                         2023-12-10T10:00:04+01:00 

  Debug    cron               CLI cron call has selected job with ID 13                                                                         2023-12-10T10:00:04+01:00 

[github-actions]

Hello 👋

Thank you for taking the time to open this issue with recognize. I know it's frustrating when software
causes problems. You have made the right choice to come here and open an issue to make sure your problem gets looked at
and if possible solved.
I try to answer all issues and if possible fix all bugs here, but it sometimes takes a while until I get to it.
Until then, please be patient.
Note also that GitHub is a place where people meet to make software better together. Nobody here is under any obligation
to help you, solve your problems or deliver on any expectations or demands you may have, but if enough people come together we can
collaborate to make this software better. For everyone.
Thus, if you can, you could also look at other issues to see whether you can help other people with your knowledge
and experience. If you have coding experience it would also be awesome if you could step up to dive into the code and
try to fix the odd bug yourself. Everyone will be thankful for extra helping hands!
One last word: If you feel, at any point, like you need to vent, this is not the place for it; you can go to the forum,
to twitter or somewhere else. But this is a technical issue tracker, so please make sure to
focus on the tech and keep your opinions to yourself. (Also see our Code of Conduct. Really.)

I look forward to working with you on this issue
Cheers 💙

[ali-essam]

Update:

Checking oc_jobs table SELECT * FROM "oc_jobs" WHERE "class" LIKE '%Recognize%' LIMIT 50, I found

id,class,argument,last_run,last_checked,reserved_at,execution_duration,argument_hash,time_sensitive
146073,OCA\Recognize\BackgroundJobs\ClassifyImagenetJob,"{""storageId"":1,""rootId"":1}",1702199738,1702199738,1702199738,72,127f6d3080643c511e99c2b74a5ebfb5,"0"
146444,OCA\Recognize\BackgroundJobs\ClassifyLandmarksJob,"{""storageId"":1,""rootId"":1}","0",1702199753,"0","0",127f6d3080643c511e99c2b74a5ebfb5,1

Disabled and enabled Face Recognition from the UI again, added this job

146443,OCA\Recognize\BackgroundJobs\SchedulerJob,"{""models"":[""faces""]}","0",1702199517,"0","0",d25c451720f59160bdf58e3c84e12cc3,1

Currently, this is what's happening

id,class,argument,last_run,last_checked,reserved_at,execution_duration,argument_hash,time_sensitive
146444,OCA\Recognize\BackgroundJobs\ClassifyLandmarksJob,"{""storageId"":1,""rootId"":1}","0",1702199753,"0","0",127f6d3080643c511e99c2b74a5ebfb5,1
146073,OCA\Recognize\BackgroundJobs\ClassifyImagenetJob,"{""storageId"":1,""rootId"":1}",1702199738,1702199738,"0",70,127f6d3080643c511e99c2b74a5ebfb5,"0"
146445,OCA\Recognize\BackgroundJobs\StorageCrawlJob,"{""storage_id"":1,""root_id"":1,""override_root"":2,""last_file_id"":0,""models"":[""faces""]}","0",1702199808,"0","0",acc3346f2c963f0602db8c435e6d4826,1
146446,OCA\Recognize\BackgroundJobs\StorageCrawlJob,"{""storage_id"":3,""root_id"":22617,""override_root"":22617,""last_file_id"":0,""models"":[""faces""]}","0",1702199808,"0","0",5216a3314e7308ded15f1d7350088e14,1


id,class,argument,last_run,last_checked,reserved_at,execution_duration,argument_hash,time_sensitive
146447,OCA\Recognize\BackgroundJobs\ClassifyFacesJob,"{""storageId"":1,""rootId"":1}","0",1702200043,"0","0",127f6d3080643c511e99c2b74a5ebfb5,1
146448,OCA\Recognize\BackgroundJobs\StorageCrawlJob,"{""storage_id"":1,""root_id"":1,""override_root"":2,""last_file_id"":25720,""models"":[""faces""]}","0",1702200051,"0","0",f615aac7ebd6fe808a5bd6e755f0e171,1
146073,OCA\Recognize\BackgroundJobs\ClassifyImagenetJob,"{""storageId"":1,""rootId"":1}",1702199738,1702200006,"0",70,127f6d3080643c511e99c2b74a5ebfb5,"0"

id,class,argument,last_run,last_checked,reserved_at,execution_duration,argument_hash,time_sensitive
146447,OCA\Recognize\BackgroundJobs\ClassifyFacesJob,"{""storageId"":1,""rootId"":1}",1702200902,1702200902,"0",98,127f6d3080643c511e99c2b74a5ebfb5,"0"
146453,OCA\Recognize\BackgroundJobs\StorageCrawlJob,"{""storage_id"":1,""root_id"":1,""override_root"":2,""last_file_id"":45488,""models"":[""faces""]}","0",1702201079,"0","0",26a4bd4160456cd14f64530373526804,1
146452,OCA\Recognize\BackgroundJobs\ClassifyLandmarksJob,"{""storageId"":1,""rootId"":1}",1702201079,1702201079,1702201079,"0",127f6d3080643c511e99c2b74a5ebfb5,"0"

Seems like this triggered classification again, files are being added to classification queue, but it still says Last Classification 4 days ago (the manual run), and no jobs for face clustering scheduled

[ali-essam]

A couple more observations,

Letting it run for a while, seems like the clustering does kick in, however lots of logs with Face score too low. continuing with next face. and Face is not straight. continuing with next face.. There are also no logs for preparing face detection for user

When I ran occ recognize:cluster-faces however, everything was processed as expected and the queue was cleared.

Looking through the code, the command doesn't run the same score filter process as the job, which leads me to assume that what's happening is:

• ClusteringFaceClassifier kicks in correctly, however all files don't have faces that pass minimum scores
• Leading to $usersToCluster[$userId] = true; never being called
• And the loop on users after being empty so it never calls $this->jobList->add(ClusterFacesJob::class, ['userId' => $userId]);
• And never calling this->clusterAnalyzer->calculateClusters which updates the lastRun and status correctly

Possible Fixes (and/or):

• Move score filtration into calculateClusters
• Implement same filtration in the command
• Remove the file from the queue if it doesn't pass the scores or if not straight (or maybe to another queue if it can still be picked up later)

[marcelklehr]

Looking through the code, the command doesn't run the same score filter process as the job

ClusteringFaceClassifier is not expected to do the same thing as the cluster-faces command. It is an earlier stage than the cluster-faces command. See https://github.com/nextcloud/recognize/wiki/Behind-the-scenes for details on how things work.

[mrbrdo]

I'm also having a problem with this @marcelklehr
I haven't manually changed anything, I tried disabling and enabling the plugin and also "Enable face recognition" in the settings.
The only recognize-related job in oc_jobs after cron runs for the first time is this one:

"OCA\Recognize\BackgroundJobs\StorageCrawlJob" "{""storage_id"":1,""root_id"":1,""override_root"":2,""last_file_id"":0,""models"":[""faces""]}"

There seem to be no jobs for classification. Even after cron runs, the setting page still shows

Face recognition: 605 Queued files, Last classification: 2 days ago, Scheduled background jobs: 1,
Face clustering: 63 faces left to cluster, Last clustering run: 2 days ago, Scheduled background jobs: 0,
A minimum of 120 faces per user is necessary for clustering to kick in

It works fine if I run the appropriate commands directly with occ, but there seems to be an issue with the cron. PS: I'm running on TrueNAS Scale Cobia with the official charts.
Can you advise?

[marcelklehr]

Face recognition: 605 Queued files, Last classification: 2 days ago, Scheduled background jobs: 1

This suggests that there actually is a job scheduled to classify faces.

The only recognize-related job in oc_jobs after cron runs for the first time is this one

This is expected. I do recommend https://github.com/nextcloud/recognize/wiki/Behind-the-scenes

If you still believe something is in error, open a new issue, detailing what you expect and what happens instead, please :)