2025-10-12 00:07:03.919903 | Job console starting... 2025-10-12 00:07:03.932969 | Updating repositories 2025-10-12 00:07:04.148021 | Preparing job workspace 2025-10-12 00:07:08.604983 | Running Ansible setup... 2025-10-12 00:07:14.760432 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-12 00:07:15.380900 | 2025-10-12 00:07:15.381014 | PLAY [localhost] 2025-10-12 00:07:15.390540 | 2025-10-12 00:07:15.390611 | TASK [Gathering Facts] 2025-10-12 00:07:16.297372 | localhost | ok 2025-10-12 00:07:16.326441 | 2025-10-12 00:07:16.326620 | TASK [Setup log path fact] 2025-10-12 00:07:16.346626 | localhost | ok 2025-10-12 00:07:16.364117 | 2025-10-12 00:07:16.364205 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-12 00:07:16.404656 | localhost | ok 2025-10-12 00:07:16.415761 | 2025-10-12 00:07:16.415856 | TASK [emit-job-header : Print job information] 2025-10-12 00:07:16.466657 | # Job Information 2025-10-12 00:07:16.467440 | Ansible Version: 2.15.12 2025-10-12 00:07:16.467497 | Job: ansible-test-sanity-docker-milestone 2025-10-12 00:07:16.467527 | Pipeline: periodic 2025-10-12 00:07:16.467553 | Executor: ze02.softwarefactory-project.io 2025-10-12 00:07:16.467578 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-12 00:07:16.467607 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/af7/ansible/af7dfd72b9244cb7887c8c03c84b8d37/ 2025-10-12 00:07:16.467633 | Event ID: 6345c3b581e843d6946dd6bca9ffe8f8 2025-10-12 00:07:16.473264 | 2025-10-12 00:07:16.473349 | LOOP [emit-job-header : Print node information] 2025-10-12 00:07:16.576017 | localhost | ok: 2025-10-12 00:07:16.576188 | localhost | # Node Information 2025-10-12 00:07:16.576215 | localhost | Inventory Hostname: controller 2025-10-12 00:07:16.576236 | localhost | Hostname: ip-172-16-179-62 2025-10-12 00:07:16.576254 | localhost | Username: zuul-worker 2025-10-12 00:07:16.576275 | localhost | Distro: Fedora 37 2025-10-12 00:07:16.576294 | localhost | Provider: ansible-us-east-2 2025-10-12 00:07:16.576311 | localhost | Region: us-east-2 2025-10-12 00:07:16.576328 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-12 00:07:16.576344 | localhost | Product Name: t3.small 2025-10-12 00:07:16.576361 | localhost | Interface IP: 3.143.240.82 2025-10-12 00:07:16.589879 | 2025-10-12 00:07:16.590024 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-12 00:07:16.942404 | localhost -> localhost | changed 2025-10-12 00:07:16.947926 | 2025-10-12 00:07:16.947997 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-12 00:07:17.716414 | localhost -> localhost | changed 2025-10-12 00:07:17.744429 | 2025-10-12 00:07:17.744491 | PLAY [all:!appliance*] 2025-10-12 00:07:17.765637 | 2025-10-12 00:07:17.765733 | TASK [include_role : start-zuul-console] 2025-10-12 00:07:17.784285 | controller | ok 2025-10-12 00:07:17.798645 | 2025-10-12 00:07:17.798745 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-12 00:07:18.456307 | controller | ok 2025-10-12 00:07:18.469107 | 2025-10-12 00:07:18.469305 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-12 00:07:21.868526 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-12 00:07:21.878265 | 2025-10-12 00:07:21.878371 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-12 00:07:22.036030 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.050895 | 2025-10-12 00:07:22.051075 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-12 00:07:22.078385 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.092572 | 2025-10-12 00:07:22.092775 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-12 00:07:22.120944 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.135932 | 2025-10-12 00:07:22.136090 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-12 00:07:22.173972 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.189409 | 2025-10-12 00:07:22.189626 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-12 00:07:22.226918 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.239603 | 2025-10-12 00:07:22.239780 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-12 00:07:22.266608 | controller | skipping: Conditional result was False 2025-10-12 00:07:22.290303 | 2025-10-12 00:07:22.290459 | TASK [Disable Fedora Modular] 2025-10-12 00:07:23.003198 | controller | changed 2025-10-12 00:07:23.009181 | 2025-10-12 00:07:23.009246 | TASK [Enable EPEL] 2025-10-12 00:07:23.033368 | controller | skipping: Conditional result was False 2025-10-12 00:07:23.040584 | 2025-10-12 00:07:23.040681 | TASK [Register the RHEL node] 2025-10-12 00:07:23.187004 | 2025-10-12 00:07:23.187164 | TASK [Show the subscription-manager status] 2025-10-12 00:07:23.404619 | controller | skipping: Conditional result was False 2025-10-12 00:07:23.417327 | 2025-10-12 00:07:23.417479 | TASK [Enable EPEL on RHEL] 2025-10-12 00:07:23.572542 | controller | skipping: Conditional result was False 2025-10-12 00:07:23.585548 | 2025-10-12 00:07:23.585880 | TASK [Install git and tox] 2025-10-12 00:08:54.583924 | controller | changed 2025-10-12 00:08:54.597187 | 2025-10-12 00:08:54.597324 | TASK [include_role : prepare-workspace] 2025-10-12 00:08:54.638459 | controller | ok 2025-10-12 00:08:54.681124 | 2025-10-12 00:08:54.681216 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-12 00:08:55.211376 | controller | ok 2025-10-12 00:08:55.230445 | 2025-10-12 00:08:55.230583 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-12 00:09:09.662526 | controller | Output suppressed because no_log was given 2025-10-12 00:09:09.681188 | 2025-10-12 00:09:09.681322 | TASK [include_role : prepare-workspace-openshift] 2025-10-12 00:09:09.697908 | controller | skipping: Conditional result was False 2025-10-12 00:09:09.746577 | 2025-10-12 00:09:09.746701 | PLAY [all:!appliance] 2025-10-12 00:09:09.760645 | 2025-10-12 00:09:09.760717 | TASK [Run add-build-sshkey role (RSA)] 2025-10-12 00:09:09.779719 | controller | ok 2025-10-12 00:09:09.795168 | 2025-10-12 00:09:09.795233 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-12 00:09:10.001701 | controller -> localhost | ok 2025-10-12 00:09:10.007959 | 2025-10-12 00:09:10.008024 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-12 00:09:10.029109 | controller | ok 2025-10-12 00:09:10.045398 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-12 00:09:10.051875 | 2025-10-12 00:09:10.051936 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-12 00:09:10.479170 | controller -> localhost | Generating public/private rsa key pair. 2025-10-12 00:09:10.479386 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_rsa. 2025-10-12 00:09:10.479415 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_rsa.pub. 2025-10-12 00:09:10.479450 | controller -> localhost | The key fingerprint is: 2025-10-12 00:09:10.479471 | controller -> localhost | SHA256:moV3U1kU9tirVhSjZgfReT5MJiQiH4U+su9PDY1q7lk zuul-build-sshkey 2025-10-12 00:09:10.479490 | controller -> localhost | The key's randomart image is: 2025-10-12 00:09:10.479510 | controller -> localhost | +---[RSA 2048]----+ 2025-10-12 00:09:10.479528 | controller -> localhost | | . ooo.=B+.| 2025-10-12 00:09:10.479547 | controller -> localhost | | o.o .=oO+| 2025-10-12 00:09:10.479565 | controller -> localhost | | .. o+*++| 2025-10-12 00:09:10.479584 | controller -> localhost | | o o .= ooo| 2025-10-12 00:09:10.479602 | controller -> localhost | | . S +o . o.| 2025-10-12 00:09:10.479630 | controller -> localhost | | * ...o o | 2025-10-12 00:09:10.479679 | controller -> localhost | | o .o E + | 2025-10-12 00:09:10.479705 | controller -> localhost | | o.+ . | 2025-10-12 00:09:10.479726 | controller -> localhost | | o=.. | 2025-10-12 00:09:10.479748 | controller -> localhost | +----[SHA256]-----+ 2025-10-12 00:09:10.479795 | controller -> localhost | ok: Runtime: 0:00:00.056713 2025-10-12 00:09:10.487764 | 2025-10-12 00:09:10.488042 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-12 00:09:10.518245 | controller | ok 2025-10-12 00:09:10.529171 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-12 00:09:10.542352 | 2025-10-12 00:09:10.542428 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-12 00:09:10.556889 | controller | skipping: Conditional result was False 2025-10-12 00:09:10.563924 | 2025-10-12 00:09:10.564015 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-12 00:09:11.191329 | controller | changed 2025-10-12 00:09:11.197935 | 2025-10-12 00:09:11.198009 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-12 00:09:11.576802 | controller | ok 2025-10-12 00:09:11.585012 | 2025-10-12 00:09:11.585113 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-12 00:09:12.883716 | controller | changed 2025-10-12 00:09:12.896911 | 2025-10-12 00:09:12.897050 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-12 00:09:14.189647 | controller | changed 2025-10-12 00:09:14.201355 | 2025-10-12 00:09:14.201556 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-12 00:09:14.225783 | controller | skipping: Conditional result was False 2025-10-12 00:09:14.235828 | 2025-10-12 00:09:14.235912 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-12 00:09:14.618022 | controller -> localhost | changed 2025-10-12 00:09:14.630546 | 2025-10-12 00:09:14.630619 | TASK [add-build-sshkey : Add back temp key] 2025-10-12 00:09:14.918189 | controller -> localhost | Identity added: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_rsa (zuul-build-sshkey) 2025-10-12 00:09:14.918486 | controller -> localhost | ok: Runtime: 0:00:00.007557 2025-10-12 00:09:14.926974 | 2025-10-12 00:09:14.927055 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-12 00:09:15.470358 | controller | ok 2025-10-12 00:09:15.475493 | 2025-10-12 00:09:15.475556 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-12 00:09:15.499811 | controller | skipping: Conditional result was False 2025-10-12 00:09:15.511913 | 2025-10-12 00:09:15.511981 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-12 00:09:15.541261 | controller | ok 2025-10-12 00:09:15.556776 | 2025-10-12 00:09:15.556842 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-12 00:09:15.753709 | controller -> localhost | ok 2025-10-12 00:09:15.760124 | 2025-10-12 00:09:15.760187 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-12 00:09:15.779418 | controller | ok 2025-10-12 00:09:15.791170 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-12 00:09:15.797126 | 2025-10-12 00:09:15.797190 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-12 00:09:16.046039 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-12 00:09:16.046247 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_ecdsa. 2025-10-12 00:09:16.046277 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_ecdsa.pub. 2025-10-12 00:09:16.046322 | controller -> localhost | The key fingerprint is: 2025-10-12 00:09:16.046345 | controller -> localhost | SHA256:+ct0D1ffc+JJ0YHOMl6b1mLP7nSBbBb2LmGj20R6HMM zuul-build-sshkey 2025-10-12 00:09:16.046365 | controller -> localhost | The key's randomart image is: 2025-10-12 00:09:16.046384 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-12 00:09:16.046403 | controller -> localhost | | | 2025-10-12 00:09:16.046421 | controller -> localhost | | . | 2025-10-12 00:09:16.046439 | controller -> localhost | | + . | 2025-10-12 00:09:16.046457 | controller -> localhost | | . * +..| 2025-10-12 00:09:16.046474 | controller -> localhost | | S o E.oo| 2025-10-12 00:09:16.046493 | controller -> localhost | | .. % Xo+| 2025-10-12 00:09:16.046511 | controller -> localhost | | o+o@+==| 2025-10-12 00:09:16.046531 | controller -> localhost | | o oB**o+| 2025-10-12 00:09:16.046551 | controller -> localhost | | o. .*= | 2025-10-12 00:09:16.046569 | controller -> localhost | +----[SHA256]-----+ 2025-10-12 00:09:16.046613 | controller -> localhost | ok: Runtime: 0:00:00.008183 2025-10-12 00:09:16.056398 | 2025-10-12 00:09:16.056473 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-12 00:09:16.087958 | controller | ok 2025-10-12 00:09:16.096405 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-12 00:09:16.105257 | 2025-10-12 00:09:16.105321 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-12 00:09:16.131109 | controller | skipping: Conditional result was False 2025-10-12 00:09:16.139974 | 2025-10-12 00:09:16.140063 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-12 00:09:16.616902 | controller | changed 2025-10-12 00:09:16.639733 | 2025-10-12 00:09:16.639852 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-12 00:09:16.991292 | controller | ok 2025-10-12 00:09:17.004210 | 2025-10-12 00:09:17.004383 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-12 00:09:18.297427 | controller | changed 2025-10-12 00:09:18.303145 | 2025-10-12 00:09:18.303211 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-12 00:09:19.805689 | controller | changed 2025-10-12 00:09:19.813976 | 2025-10-12 00:09:19.814063 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-12 00:09:19.839159 | controller | skipping: Conditional result was False 2025-10-12 00:09:19.847923 | 2025-10-12 00:09:19.848039 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-12 00:09:20.065821 | controller -> localhost | changed 2025-10-12 00:09:20.077159 | 2025-10-12 00:09:20.077266 | TASK [add-build-sshkey : Add back temp key] 2025-10-12 00:09:20.335285 | controller -> localhost | Identity added: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/af7dfd72b9244cb7887c8c03c84b8d37_id_ecdsa (zuul-build-sshkey) 2025-10-12 00:09:20.335479 | controller -> localhost | ok: Runtime: 0:00:00.008281 2025-10-12 00:09:20.341817 | 2025-10-12 00:09:20.341879 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-12 00:09:20.664042 | controller | ok 2025-10-12 00:09:20.678141 | 2025-10-12 00:09:20.678278 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-12 00:09:20.706110 | controller | skipping: Conditional result was False 2025-10-12 00:09:20.779587 | 2025-10-12 00:09:20.779791 | TASK [include_role : remove-zuul-sshkey] 2025-10-12 00:09:20.806942 | controller | skipping: Conditional result was False 2025-10-12 00:09:20.815600 | 2025-10-12 00:09:20.815715 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-12 00:09:21.142561 | controller | ok: "logs" 2025-10-12 00:09:21.142937 | controller | ok: All items complete 2025-10-12 00:09:21.142981 | 2025-10-12 00:09:21.433565 | controller | ok: "artifacts" 2025-10-12 00:09:21.749498 | controller | ok: "docs" 2025-10-12 00:09:21.767570 | 2025-10-12 00:09:21.767804 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-12 00:09:22.106438 | controller | changed: "logs" 2025-10-12 00:09:22.395574 | controller | changed: "artifacts" 2025-10-12 00:09:22.684598 | controller | changed: "docs" 2025-10-12 00:09:22.733480 | 2025-10-12 00:09:22.733619 | PLAY RECAP 2025-10-12 00:09:22.733710 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-12 00:09:22.733774 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-12 00:09:22.733805 | 2025-10-12 00:09:22.859309 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-12 00:09:22.860149 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-12 00:09:23.405692 | 2025-10-12 00:09:23.405793 | PLAY [all] 2025-10-12 00:09:23.430979 | 2025-10-12 00:09:23.431058 | TASK [Install binary dependencies] 2025-10-12 00:09:23.470423 | controller | ok 2025-10-12 00:09:23.490120 | 2025-10-12 00:09:23.490196 | TASK [bindep : Include find tasks] 2025-10-12 00:09:23.519329 | controller | ok 2025-10-12 00:09:23.526922 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-12 00:09:23.532842 | 2025-10-12 00:09:23.532903 | TASK [bindep : Look for bindep.txt] 2025-10-12 00:09:24.062033 | controller | ok 2025-10-12 00:09:24.068044 | 2025-10-12 00:09:24.068111 | TASK [bindep : Define bindep_file fact] 2025-10-12 00:09:24.092583 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.100435 | 2025-10-12 00:09:24.100535 | TASK [bindep : Look for other-requirements.txt] 2025-10-12 00:09:24.421999 | controller | ok 2025-10-12 00:09:24.429599 | 2025-10-12 00:09:24.429725 | TASK [bindep : Define bindep_file fact] 2025-10-12 00:09:24.455020 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.463240 | 2025-10-12 00:09:24.463333 | TASK [bindep : Look for bindep fallback file] 2025-10-12 00:09:24.488433 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.496026 | 2025-10-12 00:09:24.496118 | TASK [bindep : Define bindep_file fact] 2025-10-12 00:09:24.520856 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.528348 | 2025-10-12 00:09:24.528439 | TASK [bindep : Include bindep tasks] 2025-10-12 00:09:24.553166 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.564046 | 2025-10-12 00:09:24.564134 | TASK [bindep : Include install tasks] 2025-10-12 00:09:24.599724 | controller | skipping: Conditional result was False 2025-10-12 00:09:24.607250 | 2025-10-12 00:09:24.607335 | LOOP [bindep : Include package tasks] 2025-10-12 00:09:24.665605 | 2025-10-12 00:09:24.666341 | TASK [Run test-setup role] 2025-10-12 00:09:24.685130 | controller | ok 2025-10-12 00:09:24.702988 | 2025-10-12 00:09:24.703050 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-12 00:09:25.029623 | controller | ok 2025-10-12 00:09:25.048123 | 2025-10-12 00:09:25.048266 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-12 00:09:25.197159 | controller | skipping: Conditional result was False 2025-10-12 00:09:25.270813 | 2025-10-12 00:09:25.270930 | PLAY RECAP 2025-10-12 00:09:25.270988 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-12 00:09:25.271015 | 2025-10-12 00:09:25.385806 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-12 00:09:25.386642 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-12 00:09:25.958442 | 2025-10-12 00:09:25.958572 | PLAY [controller] 2025-10-12 00:09:25.977960 | 2025-10-12 00:09:25.978035 | TASK [Create the /root directory] 2025-10-12 00:09:26.697046 | controller | ok 2025-10-12 00:09:26.702632 | 2025-10-12 00:09:26.702726 | TASK [Install glibc-langpack-en] 2025-10-12 00:09:34.882998 | controller | ok: Nothing to do 2025-10-12 00:09:34.899429 | 2025-10-12 00:09:34.899764 | TASK [Ensure controller directory exists] 2025-10-12 00:09:35.371100 | controller | changed 2025-10-12 00:09:35.383880 | 2025-10-12 00:09:35.384047 | TASK [Install container runtime] 2025-10-12 00:09:35.466165 | controller | ok 2025-10-12 00:09:35.531498 | 2025-10-12 00:09:35.531727 | LOOP [ensure-podman : Find distribution installation] 2025-10-12 00:09:35.575248 | controller | ok: "/var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-12 00:09:35.598452 | controller | included: /var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-12 00:09:35.613795 | 2025-10-12 00:09:35.613962 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-12 00:10:52.251493 | controller | changed 2025-10-12 00:10:52.259900 | 2025-10-12 00:10:52.259964 | TASK [ensure-podman : Fetch podman version] 2025-10-12 00:10:52.962512 | controller | Client: Podman Engine 2025-10-12 00:10:52.962595 | controller | Version: 4.6.2 2025-10-12 00:10:52.962627 | controller | API Version: 4.6.2 2025-10-12 00:10:52.962672 | controller | Go Version: go1.19.12 2025-10-12 00:10:52.962711 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-12 00:10:52.962738 | controller | OS/Arch: linux/amd64 2025-10-12 00:10:53.401967 | controller | ok: Runtime: 0:00:00.212535 2025-10-12 00:10:53.408249 | 2025-10-12 00:10:53.408314 | TASK [ensure-podman : Print podman version installed] 2025-10-12 00:10:53.439543 | Podman version: Client: Podman Engine 2025-10-12 00:10:53.439716 | Version: 4.6.2 2025-10-12 00:10:53.439745 | API Version: 4.6.2 2025-10-12 00:10:53.439765 | Go Version: go1.19.12 2025-10-12 00:10:53.439783 | Built: Mon Aug 28 19:38:31 2023 2025-10-12 00:10:53.439802 | OS/Arch: linux/amd64 2025-10-12 00:10:53.445112 | 2025-10-12 00:10:53.445169 | TASK [ensure-podman : Validate podman engine] 2025-10-12 00:10:53.581111 | controller | skipping: Conditional result was False 2025-10-12 00:10:53.587712 | 2025-10-12 00:10:53.587779 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-12 00:10:53.612061 | controller | skipping: Conditional result was False 2025-10-12 00:10:53.622194 | 2025-10-12 00:10:53.622255 | TASK [Ensure python3.8 is present] 2025-10-12 00:10:53.636843 | controller | skipping: Conditional result was False 2025-10-12 00:10:53.642821 | 2025-10-12 00:10:53.642881 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-12 00:10:53.661548 | controller | ok 2025-10-12 00:10:53.687534 | 2025-10-12 00:10:53.687620 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-12 00:10:57.607473 | controller | ok: Nothing to do 2025-10-12 00:10:57.619389 | 2025-10-12 00:10:57.619523 | TASK [our-ensure-python : Also install python3-devel] 2025-10-12 00:11:10.898224 | controller | changed 2025-10-12 00:11:10.920342 | 2025-10-12 00:11:10.920515 | TASK [Run ensure-virtualenv role] 2025-10-12 00:11:10.947757 | controller | ok 2025-10-12 00:11:10.988555 | 2025-10-12 00:11:10.988684 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-12 00:11:11.365252 | controller | /usr/bin/virtualenv 2025-10-12 00:11:11.639392 | controller | ok: Runtime: 0:00:00.004706 2025-10-12 00:11:11.651615 | 2025-10-12 00:11:11.651792 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-12 00:11:11.688253 | controller | skipping: Conditional result was False 2025-10-12 00:11:11.688953 | controller | ok: All items complete 2025-10-12 00:11:11.689042 | 2025-10-12 00:11:11.722361 | 2025-10-12 00:11:11.722568 | TASK [Find the full path of the Python interpreter] 2025-10-12 00:11:12.180104 | controller | /usr/bin/python3 2025-10-12 00:11:12.387949 | controller | ok 2025-10-12 00:11:12.399279 | 2025-10-12 00:11:12.399441 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-12 00:11:13.794254 | controller | created virtual environment CPython3.11.0.final.0-64 in 740ms 2025-10-12 00:11:13.845869 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-12 00:11:13.845927 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv) 2025-10-12 00:11:13.845946 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-12 00:11:13.845970 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-12 00:11:14.046355 | controller | changed 2025-10-12 00:11:14.052465 | 2025-10-12 00:11:14.052563 | TASK [Set selinux package] 2025-10-12 00:11:14.082150 | controller | ok 2025-10-12 00:11:14.087034 | 2025-10-12 00:11:14.087095 | TASK [Set selinux package (Fedora)] 2025-10-12 00:11:14.125807 | controller | ok 2025-10-12 00:11:14.130787 | 2025-10-12 00:11:14.130860 | TASK [Install selinux into virtualenv] 2025-10-12 00:11:16.716693 | controller | Collecting selinux-please-lie-to-me 2025-10-12 00:11:16.814747 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-12 00:11:17.343281 | controller | Collecting setuptools<50.0.0 2025-10-12 00:11:17.358318 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-12 00:11:17.498094 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.0 MB/s eta 0:00:00 2025-10-12 00:11:17.650855 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-12 00:11:17.651266 | controller | Attempting uninstall: setuptools 2025-10-12 00:11:17.656187 | controller | Found existing installation: setuptools 62.6.0 2025-10-12 00:11:17.768708 | controller | Uninstalling setuptools-62.6.0: 2025-10-12 00:11:17.784206 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-12 00:11:18.577338 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-12 00:11:18.812552 | controller | 2025-10-12 00:11:19.028847 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-12 00:11:19.028895 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-12 00:11:19.294312 | controller | ok: Runtime: 0:00:04.426039 2025-10-12 00:11:19.306194 | 2025-10-12 00:11:19.306332 | TASK [Install pytest-forked into virtualenv] 2025-10-12 00:11:20.515275 | controller | Collecting pytest-forked 2025-10-12 00:11:20.606377 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-12 00:11:20.662735 | controller | Collecting py 2025-10-12 00:11:20.677181 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-12 00:11:20.713563 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-10-12 00:11:20.891531 | controller | Collecting pytest>=3.10 2025-10-12 00:11:20.906296 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-12 00:11:20.973469 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.6 MB/s eta 0:00:00 2025-10-12 00:11:21.030226 | controller | Collecting iniconfig>=1 2025-10-12 00:11:21.044781 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-12 00:11:21.111539 | controller | Collecting packaging>=20 2025-10-12 00:11:21.125485 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-12 00:11:21.138920 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.8 MB/s eta 0:00:00 2025-10-12 00:11:21.185766 | controller | Collecting pluggy<2,>=1.5 2025-10-12 00:11:21.199972 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-12 00:11:21.276423 | controller | Collecting pygments>=2.7.2 2025-10-12 00:11:21.290222 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-12 00:11:21.426334 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.2 MB/s eta 0:00:00 2025-10-12 00:11:21.559276 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-12 00:11:23.833945 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-10-12 00:11:23.849763 | controller | 2025-10-12 00:11:24.035054 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-12 00:11:24.035098 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-12 00:11:24.484882 | controller | ok: Runtime: 0:00:04.240282 2025-10-12 00:11:24.499387 | 2025-10-12 00:11:24.499564 | TASK [Update pip] 2025-10-12 00:11:25.604310 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-12 00:11:25.869919 | controller | Collecting pip 2025-10-12 00:11:26.023463 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-12 00:11:26.220746 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.1 MB/s eta 0:00:00 2025-10-12 00:11:26.369782 | controller | Installing collected packages: pip 2025-10-12 00:11:26.370199 | controller | Attempting uninstall: pip 2025-10-12 00:11:26.374777 | controller | Found existing installation: pip 22.2.2 2025-10-12 00:11:26.636789 | controller | Uninstalling pip-22.2.2: 2025-10-12 00:11:26.666856 | controller | Successfully uninstalled pip-22.2.2 2025-10-12 00:11:28.393418 | controller | Successfully installed pip-25.2 2025-10-12 00:11:28.673073 | controller | ok: Runtime: 0:00:03.584298 2025-10-12 00:11:28.685057 | 2025-10-12 00:11:28.685185 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-12 00:11:29.224853 | controller | changed 2025-10-12 00:11:29.236540 | 2025-10-12 00:11:29.236727 | TASK [Install ansible into virtualenv] 2025-10-12 00:11:30.306583 | controller | Processing ./src/github.com/ansible/ansible 2025-10-12 00:11:30.313076 | controller | Installing build dependencies: started 2025-10-12 00:11:32.244598 | controller | Installing build dependencies: finished with status 'done' 2025-10-12 00:11:33.829793 | controller | Getting requirements to build wheel: started 2025-10-12 00:11:33.829858 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-12 00:11:34.757688 | controller | Preparing metadata (pyproject.toml): started 2025-10-12 00:11:34.757743 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-12 00:11:34.762080 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-10-12 00:11:34.762133 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-12 00:11:35.405414 | controller | ERROR 2025-10-12 00:11:35.405824 | controller | { 2025-10-12 00:11:35.405903 | controller | "delta": "0:00:05.232890", 2025-10-12 00:11:35.405950 | controller | "end": "2025-10-12 00:11:34.908912", 2025-10-12 00:11:35.405989 | controller | "msg": "non-zero return code", 2025-10-12 00:11:35.406045 | controller | "rc": 1, 2025-10-12 00:11:35.406084 | controller | "start": "2025-10-12 00:11:29.676022" 2025-10-12 00:11:35.406119 | controller | } failure 2025-10-12 00:11:35.410840 | 2025-10-12 00:11:35.410944 | PLAY RECAP 2025-10-12 00:11:35.411031 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-12 00:11:35.411077 | 2025-10-12 00:11:35.534757 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-12 00:11:35.535702 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-12 00:11:36.151828 | 2025-10-12 00:11:36.151947 | PLAY [all] 2025-10-12 00:11:36.173471 | 2025-10-12 00:11:36.173551 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-12 00:11:36.971833 | controller | changed: non-zero return code 2025-10-12 00:11:36.997062 | 2025-10-12 00:11:36.997257 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-12 00:11:37.024906 | controller | skipping: Conditional result was False 2025-10-12 00:11:37.032937 | 2025-10-12 00:11:37.033031 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-12 00:11:37.067278 | 2025-10-12 00:11:37.067439 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-12 00:11:37.102515 | 2025-10-12 00:11:37.102723 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-12 00:11:37.127561 | controller | skipping: Conditional result was False 2025-10-12 00:11:37.135902 | 2025-10-12 00:11:37.135999 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-12 00:11:37.169886 | 2025-10-12 00:11:37.170054 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-12 00:11:37.184100 | controller | skipping: Conditional result was False 2025-10-12 00:11:37.192127 | 2025-10-12 00:11:37.192214 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-12 00:11:37.207091 | controller | skipping: Conditional result was False 2025-10-12 00:11:37.215561 | 2025-10-12 00:11:37.215647 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-12 00:11:37.230150 | controller | skipping: Conditional result was False 2025-10-12 00:11:37.264762 | 2025-10-12 00:11:37.264812 | PLAY RECAP 2025-10-12 00:11:37.264852 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-12 00:11:37.264871 | 2025-10-12 00:11:37.368750 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-12 00:11:37.370429 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-12 00:11:37.972693 | 2025-10-12 00:11:37.972801 | PLAY [all:!appliance*] 2025-10-12 00:11:37.993501 | 2025-10-12 00:11:37.993591 | TASK [unregister the node] 2025-10-12 00:11:38.130901 | controller | skipping: Conditional result was False 2025-10-12 00:11:38.143274 | 2025-10-12 00:11:38.143431 | TASK [include_role : fetch-output] 2025-10-12 00:11:38.191854 | controller | ok 2025-10-12 00:11:38.228809 | 2025-10-12 00:11:38.228900 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-12 00:11:38.295512 | controller | skipping: Conditional result was False 2025-10-12 00:11:38.307883 | 2025-10-12 00:11:38.308028 | TASK [fetch-output : Set log path for single node] 2025-10-12 00:11:38.356744 | controller | ok 2025-10-12 00:11:38.368227 | 2025-10-12 00:11:38.368359 | LOOP [fetch-output : Ensure local output dirs] 2025-10-12 00:11:38.809880 | controller -> localhost | ok: "/var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/logs" 2025-10-12 00:11:39.082727 | controller -> localhost | changed: "/var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/artifacts" 2025-10-12 00:11:39.372209 | controller -> localhost | changed: "/var/lib/zuul/builds/af7dfd72b9244cb7887c8c03c84b8d37/work/docs" 2025-10-12 00:11:39.386878 | 2025-10-12 00:11:39.387040 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-12 00:11:40.633647 | controller | changed: 2025-10-12 00:11:40.633996 | controller | .d..t...... ./ 2025-10-12 00:11:40.634055 | controller | cd+++++++++ controller/ 2025-10-12 00:11:40.634125 | controller | changed: All items complete 2025-10-12 00:11:40.634168 | 2025-10-12 00:11:41.655743 | controller | changed: .d..t...... ./ 2025-10-12 00:11:42.756855 | controller | changed: .d..t...... ./ 2025-10-12 00:11:42.789700 | 2025-10-12 00:11:42.789907 | TASK [include_role : fetch-output-openshift] 2025-10-12 00:11:42.826909 | controller | skipping: Conditional result was False 2025-10-12 00:11:42.839919 | 2025-10-12 00:11:42.840060 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-12 00:11:42.896155 | controller | skipping: Conditional result was False 2025-10-12 00:11:42.910793 | controller | skipping: Conditional result was False 2025-10-12 00:11:42.974097 | 2025-10-12 00:11:42.974232 | PLAY [localhost] 2025-10-12 00:11:42.991323 | 2025-10-12 00:11:42.991409 | TASK [Run Zuul manifest role] 2025-10-12 00:11:43.013606 | localhost | ok 2025-10-12 00:11:43.032578 | 2025-10-12 00:11:43.032682 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-12 00:11:43.474252 | localhost | changed 2025-10-12 00:11:43.479127 | 2025-10-12 00:11:43.479191 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-12 00:11:43.509465 | localhost | ok 2025-10-12 00:11:43.517558 | 2025-10-12 00:11:43.517614 | TASK [Set zuul-log-path fact] 2025-10-12 00:11:43.536848 | localhost | ok 2025-10-12 00:11:43.550271 | 2025-10-12 00:11:43.550333 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-12 00:11:43.579749 | localhost | ok 2025-10-12 00:11:43.588757 | 2025-10-12 00:11:43.588815 | LOOP [Run upload-logs-swift role] 2025-10-12 00:11:43.623977 | localhost | Output suppressed because no_log was given 2025-10-12 00:11:43.649880 | 2025-10-12 00:11:43.649947 | TASK [Set zuul-log-path fact] 2025-10-12 00:11:43.675661 | localhost | skipping: Conditional result was False 2025-10-12 00:11:43.680936 | 2025-10-12 00:11:43.680996 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-12 00:11:44.091969 | localhost -> localhost | ok: Runtime: 0:00:00.004949 2025-10-12 00:11:44.097448 | 2025-10-12 00:11:44.097509 | TASK [upload-logs-swift : Upload logs to swift]