[BUG 9.0] At least in CI, a pilot can't modify a job status

[Robin-Van-de-Merghel]

Caught in CI running with DiracX latest. Content of the error:

# 1. Pilot (job wrapper) says it's gonna send its job accounting
2025-07-30T08:17:48,218566Z None/[2]JobWrapper INFO: CPU time left in sendJobAccounting 0.00 0.00 0.00 0.00 0.01

# 2. It's being sent
2025-07-30T08:17:48,522180Z WorkloadManagement/JobAgent/InProcess INFO: Exit status:0
2025-07-30T08:17:48,522321Z WorkloadManagement/JobAgent/WorkloadManagement/JobAgent INFO: Job being submitted (DIRAC JobID: 2; Task ID: 0)
2025-07-30T08:17:58,522495Z WorkloadManagement/JobAgent/WorkloadManagement/JobAgent DEBUG: After InProcessCE submitJob()
2025-07-30T08:17:58,522734Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Trying to autodetect client for WorkloadManagement/JobStateUpdate
2025-07-30T08:17:58,522816Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Using legacy adapter for service WorkloadManagement/JobStateUpdate
2025-07-30T08:17:58,548664Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Trying to autodetect client for WorkloadManagement/JobStateUpdate
2025-07-30T08:17:58,548778Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Using legacy adapter for service WorkloadManagement/JobStateUpdate
2025-07-30T08:17:58,564831Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Trying to autodetect client for WorkloadManagement/JobStateUpdate
2025-07-30T08:17:58,564928Z WorkloadManagement/JobAgent/DIRAC.Core.Tornado.Client.ClientSelector DEBUG: Using legacy adapter for service WorkloadManagement/JobStateUpdate

# 3. Send to DiracX
2025-07-30T08:17:58,581590Z WorkloadManagement/JobAgent ERROR: Error while sending the job status HttpResponseError("Operation returned an invalid status 'Forbidden'"): Operation returned an invalid status 'Forbidden'
Content: {"detail":"Forbidden"}

See: https://github.com/DIRACGrid/DIRAC/actions/runs/16616853013/job/47011378227?pr=8248#step:11:2546

It's quite a vanilla install in #8248 , a "pure" Pilot, DIRAC and DiracX.

[Robin-Van-de-Merghel]

Ran a second times locally this time (to see more deeply logs):

DiracX logs while executing a pilot (only a pilot), from configuration to end of a pilot.
Environment of the pilot was set following this PR's CI commands: #8268

2025-07-31 09:41:21,081 - INFO:     192.168.117.2:57482 - "GET /api/auth/legacy-exchange?preferred_username=pilot&scope=vo%3Avo+group%3Apilot+property%3ALimitedDelegation+property%3AGenericPilot&expires_minutes=1440&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:41:23,197 - INFO:     192.168.117.2:57482 - "GET /api/auth/legacy-exchange?preferred_username=ciuser&scope=vo%3Avo+group%3Adirac_user+property%3ANormalUser&expires_minutes=1440&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:44:40,107 - INFO:     192.168.117.3:53714 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden
2025-07-31 09:44:40,267 - INFO:     192.168.117.2:57856 - "GET /api/auth/legacy-exchange?preferred_username=ciuser&scope=vo%3Avo+group%3Adirac_user+property%3ANormalUser&expires_minutes=11160&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:44:40,357 - INFO:     192.168.117.2:57856 - "GET /api/auth/legacy-exchange?preferred_username=ciuser&scope=vo%3Avo+group%3Adirac_user+property%3ANormalUser&expires_minutes=11160&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:44:42,594 - INFO:     192.168.117.3:53730 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:44:43,110 - INFO:     192.168.117.3:53748 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:44:43,311 - INFO:     192.168.117.3:53762 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:44:48,934 - INFO:     192.168.117.3:53788 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:44:49,438 - INFO:     192.168.117.3:36884 - "PATCH /api/jobs/heartbeat HTTP/1.1" 200 OK
2025-07-31 09:44:49,831 - INFO:     192.168.117.3:36912 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:44:49,944 - INFO:     192.168.117.3:36922 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:44:50,382 - INFO:     192.168.117.3:36936 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:45:01,347 - INFO:     192.168.117.3:57832 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden
2025-07-31 09:45:01,393 - INFO:     192.168.117.3:57850 - "PATCH /api/jobs/metadata HTTP/1.1" 403 Forbidden
2025-07-31 09:45:01,439 - INFO:     192.168.117.3:57876 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden
2025-07-31 09:45:03,775 - INFO:     192.168.117.3:57900 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden
2025-07-31 09:45:04,006 - INFO:     192.168.117.2:52052 - "GET /api/auth/legacy-exchange?preferred_username=ciuser&scope=vo%3Avo+group%3Adirac_user+property%3ANormalUser&expires_minutes=11160&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:45:04,165 - INFO:     192.168.117.2:52052 - "GET /api/auth/legacy-exchange?preferred_username=ciuser&scope=vo%3Avo+group%3Adirac_user+property%3ANormalUser&expires_minutes=11160&source=ProxyManager HTTP/1.1" 200 OK
2025-07-31 09:45:06,825 - INFO:     192.168.117.3:57924 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:45:06,896 - INFO:     192.168.117.3:57940 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:45:06,949 - INFO:     192.168.117.3:57966 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:45:10,030 - INFO:     192.168.117.3:49484 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:45:10,148 - INFO:     192.168.117.3:49502 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:45:15,543 - INFO:     192.168.117.3:49522 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:45:15,631 - INFO:     192.168.117.3:49532 - "PATCH /api/jobs/heartbeat HTTP/1.1" 200 OK
2025-07-31 09:45:15,745 - INFO:     192.168.117.3:49560 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:45:15,802 - INFO:     192.168.117.3:49578 - "PATCH /api/jobs/status?force=false HTTP/1.1" 200 OK
2025-07-31 09:45:15,937 - INFO:     192.168.117.3:49598 - "PATCH /api/jobs/metadata HTTP/1.1" 204 No Content
2025-07-31 09:45:26,746 - INFO:     192.168.117.3:37818 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden
2025-07-31 09:45:26,788 - INFO:     192.168.117.3:37822 - "PATCH /api/jobs/metadata HTTP/1.1" 403 Forbidden
2025-07-31 09:45:26,838 - INFO:     192.168.117.3:37838 - "PATCH /api/jobs/status?force=false HTTP/1.1" 403 Forbidden

We can see some of the /api/jobs/... requests have a 2XX status, but some of it also have a 403 error. Full pilot logs can be found here : pilot_stack.txt

[Robin-Van-de-Merghel]

Reminder to remove JOB_ADMINISTRATOR from pilot properties.

[fstagni]

Are all the 403 coming from the pilot inside the CI?

[Robin-Van-de-Merghel]

Most are coming from the pilot yes.