Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fact caching could leed to OOM on the controler nodes #15827

Open
5 of 11 tasks
anxjok opened this issue Feb 10, 2025 · 3 comments
Open
5 of 11 tasks

Fact caching could leed to OOM on the controler nodes #15827

anxjok opened this issue Feb 10, 2025 · 3 comments
Labels
community needs_triage type:bug

Comments

@anxjok
Copy link

anxjok commented Feb 10, 2025

Please confirm the following

  • I agree to follow this project's code of conduct.
  • I have checked the current issues for duplicates.
  • I understand that AWX is open source software provided for free and that I might not receive a timely response.
  • I am NOT reporting a (potential) security vulnerability. (These should be emailed to security@ansible.com instead.)

Bug Summary

Hey, first I'm not sure of this is a bug or a feature request.

Last week both of our controller nodes run into OOM (out of memory) after investigating the root cause we noticed that multiple jobs (with limits) were started for a big inventory (~1700 host) where fact caching was enabled. Each job toke ~ 1.7 GB of memory on the controller node. After checking what's the root cause I noticed that the facts for each host in the inventory are stored in memory.

AWX version

2024.6.1

Select the relevant components

  • UI
  • UI (tech preview)
  • API
  • Docs
  • Collection
  • CLI
  • Other

Installation method

docker development environment

Modifications

yes

Ansible version

No response

Operating system

No response

Web browser

No response

Steps to reproduce

  1. Create an inventory with 1700 hosts.
  2. Add 100 MB to the host fact.
  3. start a job and look on the user Memory of the process.

Expected results

Take the amount of memory that will be used by the fact caching into account when calculating the job impact and/or only cache facts for hosts that are within the job limit.

Actual results

The facts are cached for all hosts of the inventory which lead to the OOM of the system.

Additional information

There was already a PR that would have fixed that.
Also, It's kind a same root cause like #5567
@AlanCoding
Copy link
Member

Do you know what method this happens from?

I ask, because saving facts post-run is batched to 100 hosts at a time.

awx/awx/main/tasks/facts.py

Lines 138 to 140 in f377b5f

if len(hosts_to_update) > 100:
update_hosts(hosts_to_update)
hosts_to_update = []

So then it would be helpful to know if that batching in ineffective, or if 100 is simply too many.

Or, this could be more acute in the pre-run start_fact_cache.

Do you have any ballpark number for the size of facts? Like, 1.7k hosts with 250 MB facts per host?

@anxjok
Copy link
Author

anxjok commented Feb 12, 2025

Hey thanks for the reply.
I started another job to get logs a metrics for the ram usage.
It looks like that the memory usage starts increasing after the job state start_job_fact_cache

I copied the facts of one host from the AWX UI and checked the size of the created file.
Per host the facts are ~600KB in JSON format.
I tried to get the amount of Memory that the python will use
To simulate that I used the following python code on my local machine:

import json
with open('nc.test', 'r') as file:
    data = json.load(file)

I measured the ram usage of the process after the import of JSON and after loading the JSON file.
After Import:

ps v 744215          
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 744215 pts/21   S+     0:00      0     4 246363 15836  0.0 python3

After loading the JSON file:

ps v 744215
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 744215 pts/21   S+     0:00      0     4 247387 16904  0.0 python3

after subtracting the RSS values we get 1068KB of ram usage which will lead to ~ 1MB ram per host.

here are the ram usage of the controller node:
Image

and here are the logs of the controller node:

Show logs 
2025-02-12 06:31:33,293 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:31:34,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.014286279678344727 seconds after target
2025-02-12 06:31:34,082 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9842560291290283 seconds
2025-02-12 06:31:34,082 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task aa5abe40-ea73-494a-83e8-54db70798a5e starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:31:34,099 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:31:34,154 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 blocked by inventoryupdate-3144461 {"type": "job", "task_id": 3144459, "state": "blocked", "work_unit_id": null, "task_name": "Fact Debug", "blocked_by": "inventoryupdate-3144461"}
2025-02-12 06:31:34,157 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:31:34,159 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341894.1591399 seconds ago
2025-02-12 06:31:34,160 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03290728700812906, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0.0031448830268345773, 'process_pending_tasks_seconds': 0.0001982069807127118, '_schedule_seconds': 0.05747508502099663, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 1, 'tasks_blocked': 1, 'commit_seconds': 0.0005948543548583984}
2025-02-12 06:31:35,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012545585632324219 seconds after target
2025-02-12 06:31:35,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 4.9981818199157715 seconds
2025-02-12 06:31:35,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 5fac4d1d-053c-4516-9d9a-5d86bafdc560 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:31:35,096 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:31:35,104 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:31:35,110 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341895.110246 seconds ago
2025-02-12 06:31:35,111 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007962169998791069, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007979843998327851, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:31:37,846 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:31:37,908 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:31:40,078 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.011578559875488281 seconds after target
2025-02-12 06:31:40,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.011578559875488281 seconds after target
2025-02-12 06:31:40,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.986281394958496 seconds
2025-02-12 06:31:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 0c3d36ee-5a76-4fd7-8733-1edc1cd27636 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:31:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task d48c6757-daaf-4421-9c6e-1af5626aa8b2 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:31:40,097 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:31:40,099 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:31:11.489485+00:00
2025-02-12 06:31:48,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.01539301872253418 seconds after target
2025-02-12 06:31:48,087 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.979372024536133 seconds
2025-02-12 06:31:48,296 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:31:52,223 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Going to update inventory computed fields, pk=722
2025-02-12 06:31:52,271 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Finished updating inventory computed fields, pk=722, in 0.045 seconds
2025-02-12 06:31:52,312 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Going to update inventory computed fields, pk=722
2025-02-12 06:31:52,354 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Finished updating inventory computed fields, pk=722, in 0.042 seconds
2025-02-12 06:31:52,369 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle inventoryupdate-3144461 finalize run {"type": "inventoryupdate", "task_id": 3144461, "state": "finalize_run", "work_unit_id": "JQDtuxtb", "task_name": "1.7k inventory"}
2025-02-12 06:31:52,379 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 96930a79-1cfb-4a57-b771-a2ab9bba96ce starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:31:52,379 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 1.6868088245391846 seconds
2025-02-12 06:31:52,399 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:31:52,451 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler task job 3144459 (pending) with impact of 9 can fit on instance group 01 with 0 remaining forks and 0
2025-02-12 06:31:52,451 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 controller node chosen {"type": "job", "task_id": 3144459, "state": "controller_node_chosen", "work_unit_id": null, "task_name": "Fact Debug", "controller_node": "awx0401"}
2025-02-12 06:31:52,451 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 execution node chosen {"type": "job", "task_id": 3144459, "state": "execution_node_chosen", "work_unit_id": null, "task_name": "Fact Debug", "execution_node": "exec0101"}
2025-02-12 06:31:52,451 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting job 3144459 (pending) in group 01 instance exec0101 (remaining_capacity=111)
2025-02-12 06:31:52,465 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Submitting job job 3144459 (waiting) controlled by awx0401 to instance group 01 and execution node exec0101.
2025-02-12 06:31:52,471 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 waiting {"type": "job", "task_id": 3144459, "state": "waiting", "work_unit_id": null, "task_name": "Fact Debug"}
2025-02-12 06:31:52,475 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:31:52,478 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 1.5879652500152588 seconds
2025-02-12 06:31:52,480 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341912.4800994 seconds ago
2025-02-12 06:31:52,480 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task ea8f5785-1aee-4aab-83eb-cd390bf49f10 starting awx.main.tasks.jobs.RunJob(*[3144459])
2025-02-12 06:31:52,481 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03448180697159842, 'start_task_seconds': 0.021026399976108223, 'process_running_tasks_seconds': 1.9246013835072517e-05, 'process_pending_tasks_seconds': 0.021629249036777765, '_schedule_seconds': 0.07611902605276555, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 1, 'running_processed': 2, 'pending_processed': 1, 'tasks_blocked': 0, 'commit_seconds': 0.002476930618286133}
2025-02-12 06:31:52,605 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 pre run {"type": "job", "task_id": 3144459, "state": "pre_run", "work_unit_id": null, "task_name": "Fact Debug"}
2025-02-12 06:31:52,610 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.utils Event partition table main_jobevent_20250212_06 already exists
2025-02-12 06:31:52,610 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 start job fact cache {"type": "job", "task_id": 3144459, "state": "start_job_fact_cache", "work_unit_id": null, "task_name": "Fact Debug"}
2025-02-12 06:31:52,908 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:31:52,911 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:31:54,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.008013725280761719 seconds after target
2025-02-12 06:31:54,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.989844799041748 seconds
2025-02-12 06:31:54,077 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task f9db2ce1-9c88-45d2-ab8a-6cdd4f334ffe starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:31:54,093 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:31:54,151 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:31:54,153 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341914.1535664 seconds ago
2025-02-12 06:31:54,154 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.04104695498244837, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.567801857367158e-05, 'process_pending_tasks_seconds': 1.9486993551254272e-05, '_schedule_seconds': 0.05738130601821467, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0006430149078369141}
2025-02-12 06:31:55,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012242794036865234 seconds after target
2025-02-12 06:31:55,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 4.998279333114624 seconds
2025-02-12 06:31:55,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task f0055b1e-0d85-4073-99c1-f36adbad08e2 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:31:55,086 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:31:55,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:31:55,096 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341915.0960348 seconds ago
2025-02-12 06:31:55,097 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007548952009528875, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007569361012428999, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:31:58,077 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!5a065df8f8b6494db57d0ffa57bfeddc from awx0402-jobs-summary
2025-02-12 06:31:58,079 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!5a065df8f8b6494db57d0ffa57bfeddc from awx0402-job_events-3144459
2025-02-12 06:31:58,079 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!5a065df8f8b6494db57d0ffa57bfeddc from awx0402-jobs-status_changed
2025-02-12 06:32:00,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.007582664489746094 seconds after target
2025-02-12 06:32:00,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.990952730178833 seconds
2025-02-12 06:32:00,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 94b16b7f-c55e-4542-b2cc-2153fbef597e starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:32:03,299 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:32:06,528 INFO     [-] awx.main.wsrelay Producer awx0402-job_events-3144459 has no subscribers, shutting down.
2025-02-12 06:32:07,911 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:32:07,914 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:32:07,970 INFO     [-] awx.main.wsrelay Producer awx0402-jobs-summary has no subscribers, shutting down.
2025-02-12 06:32:08,077 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.011381387710571289 seconds after target
2025-02-12 06:32:08,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9868505001068115 seconds
2025-02-12 06:32:08,952 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!48a6efd552d34bcbae3385653147acc9 from awx0402-control-limit_reached_1
2025-02-12 06:32:08,953 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!48a6efd552d34bcbae3385653147acc9 from awx0402-jobs-status_changed
2025-02-12 06:32:08,954 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!0e32130d886743788fce4e69d15f0e98 from awx0402-control-limit_reached_1
2025-02-12 06:32:08,954 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!0e32130d886743788fce4e69d15f0e98 from awx0402-jobs-status_changed
2025-02-12 06:32:09,522 DEBUG    [47f249a7c07d4996a375bc2ee815a4b1] awx.analytics.performance request: <WSGIRequest: GET '/api/'>, response_time: 0.048s
2025-02-12 06:32:09,768 DEBUG    [847c4921d0214606ba9e3566dbfb5741] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/me/'>, response_time: 0.055s
2025-02-12 06:32:09,946 DEBUG    [b84d8c8f7d1147ce89f4886472f5754c] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/users/272/admin_of_organizations/'>, response_time: 0.060s
2025-02-12 06:32:10,039 DEBUG    [6f11535dca384536a83755c9570a1116] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/organizations/?page_size=1&role_level=execution_environment_admin_role'>, response_time: 0.072s
2025-02-12 06:32:10,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.008623123168945312 seconds after target
2025-02-12 06:32:10,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.991002082824707 seconds
2025-02-12 06:32:10,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 7ee757fc-8576-4284-a7bb-eba0af1e5e45 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:32:10,091 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:32:10,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:31:41.491713+00:00
2025-02-12 06:32:10,280 DEBUG    [9caf5c2c472a4f06a327d3cd292110be] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144459/'>, response_time: 0.150s
2025-02-12 06:32:10,327 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to control-limit_reached_1.
2025-02-12 06:32:10,327 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to jobs-status_changed.
2025-02-12 06:32:10,367 DEBUG    [c4a37075c8d84d16b0962304ccf3aa21] awx.analytics.performance request: <WSGIRequest: OPTIONS '/api/v2/jobs/3144459/job_events/'>, response_time: 0.044s
10.61.236.11 - - [12/Feb/2025:06:32:10 +0000] "OPTIONS /api/v2/jobs/3144459/job_events/ HTTP/1.1" 200 12315 "https://awx-a8n.anexia-it.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" "10.61.248.32"
[pid: 736834|app: 0|req: 728/418598] 10.61.236.11 () {64 vars in 1096 bytes} [Wed Feb 12 06:32:10 2025] OPTIONS /api/v2/jobs/3144459/job_events/ => generated 12315 bytes in 46 msecs (HTTP/1.1 200) 15 headers in 599 bytes (1 switches on core 0)
2025-02-12 06:32:10,456 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to control-limit_reached_1.
2025-02-12 06:32:10,456 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to jobs-status_changed.
2025-02-12 06:32:10,511 DEBUG    [c4449b838ae74b7fbc104e3caf77fabd] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144459/credentials/'>, response_time: 0.070s
2025-02-12 06:32:11,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.001222372055053711 seconds after target
2025-02-12 06:32:11,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.998197555541992 seconds
2025-02-12 06:32:11,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 74e97273-48ea-4cf2-a166-fbc6242842e0 starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2025-02-12 06:32:11,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Cluster node heartbeat task.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
2025-02-12 06:32:14,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.009334802627563477 seconds after target
2025-02-12 06:32:14,077 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9892973899841309 seconds
2025-02-12 06:32:14,078 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 67297b93-cd67-48aa-9eaf-cb1e17fcc346 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:32:14,095 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:32:14,156 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:32:14,158 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341934.158516 seconds ago
2025-02-12 06:32:14,159 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.034715863002929837, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.4196982849389315e-05, 'process_pending_tasks_seconds': 1.891603460535407e-05, '_schedule_seconds': 0.06021810101810843, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0007460117340087891}
2025-02-12 06:32:15,006 DEBUG    [ac6c94747ce944a895cae394102d2b52] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144459/job_events/?not__stdout=&order_by=counter&page=1&page_size=50'>, response_time: 0.109s
2025-02-12 06:32:15,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012021064758300781 seconds after target
2025-02-12 06:32:15,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.9983398914337158 seconds
2025-02-12 06:32:15,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task e3fde80f-11b0-4c67-8fd1-183bf4b5508b starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:32:15,084 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:32:15,092 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:32:15,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341935.0944507 seconds ago
2025-02-12 06:32:15,095 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006963558029383421, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006977854005526751, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:32:17,073 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.007424116134643555 seconds after target
2025-02-12 06:32:17,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 0.992229700088501 seconds
2025-02-12 06:32:17,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task d44b0b61-8cc7-42be-a1da-60cc60d5f1df starting awx.main.tasks.system.awx_k8s_reaper(*[])
2025-02-12 06:32:18,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.0012216567993164062 seconds after target
2025-02-12 06:32:18,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 1.9982624053955078 seconds
2025-02-12 06:32:18,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 6abb8558-28c0-41a2-ab82-9567e1675f9e starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2025-02-12 06:32:18,070 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Checking for unreleased receptor work units
2025-02-12 06:32:18,302 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:32:18,438 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system job 3104200 (failed) is not active, reaping receptor work unit cbHDDll0
2025-02-12 06:32:18,526 ERROR    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch Worker failed to run task awx.main.tasks.system.awx_receptor_workunit_reaper(*[], **{}
Traceback (most recent call last):
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 103, in perform_work
  result = self.run_callable(body)
           ^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 78, in run_callable
  return _call(*args, **kwargs)
         ^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/tasks/system.py", line 690, in awx_receptor_workunit_reaper
  receptor_ctl.simple_command(f"work cancel {job.work_unit_id}")
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 83, in simple_command
  return self.read_and_parse_json()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 60, in read_and_parse_json
  raise RuntimeError(text[7:])
RuntimeError: error cancelling remote unit:  unknown work unit p5g2mnQK
2025-02-12 06:32:20,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0074617862701416016 seconds after target
2025-02-12 06:32:20,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 6.99104905128479 seconds
2025-02-12 06:32:20,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 82cb8a76-92a6-40ae-af31-51894d8454da starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:32:22,914 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:32:22,916 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:32:27,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.013524770736694336 seconds after target
2025-02-12 06:32:27,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 0.9848651885986328 seconds
2025-02-12 06:32:28,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.0012662410736083984 seconds after target
2025-02-12 06:32:28,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.997137546539307 seconds
2025-02-12 06:32:33,305 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:32:34,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.013015508651733398 seconds after target
2025-02-12 06:32:34,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.985032320022583 seconds
2025-02-12 06:32:34,082 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 7e4dad01-802f-4487-ae4f-75ca1232a67c starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:32:34,099 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:32:34,149 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:32:34,155 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341954.1551168 seconds ago
2025-02-12 06:32:34,156 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03376295696943998, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.2062042262405157e-05, 'process_pending_tasks_seconds': 1.9197002984583378e-05, '_schedule_seconds': 0.049626993015408516, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0007495880126953125}
rsyslogd: omfwd: remote server at api0401.bdp.anexia-it.com:1470 seems to have closed connection. This often happens when the remote peer (or an interim system like a load balancer or firewall) shuts down or aborts a connection. Rsyslog will re-open the connection if configured to do so (we saw a generic IO Error, which usually goes along with that behaviour). [v8.2102.0-106.el9 try https://www.rsyslog.com/e/2027 ]
2025-02-12 06:32:35,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0013241767883300781 seconds after target
2025-02-12 06:32:35,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 4.998105525970459 seconds
2025-02-12 06:32:35,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 523474e3-d21c-4c43-a88b-8d8a52a76514 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:32:35,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:32:35,087 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:32:35,089 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341955.0896032 seconds ago
2025-02-12 06:32:35,090 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.0060215729754418135, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006031483004335314, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
rsyslogd: omfwd: remote server at api0401.bdp.anexia-it.com:1470 seems to have closed connection. This often happens when the remote peer (or an interim system like a load balancer or firewall) shuts down or aborts a connection. Rsyslog will re-open the connection if configured to do so (we saw a generic IO Error, which usually goes along with that behaviour). [v8.2102.0-106.el9 try https://www.rsyslog.com/e/2027 ]
2025-02-12 06:32:37,916 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:32:37,983 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:32:40,078 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.012395143508911133 seconds after target
2025-02-12 06:32:40,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.012395143508911133 seconds after target
2025-02-12 06:32:40,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.985673189163208 seconds
2025-02-12 06:32:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 67f36dff-0151-46ed-af82-79f2e812e8e4 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:32:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 78945c3b-e463-4c3e-9f65-59136073abae starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:32:40,100 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:32:40,102 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:32:11.484424+00:00
2025-02-12 06:32:48,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.014838218688964844 seconds after target
2025-02-12 06:32:48,083 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.9831461906433105 seconds
2025-02-12 06:32:48,308 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:32:52,983 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:32:52,986 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:32:54,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.015374183654785156 seconds after target
2025-02-12 06:32:54,083 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9828000068664551 seconds
2025-02-12 06:32:54,084 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 136a8bcd-707e-441c-bec2-b70a4f32ad15 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:32:54,098 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:32:54,145 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:32:54,148 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739341974.1478887 seconds ago
2025-02-12 06:32:54,148 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03188521001720801, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.1469971872866154e-05, 'process_pending_tasks_seconds': 2.1220010239630938e-05, '_schedule_seconds': 0.047212202043738216, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0007081031799316406}
2025-02-12 06:32:55,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012748241424560547 seconds after target
2025-02-12 06:32:55,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 4.998137950897217 seconds
2025-02-12 06:32:55,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task b9b3e621-3cd3-4fcd-87d1-53f99fc68a5f starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:32:55,084 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:32:55,091 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:32:55,096 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341975.0967317 seconds ago
2025-02-12 06:32:55,098 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006880299013573676, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.00689180102199316, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:32:57,448 DEBUG    [0b8c8e2db8a14a9e81f71e90804a0022] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/job_templates/2441/survey_spec/'>, response_time: 0.096s
2025-02-12 06:33:00,078 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.011474132537841797 seconds after target
2025-02-12 06:33:00,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.987124443054199 seconds
2025-02-12 06:33:00,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 8982e58c-5c31-43a1-a667-86ec68af4a63 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:33:03,310 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:33:04,274 DEBUG    [d32b25db69954c94a7ed2e20c1fa2626] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/unified_jobs/?id=3144463'>, response_time: 0.131s
2025-02-12 06:33:04,325 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 3.740659713745117 seconds
2025-02-12 06:33:04,326 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 76b8fd9b-bfee-4583-b36e-aa9622d71d63 starting awx.main.tasks.jobs.RunInventoryUpdate(*[3144465])
2025-02-12 06:33:04,390 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Going to update inventory computed fields, pk=774
2025-02-12 06:33:04,410 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Finished updating inventory computed fields, pk=774, in 0.020 seconds
2025-02-12 06:33:04,430 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 pre run {"type": "inventoryupdate", "task_id": 3144465, "state": "pre_run", "work_unit_id": null, "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:04,434 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.utils Event partition table main_inventoryupdateevent_20250212_06 already exists
2025-02-12 06:33:04,434 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 preparing playbook {"type": "inventoryupdate", "task_id": 3144465, "state": "preparing_playbook", "work_unit_id": null, "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:04,436 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 start job fact cache {"type": "inventoryupdate", "task_id": 3144465, "state": "start_job_fact_cache", "work_unit_id": null, "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:04,814 DEBUG    [22a01d63f0534f2693c4280405d55d95] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144463/credentials/'>, response_time: 0.147s
2025-02-12 06:33:05,035 DEBUG    [c33607dab59b486399b4884b9f91e436] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144463/job_events/?not__stdout=&order_by=counter&page=1&page_size=50'>, response_time: 0.129s
2025-02-12 06:33:07,986 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:33:07,989 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:33:08,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.010799169540405273 seconds after target
2025-02-12 06:33:08,079 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9872984886169434 seconds
2025-02-12 06:33:10,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.008502721786499023 seconds after target
2025-02-12 06:33:10,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9912023544311523 seconds
2025-02-12 06:33:10,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task b8664e3f-d224-4f33-92d5-7c62e411f294 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:33:10,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:33:10,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:32:41.485090+00:00
2025-02-12 06:33:11,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0012180805206298828 seconds after target
2025-02-12 06:33:11,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.99816632270813 seconds
2025-02-12 06:33:11,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task bc8c9625-1378-499f-9f83-ffee8dbe949b starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2025-02-12 06:33:11,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Cluster node heartbeat task.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
2025-02-12 06:33:14,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.009521961212158203 seconds after target
2025-02-12 06:33:14,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9890091419219971 seconds
2025-02-12 06:33:14,078 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 009f9c57-8292-4395-b947-428a6df7ee02 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:33:14,091 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:33:14,147 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 blocked by projectupdate-3144464 {"type": "job", "task_id": 3144463, "state": "blocked", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "blocked_by": "projectupdate-3144464"}
2025-02-12 06:33:14,150 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:33:14,153 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739341994.1529086 seconds ago
2025-02-12 06:33:14,153 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.036161187977995723, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0.0036613860283978283, 'process_pending_tasks_seconds': 0.0002229349920526147, '_schedule_seconds': 0.05923077097395435, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 5, 'pending_processed': 1, 'tasks_blocked': 1, 'commit_seconds': 0.0005764961242675781}
2025-02-12 06:33:15,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012469291687011719 seconds after target
2025-02-12 06:33:15,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.998178482055664 seconds
2025-02-12 06:33:15,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 8283bad3-d089-4c06-8a3b-3954c2ad3b32 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:33:15,085 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:33:15,096 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:33:15,099 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739341995.099439 seconds ago
2025-02-12 06:33:15,100 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008491579035762697, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008510865969583392, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:33:15,142 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.facts Inventory 722 host facts prepared for 1702 hosts, took 82.532 s
2025-02-12 06:33:15,148 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.jobs Skipping project sync for 3144459 because commit is locally available
2025-02-12 06:33:15,564 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.jobs Project 3281 prepared /tmp/awx_3144459_f9p17flh/requirements_collections from cache
2025-02-12 06:33:15,726 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.jobs Project 3281 prepared /tmp/awx_3144459_f9p17flh/requirements_roles from cache
2025-02-12 06:33:15,727 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 preparing playbook {"type": "job", "task_id": 3144459, "state": "preparing_playbook", "work_unit_id": null, "task_name": "Fact Debug"}
2025-02-12 06:33:15,878 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 running playbook {"type": "job", "task_id": 3144459, "state": "running_playbook", "work_unit_id": null, "task_name": "Fact Debug"}
2025-02-12 06:33:17,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.008426666259765625 seconds after target
2025-02-12 06:33:17,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 0.9912252426147461 seconds
2025-02-12 06:33:17,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task a84d6bb8-1aad-41f8-bd9a-0639cd12d8d2 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2025-02-12 06:33:18,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.0011985301971435547 seconds after target
2025-02-12 06:33:18,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 1.998328685760498 seconds
2025-02-12 06:33:18,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task c4f0037f-57ba-4e45-ad04-7a7088cc6be2 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2025-02-12 06:33:18,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Checking for unreleased receptor work units
2025-02-12 06:33:18,314 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:33:18,446 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system job 3104200 (failed) is not active, reaping receptor work unit cbHDDll0
2025-02-12 06:33:18,546 ERROR    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch Worker failed to run task awx.main.tasks.system.awx_receptor_workunit_reaper(*[], **{}
Traceback (most recent call last):
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 103, in perform_work
  result = self.run_callable(body)
           ^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 78, in run_callable
  return _call(*args, **kwargs)
         ^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/tasks/system.py", line 690, in awx_receptor_workunit_reaper
  receptor_ctl.simple_command(f"work cancel {job.work_unit_id}")
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 83, in simple_command
  return self.read_and_parse_json()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 60, in read_and_parse_json
  raise RuntimeError(text[7:])
RuntimeError: error cancelling remote unit:  unknown work unit p5g2mnQK
2025-02-12 06:33:20,073 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.007430553436279297 seconds after target
2025-02-12 06:33:20,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 6.991079092025757 seconds
2025-02-12 06:33:20,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 63d3b9cc-61a4-4fb3-82b1-07a1559bc647 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:33:21,339 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.facts Inventory 328 host facts prepared for 1116 hosts, took 16.700 s
2025-02-12 06:33:22,989 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:33:22,992 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:33:24,413 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.facts Inventory 340 host facts prepared for 306 hosts, took 3.003 s
2025-02-12 06:33:24,432 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 running playbook {"type": "inventoryupdate", "task_id": 3144465, "state": "running_playbook", "work_unit_id": null, "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:27,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.007599830627441406 seconds after target
2025-02-12 06:33:27,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 0.9911203384399414 seconds
2025-02-12 06:33:28,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.0012128353118896484 seconds after target
2025-02-12 06:33:28,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.997674465179443 seconds
2025-02-12 06:33:33,316 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:33:34,073 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.006620883941650391 seconds after target
2025-02-12 06:33:34,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9919991493225098 seconds
2025-02-12 06:33:34,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task bf110b83-87bc-4ac5-a54a-de7a973ace36 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:33:34,089 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:33:34,145 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 blocked by inventoryupdate-3144465 {"type": "job", "task_id": 3144463, "state": "blocked", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "blocked_by": "inventoryupdate-3144465"}
2025-02-12 06:33:34,151 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:33:34,154 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342014.154455 seconds ago
2025-02-12 06:33:34,155 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03637121699284762, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0.003533401992172003, 'process_pending_tasks_seconds': 0.0022736320388503373, '_schedule_seconds': 0.06152826896868646, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 4, 'pending_processed': 1, 'tasks_blocked': 1, 'commit_seconds': 0.0017845630645751953}
2025-02-12 06:33:34,940 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 work unit id received {"type": "inventoryupdate", "task_id": 3144465, "state": "work_unit_id_received", "work_unit_id": "ZWCUNzz5", "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:34,953 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 work unit id assigned {"type": "inventoryupdate", "task_id": 3144465, "state": "work_unit_id_assigned", "work_unit_id": "ZWCUNzz5", "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:33:35,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0007445812225341797 seconds after target
2025-02-12 06:33:35,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 4.998711109161377 seconds
2025-02-12 06:33:35,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 0c3ddf1a-26e8-4cf3-b9f1-310ec1248960 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:33:35,083 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:33:35,090 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:33:35,092 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342015.0926836 seconds ago
2025-02-12 06:33:35,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006784486002288759, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006798503978643566, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:33:36,217 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 work unit id received {"type": "job", "task_id": 3144459, "state": "work_unit_id_received", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:33:36,252 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 work unit id assigned {"type": "job", "task_id": 3144459, "state": "work_unit_id_assigned", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:33:37,992 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:33:38,055 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:33:40,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.007527589797973633 seconds after target
2025-02-12 06:33:40,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.007527589797973633 seconds after target
2025-02-12 06:33:40,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task d7a6501e-a5aa-499f-8d4b-552cad624f9d starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:33:40,082 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch scaling up worker pid:771243
2025-02-12 06:33:40,083 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.9829185009002686 seconds
2025-02-12 06:33:40,084 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 6ba651f1-c508-4e4f-a4d6-ab9cdee589d3 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:33:40,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:33:40,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:33:11.484954+00:00
2025-02-12 06:33:48,081 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.014956235885620117 seconds after target
2025-02-12 06:33:48,084 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.981604337692261 seconds
2025-02-12 06:33:48,319 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
rsyslogd: omfwd: remote server at api0401.bdp.anexia-it.com:1470 seems to have closed connection. This often happens when the remote peer (or an interim system like a load balancer or firewall) shuts down or aborts a connection. Rsyslog will re-open the connection if configured to do so (we saw a generic IO Error, which usually goes along with that behaviour). [v8.2102.0-106.el9 try https://www.rsyslog.com/e/2027 ]
rsyslogd: omfwd: remote server at api0401.bdp.anexia-it.com:1470 seems to have closed connection. This often happens when the remote peer (or an interim system like a load balancer or firewall) shuts down or aborts a connection. Rsyslog will re-open the connection if configured to do so (we saw a generic IO Error, which usually goes along with that behaviour). [v8.2102.0-106.el9 try https://www.rsyslog.com/e/2027 ]
2025-02-12 06:33:51,391 DEBUG    [b99e456dcdf945bb8007b4b75d90869c] awx.analytics.performance request: <WSGIRequest: GET '/api/'>, response_time: 0.016s
2025-02-12 06:33:51,481 DEBUG    [ba80b94a72b44aa29f8c18363409b394] awx.analytics.performance request: <WSGIRequest: GET '/api/'>, response_time: 0.018s
2025-02-12 06:33:53,055 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:33:53,057 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:33:54,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.011316537857055664 seconds after target
2025-02-12 06:33:54,079 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9872100353240967 seconds
2025-02-12 06:33:54,079 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task b8f37c39-38da-469d-a0db-9badbe55bd54 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:33:54,097 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:33:54,163 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 blocked by inventoryupdate-3144465 {"type": "job", "task_id": 3144463, "state": "blocked", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "blocked_by": "inventoryupdate-3144465"}
2025-02-12 06:33:54,167 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:33:54,174 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342034.1740642 seconds ago
2025-02-12 06:33:54,174 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.04500449699116871, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0.0034156579640693963, 'process_pending_tasks_seconds': 0.0004071149742230773, '_schedule_seconds': 0.07030683499760926, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 4, 'pending_processed': 1, 'tasks_blocked': 1, 'commit_seconds': 0.0006849765777587891}
2025-02-12 06:33:55,059 DEBUG    [d036104c61a1468bbe8163c75368bcbf] awx.sso.backends Forcing LDAP connection to close
2025-02-12 06:33:55,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012061595916748047 seconds after target
2025-02-12 06:33:55,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 4.998208999633789 seconds
2025-02-12 06:33:55,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 30ad5dfb-b88a-4fca-8f6f-a796f8c387d0 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:33:55,078 INFO     [d036104c61a1468bbe8163c75368bcbf] awx.api.generics User adm.sjovicic logged in from 10.61.236.11
2025-02-12 06:33:55,085 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:33:55,089 DEBUG    [d036104c61a1468bbe8163c75368bcbf] awx.analytics.performance request: <WSGIRequest: POST '/api/login/'>, response_time: 0.148s
10.61.236.11 - - [12/Feb/2025:06:33:55 +0000] "POST /api/login/ HTTP/1.1" 302 0 "https://awx-a8n.anexia-it.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" "10.62.27.65"
[pid: 764818|app: 0|req: 971/418690] 10.61.236.11 () {64 vars in 1146 bytes} [Wed Feb 12 06:33:54 2025] POST /api/login/ => generated 0 bytes in 149 msecs (HTTP/1.1 302) 15 headers in 753 bytes (1 switches on core 0)
2025-02-12 06:33:55,091 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:33:55,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342035.0934682 seconds ago
2025-02-12 06:33:55,094 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006489996041636914, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006521034985780716, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:33:55,202 DEBUG    [adc511fd35cf428a93e4b7653bf35b57] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/me/'>, response_time: 0.067s
2025-02-12 06:33:55,282 DEBUG    [5cc0e8752097445ca0743bd94f4164b3] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/config/'>, response_time: 0.054s
2025-02-12 06:33:55,460 DEBUG    [4d1696ff00664882a14e578033478638] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/organizations/?page_size=1&role_level=notification_admin_role'>, response_time: 0.090s
2025-02-12 06:33:55,466 DEBUG    [5b5faa2456fb47bc87e9d22d02538aa6] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/organizations/?page_size=1&role_level=execution_environment_admin_role'>, response_time: 0.087s
2025-02-12 06:33:55,774 DEBUG    [a1afa824953c444393bf7c2a6222b289] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/dashboard/graphs/jobs/?job_type=all&period=month'>, response_time: 0.272s
2025-02-12 06:33:57,861 DEBUG    [c01246f105aa4d94a0850c93b7fbf708] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/execution_environments/?order_by=name&page=1&page_size=20'>, response_time: 0.101s
2025-02-12 06:34:00,073 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.007082462310791016 seconds after target
2025-02-12 06:34:00,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.990736961364746 seconds
2025-02-12 06:34:00,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 64a62b3a-a0f0-4aa4-8da6-edf26128d7e7 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:34:03,321 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:34:06,968 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.commands.run_callback_receiver Starting EOF event processing for Job 3144465
2025-02-12 06:34:06,968 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.commands.run_callback_receiver Starting EOF event processing for Job 3144465
2025-02-12 06:34:07,003 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 stats wrapup finished {"type": "inventoryupdate", "task_id": 3144465, "state": "stats_wrapup_finished", "work_unit_id": "ZWCUNzz5", "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:34:07,070 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.jobs inventory_update 3144465 (running) finished running, producing 0 events.
2025-02-12 06:34:07,072 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 post run {"type": "inventoryupdate", "task_id": 3144465, "state": "post_run", "work_unit_id": "ZWCUNzz5", "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:34:08,057 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:34:08,060 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:34:08,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.014431238174438477 seconds after target
2025-02-12 06:34:08,085 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9806513786315918 seconds
2025-02-12 06:34:10,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.010030984878540039 seconds after target
2025-02-12 06:34:10,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9895505905151367 seconds
2025-02-12 06:34:10,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 975a02c8-29f7-452a-9ad6-3c853327d23d starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:34:10,094 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:34:10,097 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:33:41.491976+00:00
2025-02-12 06:34:11,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0012276172637939453 seconds after target
2025-02-12 06:34:11,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.9981164932250977 seconds
2025-02-12 06:34:11,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 3d844962-9dc8-4d2c-8033-67d2b18f4afa starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2025-02-12 06:34:11,070 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Cluster node heartbeat task.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
2025-02-12 06:34:14,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.009551286697387695 seconds after target
2025-02-12 06:34:14,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9890711307525635 seconds
2025-02-12 06:34:14,078 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task b35201b4-6775-439d-964e-8ceb2d7e7ab4 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:34:14,091 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:34:14,144 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 blocked by inventoryupdate-3144465 {"type": "job", "task_id": 3144463, "state": "blocked", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "blocked_by": "inventoryupdate-3144465"}
2025-02-12 06:34:14,147 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:34:14,149 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342054.1496277 seconds ago
2025-02-12 06:34:14,150 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03363746899412945, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0.0034525779774412513, 'process_pending_tasks_seconds': 0.0002203690237365663, '_schedule_seconds': 0.0555832710233517, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 1, 'tasks_blocked': 1, 'commit_seconds': 0.0005693435668945312}
2025-02-12 06:34:15,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.001232147216796875 seconds after target
2025-02-12 06:34:15,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.9982733726501465 seconds
2025-02-12 06:34:15,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 4f5a3dec-4068-451b-a037-3aee3ee06cea starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:34:15,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:34:15,102 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:34:15,104 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342055.1045978 seconds ago
2025-02-12 06:34:15,105 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008291057019960135, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008304172020871192, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:34:15,590 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Going to update inventory computed fields, pk=774
2025-02-12 06:34:15,632 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Finished updating inventory computed fields, pk=774, in 0.041 seconds
2025-02-12 06:34:15,678 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Going to update inventory computed fields, pk=774
2025-02-12 06:34:15,692 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.models.inventory Finished updating inventory computed fields, pk=774, in 0.014 seconds
2025-02-12 06:34:15,706 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle inventoryupdate-3144465 finalize run {"type": "inventoryupdate", "task_id": 3144465, "state": "finalize_run", "work_unit_id": "ZWCUNzz5", "task_name": "d62 - ale test constructed - Auto-created source for: d62 - ale test constructed"}
2025-02-12 06:34:15,716 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 35e3049b-920c-4e32-87b9-8bdfa37f02ce starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:34:15,717 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.3491055965423584 seconds
2025-02-12 06:34:15,732 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:34:15,781 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler task job 3144463 (pending) with impact of 6 can fit on instance group 01 with 0 remaining forks and 0
2025-02-12 06:34:15,782 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 controller node chosen {"type": "job", "task_id": 3144463, "state": "controller_node_chosen", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "controller_node": "awx0402"}
2025-02-12 06:34:15,782 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 execution node chosen {"type": "job", "task_id": 3144463, "state": "execution_node_chosen", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test", "execution_node": "exec0102"}
2025-02-12 06:34:15,782 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting job 3144463 (pending) in group 01 instance exec0102 (remaining_capacity=111)
2025-02-12 06:34:15,798 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Submitting job job 3144463 (waiting) controlled by awx0402 to instance group 01 and execution node exec0102.
2025-02-12 06:34:15,804 INFO     [4f13fc6d4c1b43ed9997b8edc46b945f] awx.analytics.job_lifecycle job-3144463 waiting {"type": "job", "task_id": 3144463, "state": "waiting", "work_unit_id": null, "task_name": "D27 - LNX - ale_maint_test"}
2025-02-12 06:34:15,807 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:34:15,812 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342055.812556 seconds ago
2025-02-12 06:34:15,813 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03316074097529054, 'start_task_seconds': 0.022714797989465296, 'process_running_tasks_seconds': 1.4918972738087177e-05, 'process_pending_tasks_seconds': 0.023191616986878216, '_schedule_seconds': 0.07562089001294225, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 1, 'running_processed': 2, 'pending_processed': 1, 'tasks_blocked': 0, 'commit_seconds': 0.003263235092163086}
2025-02-12 06:34:17,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.007849693298339844 seconds after target
2025-02-12 06:34:17,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 0.9917669296264648 seconds
2025-02-12 06:34:17,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task d82a41e7-9c83-4eaa-a883-9a7091828973 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2025-02-12 06:34:18,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.0011849403381347656 seconds after target
2025-02-12 06:34:18,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 1.9983105659484863 seconds
2025-02-12 06:34:18,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task f68df048-cddf-4d13-b45e-eabb60a46447 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2025-02-12 06:34:18,070 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Checking for unreleased receptor work units
2025-02-12 06:34:18,324 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:34:18,455 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system job 3104200 (failed) is not active, reaping receptor work unit cbHDDll0
2025-02-12 06:34:18,541 ERROR    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch Worker failed to run task awx.main.tasks.system.awx_receptor_workunit_reaper(*[], **{}
Traceback (most recent call last):
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 103, in perform_work
  result = self.run_callable(body)
           ^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 78, in run_callable
  return _call(*args, **kwargs)
         ^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/tasks/system.py", line 690, in awx_receptor_workunit_reaper
  receptor_ctl.simple_command(f"work cancel {job.work_unit_id}")
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 83, in simple_command
  return self.read_and_parse_json()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 60, in read_and_parse_json
  raise RuntimeError(text[7:])
RuntimeError: error cancelling remote unit:  unknown work unit p5g2mnQK
2025-02-12 06:34:20,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.008605480194091797 seconds after target
2025-02-12 06:34:20,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 6.989748477935791 seconds
2025-02-12 06:34:20,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 121fbaa8-4841-47f7-8f73-a596304730bc starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:34:22,623 DEBUG    [-] awx.main.models.inventory Going to update inventory computed fields, pk=722
2025-02-12 06:34:22,664 DEBUG    [-] awx.main.models.inventory Finished updating inventory computed fields, pk=722, in 0.042 seconds
2025-02-12 06:34:22,729 DEBUG    [-] awx.main.models.events Event propagation for job 3144459: marked 1 as changed in 0.0596s, 0 as failed in 0.0024s
2025-02-12 06:34:22,781 INFO     [-] awx.analytics.job_lifecycle job-3144459 stats wrapup finished {"type": "job", "task_id": 3144459, "state": "stats_wrapup_finished", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:34:23,060 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:34:23,063 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:34:27,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.013489723205566406 seconds after target
2025-02-12 06:34:27,081 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch scaling down worker pid:768944
2025-02-12 06:34:27,081 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 0.9848446846008301 seconds
2025-02-12 06:34:27,082 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch worker exiting gracefully pid:768944
2025-02-12 06:34:28,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.0012183189392089844 seconds after target
2025-02-12 06:34:28,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.997607469558716 seconds
2025-02-12 06:34:33,327 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:34:34,078 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.012259960174560547 seconds after target
2025-02-12 06:34:34,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9863908290863037 seconds
2025-02-12 06:34:34,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task d25d2f67-3f72-4c9b-94e8-9c788f2ca1d6 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:34:34,099 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:34:34,155 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:34:34,158 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342074.1584618 seconds ago
2025-02-12 06:34:34,159 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.038705745013430715, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.5148969143629074e-05, 'process_pending_tasks_seconds': 2.277403837069869e-05, '_schedule_seconds': 0.05628510995302349, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0009748935699462891}
2025-02-12 06:34:35,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012519359588623047 seconds after target
2025-02-12 06:34:35,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 4.998161315917969 seconds
2025-02-12 06:34:35,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 47af3731-b578-4ca7-bf40-a206fb7f0ce7 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:34:35,086 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:34:35,092 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:34:35,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342075.0948706 seconds ago
2025-02-12 06:34:35,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006763656972907484, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006775459041818976, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:34:38,062 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:34:38,135 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:34:40,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.008510828018188477 seconds after target
2025-02-12 06:34:40,076 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.008510828018188477 seconds after target
2025-02-12 06:34:40,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.9892799854278564 seconds
2025-02-12 06:34:40,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task f1671de7-b5cc-4584-8690-3716e5980406 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:34:40,078 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task ea1f4528-0e18-4a07-984c-afd4c7d53257 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:34:40,094 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:34:40,096 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:34:11.486233+00:00
2025-02-12 06:34:48,081 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.014791727066040039 seconds after target
2025-02-12 06:34:48,083 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.98321270942688 seconds
2025-02-12 06:34:48,329 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
...The work of process 757743 is done. Seeya!
worker 3 killed successfully (pid: 757743)
Respawned uWSGI worker 3 (new pid: 771246)
mounting awx.wsgi:application on /
WSGI app 0 (mountpoint='/') ready in 1 seconds on interpreter 0x7fe9b0376cf8 pid: 771246 (default app)
2025-02-12 06:34:53,135 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:34:53,138 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:34:54,079 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.01268315315246582 seconds after target
2025-02-12 06:34:54,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9857287406921387 seconds
2025-02-12 06:34:54,081 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 8fb3a8ef-ace3-41e8-8a6b-fab51351a7f3 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:34:54,097 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:34:54,144 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:34:54,149 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342094.149277 seconds ago
2025-02-12 06:34:54,150 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.02871616301126778, 'start_task_seconds': 0, 'process_running_tasks_seconds': 5.823100218549371e-05, 'process_pending_tasks_seconds': 4.056701436638832e-05, '_schedule_seconds': 0.046695438970346004, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0007174015045166016}
2025-02-12 06:34:55,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012335777282714844 seconds after target
2025-02-12 06:34:55,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 4.998216390609741 seconds
2025-02-12 06:34:55,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task adf9a758-d9e5-4ac7-add7-bbabb3ef6fce starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:34:55,084 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:34:55,092 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:34:55,094 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342095.0941296 seconds ago
2025-02-12 06:34:55,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007161073968745768, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007174008991569281, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
...The work of process 764818 is done. Seeya!
2025-02-12 06:34:56,077 DEBUG    [13c3066e43c04ea8ab19249b6bf5fb39] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/config/'>, response_time: 0.080s
2025-02-12 06:34:56,186 DEBUG    [f8daa7514f82492b87132179ce9aa763] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/settings/system/'>, response_time: 0.097s
2025-02-12 06:34:56,414 DEBUG    [87d750a739fd4e9aa54bd180d790330a] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/organizations/?page_size=1&role_level=notification_admin_role'>, response_time: 0.216s
2025-02-12 06:34:56,498 DEBUG    [526c1c7cf6104e008df51c509491b79b] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/workflow_approvals/?page_size=1&status=pending'>, response_time: 0.053s
2025-02-12 06:34:56,552 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to control-limit_reached_1.
2025-02-12 06:34:56,554 DEBUG    [-] awx.main.wsrelay Connection from awx0401 to awx0402 added subscription to jobs-status_changed.
2025-02-12 06:34:56,962 DEBUG    [839f60f536514d3cbcfc01346afe76ce] awx.analytics.performance request: <WSGIRequest: OPTIONS '/api/v2/jobs/3128757/job_events/'>, response_time: 0.059s
10.61.236.11 - - [12/Feb/2025:06:34:56 +0000] "OPTIONS /api/v2/jobs/3128757/job_events/ HTTP/1.1" 200 12315 "https://awx-a8n.anexia-it.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" "10.62.27.65"
[pid: 764812|app: 0|req: 471/418748] 10.61.236.11 () {60 vars in 1144 bytes} [Wed Feb 12 06:34:56 2025] OPTIONS /api/v2/jobs/3128757/job_events/ => generated 12315 bytes in 61 msecs (HTTP/1.1 200) 15 headers in 599 bytes (1 switches on core 0)
worker 2 killed successfully (pid: 764818)
Respawned uWSGI worker 2 (new pid: 771252)
mounting awx.wsgi:application on /
WSGI app 0 (mountpoint='/') ready in 1 seconds on interpreter 0x7fe9b0376cf8 pid: 771252 (default app)
2025-02-12 06:34:59,863 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!e9125c086fd14822bae3d99d095241c9 from awx0402-control-limit_reached_1
2025-02-12 06:34:59,864 DEBUG    [-] awx.main.wsrelay Unsubscribed specific.ae06309e281c406785d2c30a46e54460!e9125c086fd14822bae3d99d095241c9 from awx0402-jobs-status_changed
2025-02-12 06:35:00,077 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.011310338973999023 seconds after target
2025-02-12 06:35:00,079 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.987064361572266 seconds
2025-02-12 06:35:00,080 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 7df3ae31-15b3-410e-8794-b0a6ca18c71b starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:35:03,332 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:35:03,476 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.main.commands.run_callback_receiver Starting EOF event processing for Job 3144459
2025-02-12 06:35:03,476 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.main.commands.run_callback_receiver Starting EOF event processing for Job 3144459
2025-02-12 06:35:03,603 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.jobs job 3144459 (running) finished running, producing 348 events.
2025-02-12 06:35:03,605 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 post run {"type": "job", "task_id": 3144459, "state": "post_run", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:35:03,625 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 finish job fact cache {"type": "job", "task_id": 3144459, "state": "finish_job_fact_cache", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:35:08,082 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.015470266342163086 seconds after target
2025-02-12 06:35:08,083 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.982591152191162 seconds
2025-02-12 06:35:08,138 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:35:08,141 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:35:10,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.007449150085449219 seconds after target
2025-02-12 06:35:10,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9921557903289795 seconds
2025-02-12 06:35:10,074 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 5180772b-30cf-423c-8f44-4129fb9e2289 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:35:10,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:35:10,095 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:34:41.485624+00:00
2025-02-12 06:35:11,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0012309551239013672 seconds after target
2025-02-12 06:35:11,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.9982333183288574 seconds
2025-02-12 06:35:11,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task b7b9d27c-d773-4db4-ad7f-7c3858e20910 starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2025-02-12 06:35:11,069 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.tasks.system Cluster node heartbeat task.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
2025-02-12 06:35:14,073 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found task_manager to run, 0.007340431213378906 seconds after target
2025-02-12 06:35:14,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.991318941116333 seconds
2025-02-12 06:35:14,075 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task 2e93d12b-263d-48df-8575-b6db5a209490 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:35:14,092 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:35:14,143 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:35:14,148 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording task_manager metrics, last recorded 1739342114.1481125 seconds ago
2025-02-12 06:35:14,149 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03430387895787135, 'start_task_seconds': 0, 'process_running_tasks_seconds': 1.8746010027825832e-05, 'process_pending_tasks_seconds': 1.8925988115370274e-05, '_schedule_seconds': 0.050599578011315316, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 3, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0006499290466308594}
2025-02-12 06:35:15,067 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012044906616210938 seconds after target
2025-02-12 06:35:15,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.9982905387878418 seconds
2025-02-12 06:35:15,068 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.dispatch task c791769b-1010-4658-aefc-e770752650b6 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:35:15,083 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:35:15,090 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:35:15,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342115.0928214 seconds ago
2025-02-12 06:35:15,093 DEBUG    [4f13fc6d4c1b43ed9997b8edc46b945f] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006996651005465537, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007009285036474466, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:35:15,774 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.facts Inventory 722 host facts: updated 1, cleared 0, unchanged 1701, took 12.149 s
rsyslogd: omfwd: remote server at api0401.bdp.anexia-it.com:1470 seems to have closed connection. This often happens when the remote peer (or an interim system like a load balancer or firewall) shuts down or aborts a connection. Rsyslog will re-open the connection if configured to do so (we saw a generic IO Error, which usually goes along with that behaviour). [v8.2102.0-106.el9 try https://www.rsyslog.com/e/2027 ]
2025-02-12 06:35:15,869 INFO     [9b0f236bd11645e7a759f2b439002a52] awx.analytics.job_lifecycle job-3144459 finalize run {"type": "job", "task_id": 3144459, "state": "finalize_run", "work_unit_id": "JppO55hN", "task_name": "Fact Debug"}
2025-02-12 06:35:15,910 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 69223286-ed07-47bd-8861-b8a9b83269cc starting awx.main.tasks.system.update_inventory_computed_fields(*[722])
2025-02-12 06:35:15,910 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.156425952911377 seconds
2025-02-12 06:35:15,929 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Going to update inventory computed fields, pk=722
2025-02-12 06:35:15,978 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.models.inventory Finished updating inventory computed fields, pk=722, in 0.049 seconds
2025-02-12 06:35:16,311 DEBUG    [e9c2365d899f47e39162d75308766711] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144459/'>, response_time: 0.151s
2025-02-12 06:35:16,357 DEBUG    [210ea031e1a64a3cb4c7ce0740b07e31] awx.analytics.performance request: <WSGIRequest: GET '/api/v2/jobs/3144459/'>, response_time: 0.156s
2025-02-12 06:35:17,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.007837295532226562 seconds after target
2025-02-12 06:35:17,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 0.9917402267456055 seconds
2025-02-12 06:35:17,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 4d4d67c7-4dde-45ed-b40d-1315d829c15c starting awx.main.tasks.system.awx_k8s_reaper(*[])
2025-02-12 06:35:18,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.001257181167602539 seconds after target
2025-02-12 06:35:18,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 1.9981238842010498 seconds
2025-02-12 06:35:18,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 06b4448d-6cf1-4137-bd59-e19e5fc89322 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2025-02-12 06:35:18,071 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Checking for unreleased receptor work units
2025-02-12 06:35:18,335 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:35:18,477 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system job 3104200 (failed) is not active, reaping receptor work unit cbHDDll0
2025-02-12 06:35:18,565 ERROR    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch Worker failed to run task awx.main.tasks.system.awx_receptor_workunit_reaper(*[], **{}
Traceback (most recent call last):
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 103, in perform_work
  result = self.run_callable(body)
           ^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/dispatch/worker/task.py", line 78, in run_callable
  return _call(*args, **kwargs)
         ^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/awx/main/tasks/system.py", line 690, in awx_receptor_workunit_reaper
  receptor_ctl.simple_command(f"work cancel {job.work_unit_id}")
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 83, in simple_command
  return self.read_and_parse_json()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/lib/awx/venv/awx/lib64/python3.11/site-packages/receptorctl/socket_interface.py", line 60, in read_and_parse_json
  raise RuntimeError(text[7:])
RuntimeError: error cancelling remote unit:  unknown work unit p5g2mnQK
2025-02-12 06:35:20,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0081787109375 seconds after target
2025-02-12 06:35:20,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 6.990530014038086 seconds
2025-02-12 06:35:20,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 87b916d1-175c-4228-a65c-9396128fcfec starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:35:23,141 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:35:23,143 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:35:27,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.013336181640625 seconds after target
2025-02-12 06:35:27,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 0.9851586818695068 seconds
2025-02-12 06:35:28,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.0012195110321044922 seconds after target
2025-02-12 06:35:28,072 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.994009256362915 seconds
2025-02-12 06:35:33,338 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:35:34,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.01274418830871582 seconds after target
2025-02-12 06:35:34,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9858741760253906 seconds
2025-02-12 06:35:34,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 7ac5c88b-f40e-4fc1-829e-581e5f029669 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:35:34,097 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:35:34,147 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:35:34,150 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739342134.1500196 seconds ago
2025-02-12 06:35:34,150 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.03299543500179425, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.1781015675514936e-05, 'process_pending_tasks_seconds': 2.9867049306631088e-05, '_schedule_seconds': 0.05017523898277432, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 2, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0006062984466552734}
2025-02-12 06:35:35,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012252330780029297 seconds after target
2025-02-12 06:35:35,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 4.998263359069824 seconds
2025-02-12 06:35:35,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 89ef5ffe-6d31-4a2d-bfe3-c52f1ad30e81 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:35:35,084 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:35:35,091 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:35:35,093 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342135.0934222 seconds ago
2025-02-12 06:35:35,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006174774025566876, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006192868982907385, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:35:38,143 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:35:38,214 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:35:40,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.01321101188659668 seconds after target
2025-02-12 06:35:40,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.01321101188659668 seconds after target
2025-02-12 06:35:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.985263109207153 seconds
2025-02-12 06:35:40,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task eac1affb-008d-4eec-b773-fdeb572b5b54 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:35:40,082 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task f71673d6-4eb9-494a-878e-4fd509dfa81b starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:35:40,100 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:35:40,102 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:35:11.486639+00:00
2025-02-12 06:35:48,082 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.015674114227294922 seconds after target
2025-02-12 06:35:48,087 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.978880882263184 seconds
2025-02-12 06:35:48,341 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:35:53,214 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:35:53,216 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:35:54,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.012880563735961914 seconds after target
2025-02-12 06:35:54,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9854881763458252 seconds
2025-02-12 06:35:54,081 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 141bf612-47e1-447e-a7e1-9d008aa08e6f starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:35:54,097 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:35:54,146 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:35:54,148 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739342154.148304 seconds ago
2025-02-12 06:35:54,149 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.031697703001555055, 'start_task_seconds': 0, 'process_running_tasks_seconds': 2.7442991267889738e-05, 'process_pending_tasks_seconds': 2.844404662027955e-05, '_schedule_seconds': 0.04846591199748218, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 2, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0006036758422851562}
2025-02-12 06:35:55,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012545585632324219 seconds after target
2025-02-12 06:35:55,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 4.998216390609741 seconds
2025-02-12 06:35:55,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 258d7fc8-67af-486d-b61f-a220bfd76738 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:35:55,087 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:35:55,095 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:35:55,100 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342155.10065 seconds ago
2025-02-12 06:35:55,101 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007958142959978431, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007973482017405331, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2025-02-12 06:36:00,078 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.011675357818603516 seconds after target
2025-02-12 06:36:00,079 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.986897706985474 seconds
2025-02-12 06:36:00,080 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 2b48c713-f1b6-4500-88ee-ee740c66f143 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2025-02-12 06:36:03,343 DEBUG    [-] awx.main.wsrelay Web host awx0402 (awx0402) online heartbeat received.
2025-02-12 06:36:08,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.007711172103881836 seconds after target
2025-02-12 06:36:08,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.990441083908081 seconds
2025-02-12 06:36:08,216 DEBUG    [-] awx.main.commands.run_ws_heartbeat Sending heartbeat
2025-02-12 06:36:08,219 DEBUG    [-] awx.main.wsrelay Received a heartbeat request for awx0401. Skipping as we use redis for local host.
2025-02-12 06:36:10,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.008448362350463867 seconds after target
2025-02-12 06:36:10,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9911818504333496 seconds
2025-02-12 06:36:10,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task 9af8942e-34c6-4943-b23c-a48d3cee2226 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2025-02-12 06:36:10,092 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Starting periodic scheduler
2025-02-12 06:36:10,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Last scheduler run was: 2025-02-12 06:35:41.491058+00:00
2025-02-12 06:36:11,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0012211799621582031 seconds after target
2025-02-12 06:36:11,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is gather_analytics in 0.9981939792633057 seconds
2025-02-12 06:36:11,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task cde8b2d6-d708-4926-8b83-039d1c59bf7e starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2025-02-12 06:36:11,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.tasks.system Cluster node heartbeat task.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
min_value in DecimalField should be Decimal type.
2025-02-12 06:36:12,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found gather_analytics to run, 0.007567644119262695 seconds after target
2025-02-12 06:36:12,074 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is task_manager in 1.9920454025268555 seconds
2025-02-12 06:36:12,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task c814343c-3127-4ace-a7b1-14dfa6773a37 starting awx.main.tasks.system.gather_analytics(*[])
2025-02-12 06:36:14,075 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found task_manager to run, 0.008556604385375977 seconds after target
2025-02-12 06:36:14,076 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 0.9900531768798828 seconds
2025-02-12 06:36:14,077 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task d052d8b1-7f4f-4f10-a369-6c5be72dc523 starting awx.main.scheduler.tasks.task_manager(*[])
2025-02-12 06:36:14,092 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting task_manager Scheduler
2025-02-12 06:36:14,138 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting task_manager Scheduler changes
2025-02-12 06:36:14,145 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording task_manager metrics, last recorded 1739342174.1448605 seconds ago
2025-02-12 06:36:14,145 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.029504495032597333, 'start_task_seconds': 0, 'process_running_tasks_seconds': 1.7343030776828527e-05, 'process_pending_tasks_seconds': 1.955695915967226e-05, '_schedule_seconds': 0.04620113701093942, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 2, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0009071826934814453}
2025-02-12 06:36:15,067 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0012421607971191406 seconds after target
2025-02-12 06:36:15,068 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 1.9982266426086426 seconds
2025-02-12 06:36:15,069 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.dispatch task b7c164f6-7f2c-48e6-8065-f626f4dc33b3 starting awx.main.scheduler.tasks.dependency_manager(*[])
2025-02-12 06:36:15,086 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Starting dependency_manager Scheduler
2025-02-12 06:36:15,094 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Commiting dependency_manager Scheduler changes
2025-02-12 06:36:15,096 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler recording dependency_manager metrics, last recorded 1739342175.0967422 seconds ago
2025-02-12 06:36:15,097 DEBUG    [9b0f236bd11645e7a759f2b439002a52] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.0071402949979528785, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007153469021432102, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}

@egmar
Copy link
Contributor

egmar commented Feb 17, 2025 •
edited
Loading

I've seen this in past, and there is even an issue touching some aspect of the problem #9403 and a more generic one in Ansible project ansible/ansible#73654.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
community needs_triage type:bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@egmar @AlanCoding @anxjok