search

ansible / awx

AWX provides a web-based user interface, REST API, and task engine built on top of Ansible. It is one of the upstream projects for Red Hat Ansible Automation Platform.
Other
14.06k stars 3.42k forks source link

AWX 24.0.0 does not run project and job updates: Demo Job Template #15023

Open moreirodamian opened 7 months ago

moreirodamian commented 7 months ago

Please confirm the following

Bug Summary

Install AWX 24.0.0 using AWX Operator. K8s Version: v1.29.1

When the installation finishes, try to run the default job: Demo Job Template and it remains pending.

The awx-task container logs say the following:

[wait-for-migrations] Waiting for database migrations...
[wait-for-migrations] Attempt 1
Instance Group already registered controlplane
Instance Group already registered default
Successfully registered instance None
(changed: True)
2024-03-25 01:52:48,479 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
2024-03-25 01:52:48,479 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
2024-03-25 01:52:48,486 INFO RPC interface 'supervisor' initialized
2024-03-25 01:52:48,486 INFO RPC interface 'supervisor' initialized
2024-03-25 01:52:48,486 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2024-03-25 01:52:48,486 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2024-03-25 01:52:48,486 INFO supervisord started with pid 7
2024-03-25 01:52:48,486 INFO supervisord started with pid 7
2024-03-25 01:52:49,491 INFO spawned: 'superwatcher' with pid 30
2024-03-25 01:52:49,491 INFO spawned: 'superwatcher' with pid 30
2024-03-25 01:52:49,494 INFO spawned: 'dispatcher' with pid 31
2024-03-25 01:52:49,494 INFO spawned: 'dispatcher' with pid 31
2024-03-25 01:52:49,497 INFO spawned: 'callback-receiver' with pid 32
2024-03-25 01:52:49,497 INFO spawned: 'callback-receiver' with pid 32
2024-03-25 01:52:49,500 INFO spawned: 'wsrelay' with pid 33
2024-03-25 01:52:49,500 INFO spawned: 'wsrelay' with pid 33
READY
2024-03-25 01:52:50,503 INFO success: superwatcher entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-03-25 01:52:50,503 INFO success: superwatcher entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-03-25 01:52:53,200 INFO     [-] awx.main.dispatch Running worker dispatcher listening to queues ['tower_broadcast_all', 'tower_settings_change', 'awx-task-788785d975-nx2z8']
2024-03-25 01:52:53,202 INFO     [-] awx.main.commands.run_callback_receiver Callback receiver started with pid=32
2024-03-25 01:52:53,273 INFO     [-] awx.main.wsrelay Active instance with hostname awx-task-788785d975-nx2z8 is registered.
2024-03-25 01:52:53,529 WARNING  [-] awx.main.tasks.system Rejoining the cluster as instance awx-task-788785d975-nx2z8. Prior last_seen None
2024-03-25 01:52:53,572 INFO     [-] awx.main.dispatch Dispatcher listener connection established
2024-03-25 01:52:53,572 WARNING  [-] awx.main.dispatch.periodic Scheduler next run unexpectedly over 20 seconds in future: 25.627272129058838
2024-03-25 01:53:19,605 INFO success: dispatcher entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:19,605 INFO success: dispatcher entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:19,605 INFO success: callback-receiver entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:19,605 INFO success: callback-receiver entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:19,605 INFO success: wsrelay entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:19,605 INFO success: wsrelay entered RUNNING state, process has stayed up for > than 30 seconds (startsecs)
2024-03-25 01:53:56,408 WARNING  [-] awx.main.tasks.system Heartbeat skew - interval=62.8150, expected=60
2024-03-25 01:54:02,325 ERROR    [-] awx.main.dispatch Worker failed to run task awx.main.tasks.system.awx_k8s_reaper(*[], **{}
Traceback (most recent call last):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/utils.py", line 98, in inner
    return func(*args, **kwargs)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 321, in fetchmany
    recs = self._conn.wait(self._fetch_gen(size))
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 957, in wait
    return waiting.wait(gen, self.pgconn.socket, timeout=timeout)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/waiting.py", line 283, in wait_epoll
    s = gen.send(ready)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 172, in _fetch_gen
    res = yield from self._conn._exec_command(query, result_format=self._format)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 466, in _exec_command
    raise e.error_from_result(result, encoding=pgconn_encoding(self.pgconn))
psycopg.errors.InvalidCursorName: cursor "_django_curs_140304504547136_sync_1" does not exist

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 2093, in cursor_iter
    for rows in iter((lambda: cursor.fetchmany(itersize)), sentinel):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 2093, in <lambda>
    for rows in iter((lambda: cursor.fetchmany(itersize)), sentinel):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/utils.py", line 98, in inner
    return func(*args, **kwargs)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/utils.py", line 98, in inner
    return func(*args, **kwargs)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 321, in fetchmany
    recs = self._conn.wait(self._fetch_gen(size))
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 957, in wait
    return waiting.wait(gen, self.pgconn.socket, timeout=timeout)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/waiting.py", line 283, in wait_epoll
    s = gen.send(ready)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 172, in _fetch_gen
    res = yield from self._conn._exec_command(query, result_format=self._format)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 466, in _exec_command
    raise e.error_from_result(result, encoding=pgconn_encoding(self.pgconn))
django.db.utils.ProgrammingError: cursor "_django_curs_140304504547136_sync_1" does not exist

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/var/lib/awx/venv/awx/lib64/python3.9/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.9/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.9/site-packages/awx/main/tasks/system.py", line 700, in awx_k8s_reaper
    for group in InstanceGroup.objects.filter(is_container_group=True).iterator():
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/query.py", line 516, in _iterator
    yield from iterable
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/query.py", line 121, in __iter__
    for row in compiler.results_iter(results):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 1496, in apply_converters
    for row in map(list, rows):
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 2096, in cursor_iter
    cursor.close()
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 269, in close
    self._conn.wait(self._close_gen())
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 957, in wait
    return waiting.wait(gen, self.pgconn.socket, timeout=timeout)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/waiting.py", line 283, in wait_epoll
    s = gen.send(ready)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/server_cursor.py", line 158, in _close_gen
    yield from self._conn._exec_command(query)
  File "/var/lib/awx/venv/awx/lib64/python3.9/site-packages/psycopg/connection.py", line 466, in _exec_command
    raise e.error_from_result(result, encoding=pgconn_encoding(self.pgconn))
psycopg.errors.InvalidCursorName: cursor "_django_curs_140304504547136_sync_1" does not exist
2024-03-25 01:59:56,379 ERROR    [-] awx.main.dispatch project_update 1 (failed) is no longer waiting; reaping

AWX version

24.0.0

Select the relevant components

Installation method

kubernetes

Modifications

no

Ansible version

No response

Operating system

No response

Web browser

Chrome

Steps to reproduce

Demo Job Template

Expected results

Running correctly

Actual results

pending state

Additional information

GET /api/v2/ping/
HTTP 200 OK
Allow: GET, HEAD, OPTIONS
Content-Type: application/json
Vary: Accept
X-API-Node: awx-web-7ff454b6d8-9tm5x
X-API-Product-Name: AWX
X-API-Time: 0.021s

{
    "ha": true,
    "version": "24.0.0",
    "active_node": "awx-web-7ff454b6d8-9tm5x",
    "install_uuid": "8c8b1d2e-3aeb-44bc-bb7a-ec605ce15fb6",
    "instances": [
        {
            "node": "awx-task-788785d975-nx2z8",
            "node_type": "control",
            "uuid": "63ca7ef8-dbf3-4b31-8f74-b9551098592e",
            "heartbeat": "2024-03-25T02:17:56.256202Z",
            "capacity": 159,
            "version": "24.0.0"
        },
        {
            "node": "awx-task-788785d975-whbkj",
            "node_type": "control",
            "uuid": "463d09b5-aaad-4bac-94b3-5c896463ddff",
            "heartbeat": "2024-03-25T02:17:25.266348Z",
            "capacity": 146,
            "version": "24.0.0"
        }
    ],
    "instance_groups": [
        {
            "name": "controlplane",
            "capacity": 305,
            "instances": [
                "awx-task-788785d975-nx2z8",
                "awx-task-788785d975-whbkj"
            ]
        },
        {
            "name": "default",
            "capacity": 0,
            "instances": []
        }
    ]
}
fosterseth commented 7 months ago

@moreirodamian are you still experiencing this bad state? are your postgres pods up and healthy? does restarting postgres or task pods help at all?

TheRealHaoLiu commented 7 months ago

is this a fresh install? or an upgrade?

TheRealHaoLiu commented 7 months ago

is the database external or managed by AWX-operator?

TheRealHaoLiu commented 7 months ago

from the traceback it seems its failing while trying to run awx.main.tasks.system.awx_k8s_reaper

it runs periodically, do you continue to see this error all the time?

also 

2024-03-25 01:59:56,379 ERROR    [-] awx.main.dispatch project_update 1 (failed) is no longer waiting; reaping

worries me this means that we assign a job to the task instance and the task instance fail to start the job in time...

kinda points me to the direction of postgres problem...

marek1712 commented 7 months ago

Hi.

I'm facing the same issue: just upgraded AWX from 23.9.0 to 24.1.0 using @kurokobo's guide: LINK.

Inventory Source job works fine - but state is stuck in Pending state and no Output is shown. I have to move between Details/Output for it to refresh. Once it's finished: status is changed from Pending to Successful.

Database is managed by AWX-operator.

kubectl -n awx get pods
NAME                                               READY   STATUS      RESTARTS        AGE
awx-migration-24.1.0-xhdkl                         0/1     Completed   0               23m
awx-postgres-15-0                                  1/1     Running     1 (9m41s ago)   25m
awx-web-6d85dc6db7-wpfgp                           3/3     Running     3 (9m41s ago)   25m
awx-operator-controller-manager-6458cd4798-wpnm8   2/2     Running     2 (9m41s ago)   26m
awx-task-744d849bbf-45rwn                          4/4     Running     5 (8m42s ago)   25m

I haven't cleaned up postgres-13-0 yet:

kubectl -n awx get pv
NAME                     CAPACITY   ACCESS MODES   RECLAIM POLICY   STATUS   CLAIM                               STORAGECLASS          REASON   AGE
awx-projects-volume      2Gi        RWO            Retain           Bound    awx/awx-projects-claim              awx-projects-volume            2y153d
awx-postgres-13-volume   8Gi        RWO            Retain           Bound    awx/postgres-13-awx-postgres-13-0   awx-postgres-volume            512d
awx-backup-volume        2Gi        RWO            Retain           Bound    awx/awx-backup-claim                awx-backup-volume              408d
awx-postgres-15-volume   8Gi        RWO            Retain           Bound    awx/postgres-15-awx-postgres-15-0   awx-postgres-volume            29m

Describe PG pods:

kubectl -n awx describe pods awx-postgres-15-0
Name:             awx-postgres-15-0
Namespace:        awx
Priority:         0
Service Account:  default
Node:             awx.abc.local/192.168.233.128
Start Time:       Thu, 28 Mar 2024 11:12:09 +0100
Labels:           app.kubernetes.io/component=database
                  app.kubernetes.io/instance=postgres-15-awx
                  app.kubernetes.io/managed-by=awx-operator
                  app.kubernetes.io/name=postgres-15
                  app.kubernetes.io/part-of=awx
                  apps.kubernetes.io/pod-index=0
                  controller-revision-hash=awx-postgres-15-6f4f4f496d
                  statefulset.kubernetes.io/pod-name=awx-postgres-15-0
Annotations:      <none>
Status:           Running
IP:               10.42.0.117
IPs:
  IP:           10.42.0.117
Controlled By:  StatefulSet/awx-postgres-15
Containers:
  postgres:
    Container ID:   containerd://946ee79165b663cb459e6f2d5dc49bccba27eb653a5625dbb32a8165e6f33e4e
    Image:          quay.io/sclorg/postgresql-15-c9s:latest
    Image ID:       quay.io/sclorg/postgresql-15-c9s@sha256:48d6daecae2d091213664ba7bf60cb6411a986b7e1060e0ee97b19b59e4ae429
    Port:           5432/TCP
    Host Port:      0/TCP
    State:          Running
      Started:      Thu, 28 Mar 2024 11:27:55 +0100
    Last State:     Terminated
      Reason:       Unknown
      Exit Code:    255
      Started:      Thu, 28 Mar 2024 11:12:10 +0100
      Finished:     Thu, 28 Mar 2024 11:27:51 +0100
    Ready:          True
    Restart Count:  1
    Environment:
      POSTGRESQL_DATABASE:        <set to the key 'database' in secret 'awx-postgres-configuration'>  Optional: false
      POSTGRESQL_USER:            <set to the key 'username' in secret 'awx-postgres-configuration'>  Optional: false
      POSTGRESQL_PASSWORD:        <set to the key 'password' in secret 'awx-postgres-configuration'>  Optional: false
      POSTGRES_DB:                <set to the key 'database' in secret 'awx-postgres-configuration'>  Optional: false
      POSTGRES_USER:              <set to the key 'username' in secret 'awx-postgres-configuration'>  Optional: false
      POSTGRES_PASSWORD:          <set to the key 'password' in secret 'awx-postgres-configuration'>  Optional: false
      PGDATA:                     /var/lib/pgsql/data/pgdata
      POSTGRES_INITDB_ARGS:       --auth-host=scram-sha-256
      POSTGRES_HOST_AUTH_METHOD:  scram-sha-256
    Mounts:
      /var/lib/pgsql/data from postgres-15 (rw,path="data")
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-8ctks (ro)
Conditions:
  Type              Status
  Initialized       True
  Ready             True
  ContainersReady   True
  PodScheduled      True
Volumes:
  postgres-15:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  postgres-15-awx-postgres-15-0
    ReadOnly:   false
  kube-api-access-8ctks:
    Type:                    Projected (a volume that contains injected data from multiple sources)
    TokenExpirationSeconds:  3607
    ConfigMapName:           kube-root-ca.crt
    ConfigMapOptional:       <nil>
    DownwardAPI:             true
QoS Class:                   BestEffort
Node-Selectors:              <none>
Tolerations:                 node.kubernetes.io/not-ready:NoExecute op=Exists for 300s
                             node.kubernetes.io/unreachable:NoExecute op=Exists for 300s
Events:
  Type    Reason          Age   From               Message
  ----    ------          ----  ----               -------
  Normal  Scheduled       27m   default-scheduler  Successfully assigned awx/awx-postgres-15-0 to awx.abc.local
  Normal  Pulled          27m   kubelet            Container image "quay.io/sclorg/postgresql-15-c9s:latest" already present on machine
  Normal  Created         27m   kubelet            Created container postgres
  Normal  Started         27m   kubelet            Started container postgres
  Normal  SandboxChanged  11m   kubelet            Pod sandbox changed, it will be killed and re-created.
  Normal  Pulled          11m   kubelet            Container image "quay.io/sclorg/postgresql-15-c9s:latest" already present on machine
  Normal  Created         11m   kubelet            Created container postgres
  Normal  Started         11m   kubelet            Started container postgres
kubectl -n awx describe pv awx-postgres-15-volume
Name:            awx-postgres-15-volume
Labels:          <none>
Annotations:     pv.kubernetes.io/bound-by-controller: yes
Finalizers:      [kubernetes.io/pv-protection]
StorageClass:    awx-postgres-volume
Status:          Bound
Claim:           awx/postgres-15-awx-postgres-15-0
Reclaim Policy:  Retain
Access Modes:    RWO
VolumeMode:      Filesystem
Capacity:        8Gi
Node Affinity:   <none>
Message:
Source:
    Type:          HostPath (bare host directory volume)
    Path:          /data/postgres-15
    HostPathType:
Events:            <none>
kurokobo commented 7 months ago

@marek1712

Inventory Source job works fine - but state is stuck in Pending state and no Output is shown. I have to move between Details/Output for it to refresh. Once it's finished: status is changed from Pending to Successful.

Perhaps your issue is different from OP, I think yours is here (already fixed in upstream devel branch): https://github.com/ansible/awx/issues/15038

moreirodamian commented 7 months ago

@fosterseth

It was a Fresh installation.

The db pods are fine, I also tried an external db and it didn't work either.

I set the logs to DEBUG level and obtained the following on the task pod:

2024-04-01 01:19:15,773 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9827404022216797 seconds
2024-04-01 01:19:15,774 DEBUG    [-] awx.main.dispatch task b45612fd-8c2d-4a7c-bdeb-fb2a665adb4b starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:19:15,817 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:19:15,820 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:18:45.827293+00:00
2024-04-01 01:19:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0013797283172607422 seconds after target
2024-04-01 01:19:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.997758150100708 seconds
2024-04-01 01:19:16,758 DEBUG    [-] awx.main.dispatch task 139cd56e-8c94-4a89-ba32-316c916e1e4a starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:19:16,760 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:19:19,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.021959304809570312 seconds after target
2024-04-01 01:19:19,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9749040603637695 seconds
2024-04-01 01:19:19,782 DEBUG    [-] awx.main.dispatch task 713541f3-806d-4bf8-916e-34cb6f99292e starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:19:19,812 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:19:19,869 DEBUG    [-] awx.main.scheduler control task with impact of 1 can fit on instance group controlplane with 0 remaining forks and 0
2024-04-01 01:19:19,870 INFO     [-] awx.analytics.job_lifecycle projectupdate-11 controller node chosen
2024-04-01 01:19:19,870 INFO     [-] awx.analytics.job_lifecycle projectupdate-11 execution node chosen
2024-04-01 01:19:19,887 DEBUG    [-] awx.main.scheduler Submitting job project_update 11 (waiting) controlled by awx-01-task-55bc47d74f-fgppz to instance group controlplane and execution node awx-01-task-55bc47d74f-fgppz.
2024-04-01 01:19:20,005 INFO     [-] awx.analytics.job_lifecycle projectupdate-11 waiting
2024-04-01 01:19:20,015 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:19:20,028 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934360.0277655 seconds ago
2024-04-01 01:19:20,029 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.029445271999975375, 'start_task_seconds': 0.1378897039999174, 'process_running_tasks_seconds': 2.429999995001708e-06, 'process_pending_tasks_seconds': 0.13906754399999954, '_schedule_seconds': 0.2032116389999601, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 1, 'running_processed': 0, 'pending_processed': 1, 'tasks_blocked': 0, 'commit_seconds': 0.002755880355834961}
2024-04-01 01:19:21,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.01887989044189453 seconds after target
2024-04-01 01:19:21,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9801523685455322 seconds
2024-04-01 01:19:21,776 DEBUG    [-] awx.main.dispatch task 12ccfd0f-c22f-495b-b8b1-7279cb85cdb5 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:19:21,805 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:19:21,813 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:19:21,818 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934361.8177266 seconds ago
2024-04-01 01:19:21,819 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007036750000111169, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007064062000040394, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:19:22,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.001613616943359375 seconds after target
2024-04-01 01:19:22,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9972255229949951 seconds
2024-04-01 01:19:22,760 DEBUG    [-] awx.main.dispatch task 8055176d-cb28-40b1-99cf-a85de6f1a5bb starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:19:22,799 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:19:24,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.020760297775268555 seconds after target
2024-04-01 01:19:24,777 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9782624244689941 seconds
2024-04-01 01:19:24,779 DEBUG    [-] awx.main.dispatch task cf86b798-6f3e-44c9-bf19-64c26a629880 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:19:24,781 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:19:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.00112152099609375 seconds after target
2024-04-01 01:19:25,760 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.995485544204712 seconds
2024-04-01 01:19:25,761 DEBUG    [-] awx.main.dispatch task a451179c-d277-4a86-bf95-13dcd16cac99 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:19:31,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.022985219955444336 seconds after target
2024-04-01 01:19:31,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9741806983947754 seconds
2024-04-01 01:19:33,773 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.017817258834838867 seconds after target
2024-04-01 01:19:33,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.974336624145508 seconds
2024-04-01 01:19:39,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.02064371109008789 seconds after target
2024-04-01 01:19:39,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9769792556762695 seconds
2024-04-01 01:19:39,779 DEBUG    [-] awx.main.dispatch task 7d837d4c-f4c7-4b9a-b9c7-6ebf2f138b1b starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:19:39,814 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:19:39,869 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:19:39,880 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934379.8805852 seconds ago
2024-04-01 01:19:39,882 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.02771642899995186, 'start_task_seconds': 0, 'process_running_tasks_seconds': 5.485500003032939e-05, 'process_pending_tasks_seconds': 0.00010836299998118193, '_schedule_seconds': 0.05490135599995938, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0023145675659179688}
2024-04-01 01:19:41,773 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.017336606979370117 seconds after target
2024-04-01 01:19:41,773 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.9820358753204346 seconds
2024-04-01 01:19:41,775 DEBUG    [-] awx.main.dispatch task ae0fa56b-67e4-4938-a60e-829ec9e6a174 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:19:41,839 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:19:41,847 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:19:41,852 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934381.8524008 seconds ago
2024-04-01 01:19:41,854 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007630449999965094, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007649597000067843, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:19:45,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.019114017486572266 seconds after target
2024-04-01 01:19:45,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.019114017486572266 seconds after target
2024-04-01 01:19:45,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.977203845977783 seconds
2024-04-01 01:19:45,780 DEBUG    [-] awx.main.dispatch task a70cd277-6e3f-4fe3-a589-7060681e59bd starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:19:45,779 DEBUG    [-] awx.main.dispatch task 0dfd4683-a19c-48f2-81e8-be5000637242 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:19:45,832 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:19:45,835 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:19:15.817504+00:00
2024-04-01 01:19:53,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.01810431480407715 seconds after target
2024-04-01 01:19:53,790 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.965245485305786 seconds
2024-04-01 01:19:59,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.021810054779052734 seconds after target
2024-04-01 01:19:59,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9754040241241455 seconds
2024-04-01 01:19:59,781 DEBUG    [-] awx.main.dispatch task 3bd48339-8e60-43ce-9eb1-bba8f0850127 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:19:59,818 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:19:59,867 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:19:59,877 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934399.8771276 seconds ago
2024-04-01 01:19:59,879 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.023185727000054612, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.727399996478198e-05, 'process_pending_tasks_seconds': 4.468200006613188e-05, '_schedule_seconds': 0.048847459000057825, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0016627311706542969}
2024-04-01 01:20:01,783 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.02783370018005371 seconds after target
2024-04-01 01:20:01,784 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.9713127613067627 seconds
2024-04-01 01:20:01,785 DEBUG    [-] awx.main.dispatch task f6a0b993-ef3a-4476-be85-ddb61289b265 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:20:01,829 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:20:01,839 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:20:01,852 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934401.8506076 seconds ago
2024-04-01 01:20:01,856 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.010171216999992794, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.010197521999998571, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:20:05,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.020618915557861328 seconds after target
2024-04-01 01:20:05,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.976317644119263 seconds
2024-04-01 01:20:05,780 DEBUG    [-] awx.main.dispatch task ce6a4dab-99f5-4d39-bfeb-79888746b181 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:20:13,782 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02629852294921875 seconds after target
2024-04-01 01:20:13,792 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9635109901428223 seconds
2024-04-01 01:20:15,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.02051568031311035 seconds after target
2024-04-01 01:20:15,777 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9787018299102783 seconds
2024-04-01 01:20:15,777 DEBUG    [-] awx.main.dispatch task 19a1823f-1beb-47f8-9601-d677476d06cf starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:20:15,813 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:20:15,817 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:19:45.832722+00:00
2024-04-01 01:20:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0014333724975585938 seconds after target
2024-04-01 01:20:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.997652530670166 seconds
2024-04-01 01:20:16,759 DEBUG    [-] awx.main.dispatch task abb06f45-0fd6-48fa-a4ae-dce5f987dc57 starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:20:16,761 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:20:19,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.020267724990844727 seconds after target
2024-04-01 01:20:19,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9772570133209229 seconds
2024-04-01 01:20:19,779 DEBUG    [-] awx.main.dispatch task 7478c343-d10a-4335-b514-eba5f9dc7309 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:20:19,810 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:20:19,863 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:20:19,875 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934419.8752341 seconds ago
2024-04-01 01:20:19,876 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.023997812999937196, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.967400004967203e-05, 'process_pending_tasks_seconds': 8.504000004450063e-05, '_schedule_seconds': 0.05319150599996192, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.002172231674194336}
2024-04-01 01:20:21,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.018455982208251953 seconds after target
2024-04-01 01:20:21,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9807746410369873 seconds
2024-04-01 01:20:21,776 DEBUG    [-] awx.main.dispatch task 61ded62c-225d-41cb-8ad1-183618cbbc5c starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:20:21,816 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:20:21,823 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:20:21,828 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934421.8283286 seconds ago
2024-04-01 01:20:21,830 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007123757999920599, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007148899999947389, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:20:22,756 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.0007035732269287109 seconds after target
2024-04-01 01:20:22,757 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9980807304382324 seconds
2024-04-01 01:20:22,758 DEBUG    [-] awx.main.dispatch task 0fdcee20-4996-4941-9012-a9661169cf42 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:20:22,803 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:20:24,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.018267154693603516 seconds after target
2024-04-01 01:20:24,774 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9810729026794434 seconds
2024-04-01 01:20:24,776 DEBUG    [-] awx.main.dispatch task d7e1f494-d85e-4dcb-925f-8dba80b7850f starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:20:24,776 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:20:25,756 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.00047850608825683594 seconds after target
2024-04-01 01:20:25,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.996834754943848 seconds
2024-04-01 01:20:25,760 DEBUG    [-] awx.main.dispatch task e6a516be-f1a0-4b91-bbc9-82c1773bce99 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:20:31,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.02273869514465332 seconds after target
2024-04-01 01:20:31,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9749023914337158 seconds
2024-04-01 01:20:33,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.018827438354492188 seconds after target
2024-04-01 01:20:33,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.974324941635132 seconds
2024-04-01 01:20:39,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.022083282470703125 seconds after target
2024-04-01 01:20:39,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.975060224533081 seconds
2024-04-01 01:20:39,781 DEBUG    [-] awx.main.dispatch task a7b01736-5912-4cbb-bd07-28a2504296c6 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:20:39,839 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:20:39,888 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:20:39,899 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934439.8994472 seconds ago
2024-04-01 01:20:39,901 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.022380810000072415, 'start_task_seconds': 0, 'process_running_tasks_seconds': 4.7750000021551386e-05, 'process_pending_tasks_seconds': 5.141600001934421e-05, '_schedule_seconds': 0.049118276999934096, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0020685195922851562}
2024-04-01 01:20:41,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.01909613609313965 seconds after target
2024-04-01 01:20:41,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.9797749519348145 seconds
2024-04-01 01:20:41,777 DEBUG    [-] awx.main.dispatch task 8b327b10-37b4-4f70-9fc6-19ad19420c8a starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:20:41,819 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:20:41,826 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:20:41,830 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934441.830191 seconds ago
2024-04-01 01:20:41,831 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006580657000085921, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006598386999939976, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:20:45,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.021857023239135742 seconds after target
2024-04-01 01:20:45,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.021857023239135742 seconds after target
2024-04-01 01:20:45,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.974029302597046 seconds
2024-04-01 01:20:45,783 DEBUG    [-] awx.main.dispatch task 177d918a-1fa4-43dd-97e2-c7a697532ce2 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:20:45,782 DEBUG    [-] awx.main.dispatch task 74b1b439-34f8-42df-b98d-8247db0906c0 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:20:45,808 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:20:45,812 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:20:15.814260+00:00
2024-04-01 01:20:53,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.024121761322021484 seconds after target
2024-04-01 01:20:53,788 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.967725992202759 seconds
2024-04-01 01:20:59,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.020453929901123047 seconds after target
2024-04-01 01:20:59,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9764611721038818 seconds
2024-04-01 01:20:59,780 DEBUG    [-] awx.main.dispatch task b2c58a37-0109-4c63-a0bf-f87d2e1ec85d starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:20:59,847 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:20:59,904 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:20:59,915 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934459.915238 seconds ago
2024-04-01 01:20:59,917 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.030289301000038904, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.207599991128518e-05, 'process_pending_tasks_seconds': 6.978999999773805e-05, '_schedule_seconds': 0.05631309099999271, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0018877983093261719}
2024-04-01 01:21:01,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.018370389938354492 seconds after target
2024-04-01 01:21:01,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.9805262088775635 seconds
2024-04-01 01:21:01,776 DEBUG    [-] awx.main.dispatch task 201f7a43-796d-42d3-982c-c83ead61842f starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:21:01,816 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:21:01,824 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:21:01,829 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934461.8295257 seconds ago
2024-04-01 01:21:01,832 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007862775000035072, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.00789198600000418, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:21:05,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.021143674850463867 seconds after target
2024-04-01 01:21:05,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.976137638092041 seconds
2024-04-01 01:21:05,780 DEBUG    [-] awx.main.dispatch task 3fd80076-66f2-4280-ab10-4f0ccfbc1ae7 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:21:13,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02393817901611328 seconds after target
2024-04-01 01:21:13,788 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9676666259765625 seconds
2024-04-01 01:21:15,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.0196230411529541 seconds after target
2024-04-01 01:21:15,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9794251918792725 seconds
2024-04-01 01:21:15,777 DEBUG    [-] awx.main.dispatch task 827a4192-577c-44f4-9531-77febad2421a starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:21:15,826 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:21:15,828 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:20:45.809092+00:00
2024-04-01 01:21:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0010724067687988281 seconds after target
2024-04-01 01:21:16,757 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is gather_analytics in 1.9979569911956787 seconds
2024-04-01 01:21:16,759 DEBUG    [-] awx.main.dispatch task 113f8c2e-ee78-428f-91a4-7a5ec2e8ed84 starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:21:16,761 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:21:18,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found gather_analytics to run, 0.019510746002197266 seconds after target
2024-04-01 01:21:18,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 0.9795024394989014 seconds
2024-04-01 01:21:18,777 DEBUG    [-] awx.main.dispatch task c77b0874-08c4-4f73-b752-7d09211cfefc starting awx.main.tasks.system.gather_analytics(*[])
2024-04-01 01:21:19,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.0016853809356689453 seconds after target
2024-04-01 01:21:19,766 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9894213676452637 seconds
2024-04-01 01:21:19,767 DEBUG    [-] awx.main.dispatch task e64e8c28-ba0d-4601-a378-c4b9ca8dfda2 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:21:19,990 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:21:20,037 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:21:20,048 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934480.0485997 seconds ago
2024-04-01 01:21:20,050 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.020894924999993236, 'start_task_seconds': 0, 'process_running_tasks_seconds': 4.3524000034267374e-05, 'process_pending_tasks_seconds': 5.3051000008963456e-05, '_schedule_seconds': 0.046713689999933194, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0015971660614013672}
2024-04-01 01:21:21,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.019353628158569336 seconds after target
2024-04-01 01:21:21,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9793946743011475 seconds
2024-04-01 01:21:21,777 DEBUG    [-] awx.main.dispatch task 43dbed1c-30e4-4b06-b0e8-5315bf1e8a65 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:21:21,806 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:21:21,815 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:21:21,820 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934481.819978 seconds ago
2024-04-01 01:21:21,821 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008547840000005635, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008581262999996397, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:21:22,758 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.0022535324096679688 seconds after target
2024-04-01 01:21:22,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9964022636413574 seconds
2024-04-01 01:21:22,760 DEBUG    [-] awx.main.dispatch task abcca4f0-6044-410d-a2eb-056541ec1d71 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:21:22,795 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:21:24,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.019143342971801758 seconds after target
2024-04-01 01:21:24,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9779415130615234 seconds
2024-04-01 01:21:24,779 DEBUG    [-] awx.main.dispatch task 6efd2e27-ec57-4304-87e5-cdb5084ab61a starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:21:24,782 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:21:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0019295215606689453 seconds after target
2024-04-01 01:21:25,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.996673107147217 seconds
2024-04-01 01:21:25,760 DEBUG    [-] awx.main.dispatch task e482cdb2-6581-4433-9ca0-cfc476dc38a4 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:21:31,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.022418737411499023 seconds after target
2024-04-01 01:21:31,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9747354984283447 seconds
2024-04-01 01:21:33,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.01897406578063965 seconds after target
2024-04-01 01:21:33,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.973623275756836 seconds
2024-04-01 01:21:39,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.022275686264038086 seconds after target
2024-04-01 01:21:39,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9752790927886963 seconds
2024-04-01 01:21:39,781 DEBUG    [-] awx.main.dispatch task 59bf2039-af7b-4932-b811-f9b05a9542a9 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:21:39,827 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:21:39,877 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:21:39,886 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934499.886316 seconds ago
2024-04-01 01:21:39,887 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.025922987999933866, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.7130999999135383e-05, 'process_pending_tasks_seconds': 5.947300007846934e-05, '_schedule_seconds': 0.04964747899998656, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0016889572143554688}
2024-04-01 01:21:41,773 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.017073392868041992 seconds after target
2024-04-01 01:21:41,773 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.9819934368133545 seconds
2024-04-01 01:21:41,775 DEBUG    [-] awx.main.dispatch task 32b8e9de-1ed2-4a89-8bfc-65aeb227a882 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:21:41,804 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:21:41,812 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:21:41,817 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934501.8172157 seconds ago
2024-04-01 01:21:41,818 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007867067999995925, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007890523000014582, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:21:45,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.02257823944091797 seconds after target
2024-04-01 01:21:45,781 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.02257823944091797 seconds after target
2024-04-01 01:21:45,783 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.972722053527832 seconds
2024-04-01 01:21:45,784 DEBUG    [-] awx.main.dispatch task bd31e359-b133-480a-8582-144be4eef1a7 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:21:45,783 DEBUG    [-] awx.main.dispatch task f311b158-bf50-44fc-8dfe-0e696fbe821e starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:21:45,818 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:21:45,825 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:21:15.826398+00:00
2024-04-01 01:21:53,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.024785757064819336 seconds after target
2024-04-01 01:21:53,788 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.96733546257019 seconds
2024-04-01 01:21:59,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.023158788681030273 seconds after target
2024-04-01 01:21:59,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.97403883934021 seconds
2024-04-01 01:21:59,782 DEBUG    [-] awx.main.dispatch task f77379d9-ba06-474a-8a75-8f7967e647b4 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:21:59,831 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:21:59,886 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:21:59,897 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934519.8966038 seconds ago
2024-04-01 01:21:59,898 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.023648569999977553, 'start_task_seconds': 0, 'process_running_tasks_seconds': 4.5725999939350004e-05, 'process_pending_tasks_seconds': 5.984799997804657e-05, '_schedule_seconds': 0.05466343700004472, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0017859935760498047}
2024-04-01 01:22:01,772 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.016385316848754883 seconds after target
2024-04-01 01:22:01,773 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.982546091079712 seconds
2024-04-01 01:22:01,774 DEBUG    [-] awx.main.dispatch task a7794e74-7bf7-4f14-8d5e-39acfb84cfdc starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:22:01,815 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:22:01,824 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:22:01,829 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934521.8289082 seconds ago
2024-04-01 01:22:01,831 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007383045999972637, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007408145999988847, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:22:05,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.02083420753479004 seconds after target
2024-04-01 01:22:05,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.976397752761841 seconds
2024-04-01 01:22:05,780 DEBUG    [-] awx.main.dispatch task dc81f5dc-5227-4229-a9e8-2f87bee4816f starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:22:13,782 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.026453256607055664 seconds after target
2024-04-01 01:22:13,791 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9645729064941406 seconds
2024-04-01 01:22:15,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.021814823150634766 seconds after target
2024-04-01 01:22:15,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9771051406860352 seconds
2024-04-01 01:22:15,779 DEBUG    [-] awx.main.dispatch task 5456e997-bdbf-42c7-a826-0f0eba1c1999 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:22:15,816 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:22:15,820 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:21:45.818855+00:00
2024-04-01 01:22:16,758 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.002170085906982422 seconds after target
2024-04-01 01:22:16,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.9965529441833496 seconds
2024-04-01 01:22:16,760 DEBUG    [-] awx.main.dispatch task 0982801e-4b77-46e2-a9e6-b47fb07f57ad starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:22:16,763 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:22:19,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.0202329158782959 seconds after target
2024-04-01 01:22:19,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9771385192871094 seconds
2024-04-01 01:22:19,780 DEBUG    [-] awx.main.dispatch task ce0f0a3a-ccbf-4b62-bbf2-3e25491ddda3 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:22:19,804 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:22:19,852 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:22:19,861 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934539.8614311 seconds ago
2024-04-01 01:22:19,863 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.021771196000031523, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.8565999943784846e-05, 'process_pending_tasks_seconds': 4.3044999983976595e-05, '_schedule_seconds': 0.04653295399998569, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0019762516021728516}
2024-04-01 01:22:21,790 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.0348513126373291 seconds after target
2024-04-01 01:22:21,792 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9636719226837158 seconds
2024-04-01 01:22:21,793 DEBUG    [-] awx.main.dispatch task a9ab0b69-c246-4591-a875-e8bd753e6d3d starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:22:21,835 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:22:21,843 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:22:21,848 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934541.8481407 seconds ago
2024-04-01 01:22:21,850 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007510432000003675, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007565118000002258, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:22:22,758 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.002074718475341797 seconds after target
2024-04-01 01:22:22,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9967584609985352 seconds
2024-04-01 01:22:22,760 DEBUG    [-] awx.main.dispatch task db288277-5734-4e25-9500-e1e36fe6f238 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:22:22,799 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:22:24,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.01928424835205078 seconds after target
2024-04-01 01:22:24,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.979804515838623 seconds
2024-04-01 01:22:24,777 DEBUG    [-] awx.main.dispatch task 06fb017b-f61f-4c45-812c-8a22e64410a3 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:22:24,778 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:22:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0016942024230957031 seconds after target
2024-04-01 01:22:25,761 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.994540452957153 seconds
2024-04-01 01:22:25,762 DEBUG    [-] awx.main.dispatch task cb3a3ccc-c121-4e7c-8757-87c73bc7d2ce starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:22:31,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.021392345428466797 seconds after target
2024-04-01 01:22:31,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9762201309204102 seconds
2024-04-01 01:22:33,771 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.01600956916809082 seconds after target
2024-04-01 01:22:33,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.976098299026489 seconds
2024-04-01 01:22:39,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.022046566009521484 seconds after target
2024-04-01 01:22:39,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.974867820739746 seconds
2024-04-01 01:22:39,782 DEBUG    [-] awx.main.dispatch task d9e4aece-04e6-45d8-9a00-3b12a9f15ebf starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:22:39,821 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:22:39,877 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:22:39,889 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934559.8894067 seconds ago
2024-04-01 01:22:39,891 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.024387907000004816, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.819300002305681e-05, 'process_pending_tasks_seconds': 5.209800008287857e-05, '_schedule_seconds': 0.05462761199999022, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0031800270080566406}
2024-04-01 01:22:41,792 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.03649091720581055 seconds after target
2024-04-01 01:22:41,794 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.9619407653808594 seconds
2024-04-01 01:22:41,795 DEBUG    [-] awx.main.dispatch task b844b096-71a3-4643-bb4b-22489e406e69 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:22:41,833 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:22:41,842 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:22:41,847 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934561.846839 seconds ago
2024-04-01 01:22:41,848 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008075583000049846, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008106591000000662, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:22:45,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.02157282829284668 seconds after target
2024-04-01 01:22:45,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.02157282829284668 seconds after target
2024-04-01 01:22:45,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.974050283432007 seconds
2024-04-01 01:22:45,783 DEBUG    [-] awx.main.dispatch task 6eb5bc79-c484-4078-9b27-fd5134c71dce starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:22:45,782 DEBUG    [-] awx.main.dispatch task c4276b66-5126-4921-9b26-1e829f8e3aa8 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:22:45,812 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:22:45,815 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:22:15.817339+00:00
2024-04-01 01:22:53,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02364325523376465 seconds after target
2024-04-01 01:22:53,789 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.966877460479736 seconds
2024-04-01 01:22:59,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.02333998680114746 seconds after target
2024-04-01 01:22:59,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9739360809326172 seconds
2024-04-01 01:22:59,783 DEBUG    [-] awx.main.dispatch task e00ea801-4208-42ff-aa8d-69913fd9f741 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:22:59,827 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:22:59,876 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:22:59,885 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934579.8853767 seconds ago
2024-04-01 01:22:59,887 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.02164702999994006, 'start_task_seconds': 0, 'process_running_tasks_seconds': 6.21039999941786e-05, 'process_pending_tasks_seconds': 8.641199997327931e-05, '_schedule_seconds': 0.04778720800004521, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0019071102142333984}
2024-04-01 01:23:01,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.02138066291809082 seconds after target
2024-04-01 01:23:01,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.9775097370147705 seconds
2024-04-01 01:23:01,780 DEBUG    [-] awx.main.dispatch task fde6d264-adac-4505-bc40-568814364862 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:23:01,812 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:23:01,821 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:23:01,827 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934581.8266993 seconds ago
2024-04-01 01:23:01,829 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008268071999964377, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.00829505000001518, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:23:05,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.022437095642089844 seconds after target
2024-04-01 01:23:05,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.97475266456604 seconds
2024-04-01 01:23:05,781 DEBUG    [-] awx.main.dispatch task 43ae41de-b32e-4bfa-84a8-c1aec19c498e starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:23:13,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02432727813720703 seconds after target
2024-04-01 01:23:13,789 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9664623737335205 seconds
2024-04-01 01:23:15,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.0238955020904541 seconds after target
2024-04-01 01:23:15,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9754929542541504 seconds
2024-04-01 01:23:15,781 DEBUG    [-] awx.main.dispatch task cc431f50-15f5-4419-ba64-799fa37bdafc starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:23:15,814 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:23:15,818 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:22:45.812604+00:00
2024-04-01 01:23:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0014510154724121094 seconds after target
2024-04-01 01:23:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.997330904006958 seconds
2024-04-01 01:23:16,759 DEBUG    [-] awx.main.dispatch task 01e6356c-c764-49e2-ae40-37feb8d481ed starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:23:16,762 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:23:19,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.019736051559448242 seconds after target
2024-04-01 01:23:19,778 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9777953624725342 seconds
2024-04-01 01:23:19,778 DEBUG    [-] awx.main.dispatch task d80c6124-b344-484f-93e2-b0130b7de130 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:23:19,815 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:23:19,864 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:23:19,874 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934599.8745666 seconds ago
2024-04-01 01:23:19,876 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.02241566200007128, 'start_task_seconds': 0, 'process_running_tasks_seconds': 5.218499995862658e-05, 'process_pending_tasks_seconds': 5.469800009905157e-05, '_schedule_seconds': 0.04822980699998425, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0019958019256591797}
2024-04-01 01:23:21,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.019640445709228516 seconds after target
2024-04-01 01:23:21,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9794163703918457 seconds
2024-04-01 01:23:21,777 DEBUG    [-] awx.main.dispatch task 6e411877-089b-417d-9d21-c30bbfbd55c8 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:23:21,813 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:23:21,821 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:23:21,825 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934601.8256311 seconds ago
2024-04-01 01:23:21,828 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007218522000016492, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007250188999933016, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:23:22,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.0016078948974609375 seconds after target
2024-04-01 01:23:22,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9974205493927002 seconds
2024-04-01 01:23:22,759 DEBUG    [-] awx.main.dispatch task 3f8734b4-b5a7-4e22-8dc1-446d84b8d116 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:23:22,794 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:23:24,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.021141529083251953 seconds after target
2024-04-01 01:23:24,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.976036548614502 seconds
2024-04-01 01:23:24,781 DEBUG    [-] awx.main.dispatch task 5f13ba1c-5b5d-4f5c-a861-34caa9bbfea9 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:23:24,781 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:23:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0014805793762207031 seconds after target
2024-04-01 01:23:25,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.997645139694214 seconds
2024-04-01 01:23:25,759 DEBUG    [-] awx.main.dispatch task eb31a7cb-174e-4f3f-8b60-dd08b4260040 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:23:31,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.021591901779174805 seconds after target
2024-04-01 01:23:31,786 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9695751667022705 seconds
2024-04-01 01:23:33,772 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.016461610794067383 seconds after target
2024-04-01 01:23:33,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.976020812988281 seconds
2024-04-01 01:23:39,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.022785186767578125 seconds after target
2024-04-01 01:23:39,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9747405052185059 seconds
2024-04-01 01:23:39,782 DEBUG    [-] awx.main.dispatch task 3a489e35-b975-4b3f-a92e-85afc10986fb starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:23:39,825 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:23:39,872 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:23:39,883 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934619.8829827 seconds ago
2024-04-01 01:23:39,884 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.021156043000019054, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.2320999935109285e-05, 'process_pending_tasks_seconds': 4.570600003717118e-05, '_schedule_seconds': 0.04655755399994632, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0024809837341308594}
2024-04-01 01:23:41,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.018392086029052734 seconds after target
2024-04-01 01:23:41,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.980931282043457 seconds
2024-04-01 01:23:41,776 DEBUG    [-] awx.main.dispatch task 87d59e8d-1095-4e71-babe-583424d9ef0e starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:23:41,802 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:23:41,810 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:23:41,814 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934621.8145032 seconds ago
2024-04-01 01:23:41,816 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007581538999943405, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007602193000025181, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:23:45,773 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.017838716506958008 seconds after target
2024-04-01 01:23:45,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.017838716506958008 seconds after target
2024-04-01 01:23:45,777 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.978784799575806 seconds
2024-04-01 01:23:45,778 DEBUG    [-] awx.main.dispatch task 8ae60739-5682-4651-ab84-04c18e7c64b4 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:23:45,804 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:23:45,806 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:23:15.815100+00:00
2024-04-01 01:23:45,777 DEBUG    [-] awx.main.dispatch task e50dbb66-d759-47dc-a7cb-d37a0c854017 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:23:53,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02256035804748535 seconds after target
2024-04-01 01:23:53,788 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.967287540435791 seconds
2024-04-01 01:23:59,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.023540735244750977 seconds after target
2024-04-01 01:23:59,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9739162921905518 seconds
2024-04-01 01:23:59,783 DEBUG    [-] awx.main.dispatch task 369ecaf0-f3d3-43f4-b015-3b27617e1007 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:23:59,842 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:23:59,890 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:23:59,901 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934639.9015088 seconds ago
2024-04-01 01:23:59,903 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.02229292100003022, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.775000004679896e-05, 'process_pending_tasks_seconds': 4.5277000026544556e-05, '_schedule_seconds': 0.048027515000057974, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.001834869384765625}
2024-04-01 01:24:01,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.022301912307739258 seconds after target
2024-04-01 01:24:01,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.9768459796905518 seconds
2024-04-01 01:24:01,780 DEBUG    [-] awx.main.dispatch task d1f54ae1-775f-4d7a-9069-f9f72797bd6a starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:24:01,833 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:24:01,842 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:24:01,848 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934641.847919 seconds ago
2024-04-01 01:24:01,850 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008826349000059963, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008850107999933243, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:24:05,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.020622968673706055 seconds after target
2024-04-01 01:24:05,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.97666335105896 seconds
2024-04-01 01:24:05,780 DEBUG    [-] awx.main.dispatch task 133286d0-ba20-4ddf-a505-c613915c4d66 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:24:13,781 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.02522563934326172 seconds after target
2024-04-01 01:24:13,790 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9659295082092285 seconds
2024-04-01 01:24:15,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.01976156234741211 seconds after target
2024-04-01 01:24:15,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9792747497558594 seconds
2024-04-01 01:24:15,777 DEBUG    [-] awx.main.dispatch task 6b429d4a-9851-402f-9950-ed61867ce886 starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:24:15,827 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:24:15,830 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:23:45.804556+00:00
2024-04-01 01:24:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0015683174133300781 seconds after target
2024-04-01 01:24:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.99735689163208 seconds
2024-04-01 01:24:16,759 DEBUG    [-] awx.main.dispatch task 7fbce862-5b4f-44ab-af18-92c507c10f44 starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:24:16,762 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:24:19,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.021672487258911133 seconds after target
2024-04-01 01:24:19,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9753808975219727 seconds
2024-04-01 01:24:19,781 DEBUG    [-] awx.main.dispatch task 5c8c8431-1083-4c45-9885-adef21d02b9c starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:24:19,805 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:24:19,849 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:24:19,859 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934659.8589435 seconds ago
2024-04-01 01:24:19,861 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.019795173000034083, 'start_task_seconds': 0, 'process_running_tasks_seconds': 4.556999999749678e-05, 'process_pending_tasks_seconds': 5.196199992951733e-05, '_schedule_seconds': 0.042765377000023364, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0016143321990966797}
2024-04-01 01:24:21,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.019048690795898438 seconds after target
2024-04-01 01:24:21,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9799561500549316 seconds
2024-04-01 01:24:21,777 DEBUG    [-] awx.main.dispatch task de6c68fd-ea10-4ac5-a915-cf5fdb22b941 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:24:21,803 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:24:21,810 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:24:21,815 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934661.8146617 seconds ago
2024-04-01 01:24:21,816 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.00656323699990935, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006588088999933461, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:24:22,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.001682281494140625 seconds after target
2024-04-01 01:24:22,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.997328281402588 seconds
2024-04-01 01:24:22,759 DEBUG    [-] awx.main.dispatch task 1c84a819-1c6b-4f35-85a5-b8ca20f51954 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:24:22,788 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:24:24,772 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.016870737075805664 seconds after target
2024-04-01 01:24:24,773 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9821839332580566 seconds
2024-04-01 01:24:24,774 DEBUG    [-] awx.main.dispatch task b7a54f0c-2d92-4a74-9da5-bcb610d0582a starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:24:24,778 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:24:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0015485286712646484 seconds after target
2024-04-01 01:24:25,760 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.995756149291992 seconds
2024-04-01 01:24:25,760 DEBUG    [-] awx.main.dispatch task 024a2783-7e0d-4365-89b1-4cae764adf24 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:24:31,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.022158145904541016 seconds after target
2024-04-01 01:24:31,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9753921031951904 seconds
2024-04-01 01:24:33,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.020038366317749023 seconds after target
2024-04-01 01:24:33,783 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.97259783744812 seconds
2024-04-01 01:24:39,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.023351192474365234 seconds after target
2024-04-01 01:24:39,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9736499786376953 seconds
2024-04-01 01:24:39,782 DEBUG    [-] awx.main.dispatch task 5f858249-514b-4e2a-be3a-ecf8bf1d7067 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:24:39,832 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:24:39,878 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:24:39,888 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934679.8885138 seconds ago
2024-04-01 01:24:39,890 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.020328198000015618, 'start_task_seconds': 0, 'process_running_tasks_seconds': 6.546500003423716e-05, 'process_pending_tasks_seconds': 4.838299992115935e-05, '_schedule_seconds': 0.04536189300006299, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0017795562744140625}
2024-04-01 01:24:41,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.01871800422668457 seconds after target
2024-04-01 01:24:41,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.980333089828491 seconds
2024-04-01 01:24:41,776 DEBUG    [-] awx.main.dispatch task d1ae81d7-6309-4eec-a2f8-f4997ba83928 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:24:41,822 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:24:41,829 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:24:41,834 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934681.8335493 seconds ago
2024-04-01 01:24:41,835 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.0066498090000095544, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006670778000056998, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:24:45,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.020696401596069336 seconds after target
2024-04-01 01:24:45,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.020696401596069336 seconds after target
2024-04-01 01:24:45,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.975839376449585 seconds
2024-04-01 01:24:45,781 DEBUG    [-] awx.main.dispatch task 791beb6f-a81a-4039-bc51-c1439e3ce301 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:24:45,781 DEBUG    [-] awx.main.dispatch task f9c53e06-edc8-4880-aa87-8575eff5b8fd starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:24:45,810 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:24:45,813 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:24:15.827530+00:00
2024-04-01 01:24:53,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.024684429168701172 seconds after target
2024-04-01 01:24:53,970 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.785335302352905 seconds
2024-04-01 01:24:59,784 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.028308868408203125 seconds after target
2024-04-01 01:24:59,787 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9683396816253662 seconds
2024-04-01 01:24:59,788 DEBUG    [-] awx.main.dispatch task 926efd29-2819-415b-930e-fc38a48c4c8f starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:24:59,842 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:24:59,893 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:24:59,906 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934699.905791 seconds ago
2024-04-01 01:24:59,907 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.023907936000000518, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.483199998299824e-05, 'process_pending_tasks_seconds': 4.525099996044446e-05, '_schedule_seconds': 0.050777730000049814, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0017430782318115234}
2024-04-01 01:25:01,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.023939132690429688 seconds after target
2024-04-01 01:25:01,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.9745078086853027 seconds
2024-04-01 01:25:01,782 DEBUG    [-] awx.main.dispatch task 255f8745-90ab-4898-8527-5e6fd4eaf4f5 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:25:01,839 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:25:01,849 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:25:01,857 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934701.856953 seconds ago
2024-04-01 01:25:01,860 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.00795615499998803, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007984679000060169, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:25:05,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.022563695907592773 seconds after target
2024-04-01 01:25:05,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.973940849304199 seconds
2024-04-01 01:25:05,783 DEBUG    [-] awx.main.dispatch task 4e8b9b8e-4ff8-4f9e-af8c-4069624a18ca starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:25:13,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.025025129318237305 seconds after target
2024-04-01 01:25:13,789 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9664571285247803 seconds
2024-04-01 01:25:15,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.01993846893310547 seconds after target
2024-04-01 01:25:15,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9790582656860352 seconds
2024-04-01 01:25:15,777 DEBUG    [-] awx.main.dispatch task 77484989-53ec-459c-837f-e9390f04686b starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:25:15,826 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:25:15,829 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:24:45.810763+00:00
2024-04-01 01:25:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0016164779663085938 seconds after target
2024-04-01 01:25:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 2.997264862060547 seconds
2024-04-01 01:25:16,759 DEBUG    [-] awx.main.dispatch task 6ccefb23-19d3-4c73-a763-531a46c0cb9d starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:25:16,762 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:25:19,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.019924402236938477 seconds after target
2024-04-01 01:25:19,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.976731777191162 seconds
2024-04-01 01:25:19,780 DEBUG    [-] awx.main.dispatch task 07d6af57-e2b5-49e4-80f3-1268ec375256 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:25:19,809 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:25:19,854 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:25:19,865 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934719.8647316 seconds ago
2024-04-01 01:25:19,866 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.020969293000007383, 'start_task_seconds': 0, 'process_running_tasks_seconds': 4.911799999263167e-05, 'process_pending_tasks_seconds': 4.26550000156567e-05, '_schedule_seconds': 0.04484513800002787, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0016086101531982422}
2024-04-01 01:25:21,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.019047260284423828 seconds after target
2024-04-01 01:25:21,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9798297882080078 seconds
2024-04-01 01:25:21,777 DEBUG    [-] awx.main.dispatch task 8ad51e8e-6fc6-4661-a77c-4cd32d55e9ac starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:25:21,803 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:25:21,810 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:25:21,815 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934721.8151677 seconds ago
2024-04-01 01:25:21,816 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006545231000018248, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006568120999986604, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:25:22,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.0011043548583984375 seconds after target
2024-04-01 01:25:22,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.997786045074463 seconds
2024-04-01 01:25:22,758 DEBUG    [-] awx.main.dispatch task 073082bd-39f6-45d6-b7e9-4e70b61a0079 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:25:22,791 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:25:24,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.021158218383789062 seconds after target
2024-04-01 01:25:24,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9769048690795898 seconds
2024-04-01 01:25:24,780 DEBUG    [-] awx.main.dispatch task deeb56d7-104e-4db1-8e27-cef651737654 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:25:24,781 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:25:25,758 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.002594470977783203 seconds after target
2024-04-01 01:25:25,759 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.995954990386963 seconds
2024-04-01 01:25:25,760 DEBUG    [-] awx.main.dispatch task 16826313-53c5-4e7c-9e4f-f345cb754fcb starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:25:31,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.023591041564941406 seconds after target
2024-04-01 01:25:31,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9736578464508057 seconds
2024-04-01 01:25:33,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.018433332443237305 seconds after target
2024-04-01 01:25:33,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.97443413734436 seconds
2024-04-01 01:25:39,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.0201261043548584 seconds after target
2024-04-01 01:25:39,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9768946170806885 seconds
2024-04-01 01:25:39,779 DEBUG    [-] awx.main.dispatch task ba6d1357-67c4-4102-94e3-68187830cba0 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:25:39,817 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:25:39,865 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:25:39,877 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934739.87758 seconds ago
2024-04-01 01:25:39,879 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.021487283999931606, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.636600013123825e-05, 'process_pending_tasks_seconds': 6.140100003904081e-05, '_schedule_seconds': 0.04765178599996034, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0017077922821044922}
2024-04-01 01:25:41,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.020138978958129883 seconds after target
2024-04-01 01:25:41,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.978937864303589 seconds
2024-04-01 01:25:41,778 DEBUG    [-] awx.main.dispatch task b5903104-bc50-406d-b7ff-5d4eaffa1af5 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:25:41,813 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:25:41,821 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:25:41,825 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934741.8252292 seconds ago
2024-04-01 01:25:41,827 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006806470999890735, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.006830058000105055, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:25:45,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.020436763763427734 seconds after target
2024-04-01 01:25:45,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.020436763763427734 seconds after target
2024-04-01 01:25:45,780 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.975658893585205 seconds
2024-04-01 01:25:45,781 DEBUG    [-] awx.main.dispatch task 1ac7abf0-c116-44f2-9f8d-20d79a91c7c8 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:25:45,780 DEBUG    [-] awx.main.dispatch task 618ea483-8d79-40de-8f58-d04f8d4e6d8a starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:25:45,805 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:25:45,808 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:25:15.827260+00:00
2024-04-01 01:25:53,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.024500370025634766 seconds after target
2024-04-01 01:25:53,789 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.9669108390808105 seconds
2024-04-01 01:25:59,777 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.021729230880737305 seconds after target
2024-04-01 01:25:59,785 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9705820083618164 seconds
2024-04-01 01:25:59,786 DEBUG    [-] awx.main.dispatch task 86de6634-8563-4e8c-b666-d677cb377aa7 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:25:59,831 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:25:59,875 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:25:59,884 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934759.88452 seconds ago
2024-04-01 01:25:59,886 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.020197884999788585, 'start_task_seconds': 0, 'process_running_tasks_seconds': 3.467400006229582e-05, 'process_pending_tasks_seconds': 4.1655999893919216e-05, '_schedule_seconds': 0.04387519199985945, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 1, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0015401840209960938}
2024-04-01 01:26:01,771 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.01563429832458496 seconds after target
2024-04-01 01:26:01,772 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 3.983579397201538 seconds
2024-04-01 01:26:01,773 DEBUG    [-] awx.main.dispatch task 680295d4-8fb8-4b31-9ff8-a09272ee497b starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:26:01,803 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:26:01,812 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:26:01,817 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934761.8172703 seconds ago
2024-04-01 01:26:01,819 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.008157164000067496, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.008181476000117982, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:26:05,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.020718097686767578 seconds after target
2024-04-01 01:26:05,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 7.976769685745239 seconds
2024-04-01 01:26:05,780 DEBUG    [-] awx.main.dispatch task 939b22cb-6016-42e3-ab11-e66b316c77d6 starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:26:13,780 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.024067163467407227 seconds after target
2024-04-01 01:26:13,789 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 1.9661355018615723 seconds
2024-04-01 01:26:15,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found tower_scheduler to run, 0.01907038688659668 seconds after target
2024-04-01 01:26:15,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is cluster_heartbeat in 0.9802184104919434 seconds
2024-04-01 01:26:15,777 DEBUG    [-] awx.main.dispatch task 049b9600-34d8-43a3-ad1f-758af7fbb3bd starting awx.main.tasks.system.awx_periodic_scheduler(*[])
2024-04-01 01:26:15,826 DEBUG    [-] awx.main.tasks.system Starting periodic scheduler
2024-04-01 01:26:15,829 DEBUG    [-] awx.main.tasks.system Last scheduler run was: 2024-04-01 01:25:45.806146+00:00
2024-04-01 01:26:16,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found cluster_heartbeat to run, 0.0017879009246826172 seconds after target
2024-04-01 01:26:16,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is gather_analytics in 1.9973020553588867 seconds
2024-04-01 01:26:16,760 DEBUG    [-] awx.main.dispatch task 07fbe5c8-6e9a-410e-a172-729d683a4d9b starting awx.main.tasks.system.cluster_node_heartbeat(*[])
2024-04-01 01:26:16,993 DEBUG    [-] awx.main.tasks.system Cluster node heartbeat task.
2024-04-01 01:26:17,217 ERROR    [-] awx.main.dispatch project_update 11 (failed) is no longer waiting; reaping
2024-04-01 01:26:18,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found gather_analytics to run, 0.01920795440673828 seconds after target
2024-04-01 01:26:18,775 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 0.979964017868042 seconds
2024-04-01 01:26:18,777 DEBUG    [-] awx.main.dispatch task d60b0da1-3af0-4cdd-9b7a-8beb28ba1b29 starting awx.main.tasks.system.gather_analytics(*[])
2024-04-01 01:26:19,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.0014290809631347656 seconds after target
2024-04-01 01:26:19,760 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.995455026626587 seconds
2024-04-01 01:26:19,761 DEBUG    [-] awx.main.dispatch task 91d3d044-4fad-458b-b9bb-e5c7aa969e7a starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:26:19,788 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:26:19,820 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:26:19,830 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934779.8303401 seconds ago
2024-04-01 01:26:19,832 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006673884999827351, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0, 'process_pending_tasks_seconds': 0, '_schedule_seconds': 0.031775921999951606, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 0, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0017998218536376953}
2024-04-01 01:26:21,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.01991868019104004 seconds after target
2024-04-01 01:26:21,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is k8s_reaper in 0.9794597625732422 seconds
2024-04-01 01:26:21,777 DEBUG    [-] awx.main.dispatch task 43c92f00-65a9-4039-92fd-180de85552c7 starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:26:21,804 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:26:21,811 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:26:21,816 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934781.8162403 seconds ago
2024-04-01 01:26:21,817 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.006773215000066557, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.00679689799994776, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}
2024-04-01 01:26:22,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found k8s_reaper to run, 0.0014030933380126953 seconds after target
2024-04-01 01:26:22,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is receptor_reaper in 1.9979100227355957 seconds
2024-04-01 01:26:22,759 DEBUG    [-] awx.main.dispatch task dce5b3bc-aa7d-4cb1-b0f3-585aec94ae20 starting awx.main.tasks.system.awx_k8s_reaper(*[])
2024-04-01 01:26:22,802 DEBUG    [-] awx.main.tasks.system Checking for orphaned k8s pods for default-2.
2024-04-01 01:26:24,774 DEBUG    [-] awx.main.dispatch.periodic scheduler found receptor_reaper to run, 0.01824188232421875 seconds after target
2024-04-01 01:26:24,776 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is send_subsystem_metrics in 0.9793453216552734 seconds
2024-04-01 01:26:24,777 DEBUG    [-] awx.main.dispatch task b2873373-d2ad-4c48-86e4-f0b51b027865 starting awx.main.tasks.system.awx_receptor_workunit_reaper(*[])
2024-04-01 01:26:24,781 DEBUG    [-] awx.main.tasks.system Checking for unreleased receptor work units
2024-04-01 01:26:25,757 DEBUG    [-] awx.main.dispatch.periodic scheduler found send_subsystem_metrics to run, 0.0013968944549560547 seconds after target
2024-04-01 01:26:25,758 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is pool_cleanup in 5.997838497161865 seconds
2024-04-01 01:26:25,758 DEBUG    [-] awx.main.dispatch task c589120c-3f9e-4604-8c62-430015eac50c starting awx.main.analytics.analytics_tasks.send_subsystem_metrics(*[])
2024-04-01 01:26:31,779 DEBUG    [-] awx.main.dispatch.periodic scheduler found pool_cleanup to run, 0.023319244384765625 seconds after target
2024-04-01 01:26:31,782 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is metrics_gather in 1.9737317562103271 seconds
2024-04-01 01:26:33,775 DEBUG    [-] awx.main.dispatch.periodic scheduler found metrics_gather to run, 0.019345998764038086 seconds after target
2024-04-01 01:26:33,781 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is task_manager in 5.974039554595947 seconds
2024-04-01 01:26:39,776 DEBUG    [-] awx.main.dispatch.periodic scheduler found task_manager to run, 0.020751237869262695 seconds after target
2024-04-01 01:26:39,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is dependency_manager in 1.9768543243408203 seconds
2024-04-01 01:26:39,780 DEBUG    [-] awx.main.dispatch task 8e1688a0-fd26-44ef-a714-599029c46a47 starting awx.main.scheduler.tasks.task_manager(*[])
2024-04-01 01:26:39,825 DEBUG    [-] awx.main.scheduler Starting task_manager Scheduler
2024-04-01 01:26:39,862 DEBUG    [-] awx.main.scheduler Commiting task_manager Scheduler changes
2024-04-01 01:26:39,874 DEBUG    [-] awx.main.scheduler recording task_manager metrics, last recorded 1711934799.8737674 seconds ago
2024-04-01 01:26:39,875 DEBUG    [-] awx.main.scheduler Finished task_manager Scheduler, timing data:
{'get_tasks_seconds': 0.007647202999805813, 'start_task_seconds': 0, 'process_running_tasks_seconds': 0, 'process_pending_tasks_seconds': 0, '_schedule_seconds': 0.03659905000017716, '_schedule_calls': 0, 'recorded_timestamp': 0, 'tasks_started': 0, 'running_processed': 0, 'pending_processed': 0, 'tasks_blocked': 0, 'commit_seconds': 0.0018279552459716797}
2024-04-01 01:26:41,778 DEBUG    [-] awx.main.dispatch.periodic scheduler found dependency_manager to run, 0.022867441177368164 seconds after target
2024-04-01 01:26:41,779 DEBUG    [-] awx.main.dispatch.periodic Scheduler next run is tower_scheduler in 3.976327419281006 seconds
2024-04-01 01:26:41,780 DEBUG    [-] awx.main.dispatch task 1f829113-22d2-48ef-9f07-fd3e6b1791ac starting awx.main.scheduler.tasks.dependency_manager(*[])
2024-04-01 01:26:41,818 DEBUG    [-] awx.main.scheduler Starting dependency_manager Scheduler
2024-04-01 01:26:41,825 DEBUG    [-] awx.main.scheduler Commiting dependency_manager Scheduler changes
2024-04-01 01:26:41,830 DEBUG    [-] awx.main.scheduler recording dependency_manager metrics, last recorded 1711934801.8302848 seconds ago
2024-04-01 01:26:41,831 DEBUG    [-] awx.main.scheduler Finished dependency_manager Scheduler, timing data:
{'get_tasks_seconds': 0.0071662110001398105, 'generate_dependencies_seconds': 0, '_schedule_seconds': 0.007186550000142233, '_schedule_calls': 0, 'recorded_timestamp': 0, 'pending_processed': 0}

I don't know what could be happening.

moreirodamian commented 7 months ago

in the web browser console I see the following error:

connectJobSocket.js:42 WebSocket connection to 'wss://URL/websocket/' failed: WebSocket is closed before the connection is established.

Uncaught DOMException: Failed to execute 'send' on 'WebSocket': Still in CONNECTING state.
    at WebSocket.onopen (https://URL/static/js/main.6feb1356.js:2:3449283)

I replaced the AWX URL with URL.

But I don't think this error has anything to do with it.

fosterseth commented 7 months ago

in your awx-task container log output I don't see any errors, but I also don't see any logs related to job running. Do these logs capture the window of time where you launched the demo job?