2025-11-24 00:14:08.575877 | Job console starting... 2025-11-24 00:14:08.591709 | Updating repositories 2025-11-24 00:14:08.766284 | Preparing job workspace 2025-11-24 00:14:12.633972 | Running Ansible setup... 2025-11-24 00:14:20.269834 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:14:20.899458 | 2025-11-24 00:14:20.899582 | PLAY [localhost] 2025-11-24 00:14:20.910328 | 2025-11-24 00:14:20.910434 | TASK [Gathering Facts] 2025-11-24 00:14:21.874328 | localhost | ok 2025-11-24 00:14:21.889128 | 2025-11-24 00:14:21.889231 | TASK [Setup log path fact] 2025-11-24 00:14:21.929694 | localhost | ok 2025-11-24 00:14:21.957927 | 2025-11-24 00:14:21.958076 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:14:21.996241 | localhost | ok 2025-11-24 00:14:22.004688 | 2025-11-24 00:14:22.004800 | TASK [emit-job-header : Print job information] 2025-11-24 00:14:22.033126 | # Job Information 2025-11-24 00:14:22.033276 | Ansible Version: 2.15.12 2025-11-24 00:14:22.033308 | Job: ansible-test-sanity-docker-milestone 2025-11-24 00:14:22.033330 | Pipeline: periodic 2025-11-24 00:14:22.033349 | Executor: ze01.softwarefactory-project.io 2025-11-24 00:14:22.033368 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-24 00:14:22.034247 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/8d3/ansible/8d35e288b4ae47b08d81b26f8adac1db/ 2025-11-24 00:14:22.034291 | Event ID: db80f5515f954e34b34bdcccc30c1493 2025-11-24 00:14:22.038698 | 2025-11-24 00:14:22.038800 | LOOP [emit-job-header : Print node information] 2025-11-24 00:14:22.142506 | localhost | ok: 2025-11-24 00:14:22.142779 | localhost | # Node Information 2025-11-24 00:14:22.142821 | localhost | Inventory Hostname: controller 2025-11-24 00:14:22.142852 | localhost | Hostname: np0005532869 2025-11-24 00:14:22.142880 | localhost | Username: zuul 2025-11-24 00:14:22.142910 | localhost | Distro: Fedora 37 2025-11-24 00:14:22.142937 | localhost | Provider: ansible-vexxhost-ams1 2025-11-24 00:14:22.142964 | localhost | Region: ams1 2025-11-24 00:14:22.142989 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-24 00:14:22.143130 | localhost | Product Name: OpenStack Nova 2025-11-24 00:14:22.143180 | localhost | Interface IP: 38.129.16.127 2025-11-24 00:14:22.158218 | 2025-11-24 00:14:22.158318 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-24 00:14:22.599116 | localhost -> localhost | changed 2025-11-24 00:14:22.612456 | 2025-11-24 00:14:22.612669 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-24 00:14:23.529937 | localhost -> localhost | changed 2025-11-24 00:14:23.575696 | 2025-11-24 00:14:23.575820 | PLAY [all:!appliance*] 2025-11-24 00:14:23.606261 | 2025-11-24 00:14:23.606421 | TASK [include_role : start-zuul-console] 2025-11-24 00:14:23.629967 | controller | ok 2025-11-24 00:14:23.652384 | 2025-11-24 00:14:23.652503 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-24 00:14:24.623147 | controller | ok 2025-11-24 00:14:24.645782 | 2025-11-24 00:14:24.645916 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-24 00:14:26.998646 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-24 00:14:27.008947 | 2025-11-24 00:14:27.009152 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-24 00:14:27.368274 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.378597 | 2025-11-24 00:14:27.378752 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-24 00:14:27.395332 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.410471 | 2025-11-24 00:14:27.410610 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-24 00:14:27.435244 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.441868 | 2025-11-24 00:14:27.442074 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-24 00:14:27.465977 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.472288 | 2025-11-24 00:14:27.472464 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-24 00:14:27.496256 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.503362 | 2025-11-24 00:14:27.503456 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-24 00:14:27.527138 | controller | skipping: Conditional result was False 2025-11-24 00:14:27.538585 | 2025-11-24 00:14:27.538676 | TASK [Disable Fedora Modular] 2025-11-24 00:14:28.575748 | controller | changed 2025-11-24 00:14:28.581671 | 2025-11-24 00:14:28.581748 | TASK [Enable EPEL] 2025-11-24 00:14:28.595159 | controller | skipping: Conditional result was False 2025-11-24 00:14:28.601969 | 2025-11-24 00:14:28.602089 | TASK [Register the RHEL node] 2025-11-24 00:14:29.004551 | 2025-11-24 00:14:29.004802 | TASK [Show the subscription-manager status] 2025-11-24 00:14:29.379211 | controller | skipping: Conditional result was False 2025-11-24 00:14:29.393865 | 2025-11-24 00:14:29.394077 | TASK [Enable EPEL on RHEL] 2025-11-24 00:14:29.783423 | controller | skipping: Conditional result was False 2025-11-24 00:14:29.796178 | 2025-11-24 00:14:29.796325 | TASK [Install git and tox] 2025-11-24 00:16:38.412231 | controller | changed 2025-11-24 00:16:38.430506 | 2025-11-24 00:16:38.430649 | TASK [include_role : prepare-workspace] 2025-11-24 00:16:38.473630 | controller | ok 2025-11-24 00:16:38.516688 | 2025-11-24 00:16:38.516863 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-24 00:16:39.389309 | controller | ok 2025-11-24 00:16:39.398412 | 2025-11-24 00:16:39.398501 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-24 00:16:56.071054 | controller | Output suppressed because no_log was given 2025-11-24 00:16:56.086750 | 2025-11-24 00:16:56.086898 | TASK [include_role : prepare-workspace-openshift] 2025-11-24 00:16:56.116742 | controller | skipping: Conditional result was False 2025-11-24 00:16:56.175471 | 2025-11-24 00:16:56.175568 | PLAY [all:!appliance] 2025-11-24 00:16:56.191558 | 2025-11-24 00:16:56.191654 | TASK [Run add-build-sshkey role (RSA)] 2025-11-24 00:16:56.223761 | controller | ok 2025-11-24 00:16:56.241219 | 2025-11-24 00:16:56.241333 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:16:56.480176 | controller -> localhost | ok 2025-11-24 00:16:56.488766 | 2025-11-24 00:16:56.488862 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:16:56.513679 | controller | ok 2025-11-24 00:16:56.533362 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:16:56.541312 | 2025-11-24 00:16:56.541394 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:16:57.094172 | controller -> localhost | Generating public/private rsa key pair. 2025-11-24 00:16:57.094400 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_rsa. 2025-11-24 00:16:57.094430 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_rsa.pub. 2025-11-24 00:16:57.094453 | controller -> localhost | The key fingerprint is: 2025-11-24 00:16:57.094493 | controller -> localhost | SHA256:fKIF/39RGxFCR3XVwNV4gnnFf5xan/9+z/snL2TkWrI zuul-build-sshkey 2025-11-24 00:16:57.094531 | controller -> localhost | The key's randomart image is: 2025-11-24 00:16:57.094556 | controller -> localhost | +---[RSA 2048]----+ 2025-11-24 00:16:57.094581 | controller -> localhost | | .*oX%| 2025-11-24 00:16:57.094602 | controller -> localhost | | o B.*| 2025-11-24 00:16:57.094622 | controller -> localhost | | . . ++| 2025-11-24 00:16:57.094641 | controller -> localhost | | + .+=| 2025-11-24 00:16:57.094659 | controller -> localhost | | S . oo.*| 2025-11-24 00:16:57.094688 | controller -> localhost | | o + ..*o.| 2025-11-24 00:16:57.094717 | controller -> localhost | | . . B ..| 2025-11-24 00:16:57.094738 | controller -> localhost | | .E +.+| 2025-11-24 00:16:57.094757 | controller -> localhost | | .. *#| 2025-11-24 00:16:57.094778 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:16:57.094835 | controller -> localhost | ok: Runtime: 0:00:00.158689 2025-11-24 00:16:57.101986 | 2025-11-24 00:16:57.102071 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:16:57.132578 | controller | ok 2025-11-24 00:16:57.143905 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:16:57.153007 | 2025-11-24 00:16:57.153107 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:16:57.177858 | controller | skipping: Conditional result was False 2025-11-24 00:16:57.188919 | 2025-11-24 00:16:57.189103 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:16:58.232515 | controller | changed 2025-11-24 00:16:58.248395 | 2025-11-24 00:16:58.248577 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:16:58.897411 | controller | ok 2025-11-24 00:16:58.914297 | 2025-11-24 00:16:58.914429 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:17:01.894254 | controller | changed 2025-11-24 00:17:01.909058 | 2025-11-24 00:17:01.909201 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:17:04.863779 | controller | changed 2025-11-24 00:17:04.876468 | 2025-11-24 00:17:04.876607 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:17:04.904470 | controller | skipping: Conditional result was False 2025-11-24 00:17:04.915177 | 2025-11-24 00:17:04.915301 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:17:05.349638 | controller -> localhost | changed 2025-11-24 00:17:05.367788 | 2025-11-24 00:17:05.367904 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:17:05.616791 | controller -> localhost | Identity added: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_rsa (zuul-build-sshkey) 2025-11-24 00:17:05.617062 | controller -> localhost | ok: Runtime: 0:00:00.006923 2025-11-24 00:17:05.624150 | 2025-11-24 00:17:05.624215 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:17:06.529276 | controller | ok 2025-11-24 00:17:06.543271 | 2025-11-24 00:17:06.543460 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:17:06.581492 | controller | skipping: Conditional result was False 2025-11-24 00:17:06.603666 | 2025-11-24 00:17:06.603807 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-24 00:17:06.636390 | controller | ok 2025-11-24 00:17:06.659624 | 2025-11-24 00:17:06.659776 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:17:06.939397 | controller -> localhost | ok 2025-11-24 00:17:06.950726 | 2025-11-24 00:17:06.950856 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:17:06.985795 | controller | ok 2025-11-24 00:17:07.002425 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:17:07.011328 | 2025-11-24 00:17:07.011431 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:17:07.323244 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-24 00:17:07.323464 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_ecdsa. 2025-11-24 00:17:07.323499 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_ecdsa.pub. 2025-11-24 00:17:07.323533 | controller -> localhost | The key fingerprint is: 2025-11-24 00:17:07.323553 | controller -> localhost | SHA256:bV08ywu91MxUsYkU7NfmzxU+WBbwWXz4hnrV9GZNsuw zuul-build-sshkey 2025-11-24 00:17:07.323574 | controller -> localhost | The key's randomart image is: 2025-11-24 00:17:07.323595 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-24 00:17:07.323613 | controller -> localhost | | .+o++| 2025-11-24 00:17:07.323630 | controller -> localhost | | .o=.@| 2025-11-24 00:17:07.323648 | controller -> localhost | | .o+%O| 2025-11-24 00:17:07.323666 | controller -> localhost | | . . =+%%| 2025-11-24 00:17:07.323684 | controller -> localhost | | S o oo@B=| 2025-11-24 00:17:07.323702 | controller -> localhost | | . .+E=o| 2025-11-24 00:17:07.323720 | controller -> localhost | | .o.+| 2025-11-24 00:17:07.323737 | controller -> localhost | | o| 2025-11-24 00:17:07.323756 | controller -> localhost | | | 2025-11-24 00:17:07.323773 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:17:07.323822 | controller -> localhost | ok: Runtime: 0:00:00.011995 2025-11-24 00:17:07.331042 | 2025-11-24 00:17:07.331149 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:17:07.368786 | controller | ok 2025-11-24 00:17:07.385606 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:17:07.399101 | 2025-11-24 00:17:07.399255 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:17:07.425675 | controller | skipping: Conditional result was False 2025-11-24 00:17:07.436473 | 2025-11-24 00:17:07.436639 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:17:08.305677 | controller | changed 2025-11-24 00:17:08.348600 | 2025-11-24 00:17:08.348759 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:17:08.975119 | controller | ok 2025-11-24 00:17:08.987787 | 2025-11-24 00:17:08.987929 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:17:11.921271 | controller | changed 2025-11-24 00:17:11.927562 | 2025-11-24 00:17:11.927665 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:17:14.843738 | controller | changed 2025-11-24 00:17:14.860507 | 2025-11-24 00:17:14.860698 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:17:14.886279 | controller | skipping: Conditional result was False 2025-11-24 00:17:14.896861 | 2025-11-24 00:17:14.896992 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:17:15.148232 | controller -> localhost | changed 2025-11-24 00:17:15.181728 | 2025-11-24 00:17:15.182100 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:17:15.540231 | controller -> localhost | Identity added: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/8d35e288b4ae47b08d81b26f8adac1db_id_ecdsa (zuul-build-sshkey) 2025-11-24 00:17:15.540509 | controller -> localhost | ok: Runtime: 0:00:00.007447 2025-11-24 00:17:15.550339 | 2025-11-24 00:17:15.550463 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:17:16.245833 | controller | ok 2025-11-24 00:17:16.259659 | 2025-11-24 00:17:16.259825 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:17:16.298072 | controller | skipping: Conditional result was False 2025-11-24 00:17:16.326614 | 2025-11-24 00:17:16.326763 | TASK [include_role : remove-zuul-sshkey] 2025-11-24 00:17:16.354057 | controller | skipping: Conditional result was False 2025-11-24 00:17:16.362972 | 2025-11-24 00:17:16.363078 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-24 00:17:17.007295 | controller | ok: "logs" 2025-11-24 00:17:17.007626 | controller | ok: All items complete 2025-11-24 00:17:17.007666 | 2025-11-24 00:17:17.624914 | controller | ok: "artifacts" 2025-11-24 00:17:18.200682 | controller | ok: "docs" 2025-11-24 00:17:18.223080 | 2025-11-24 00:17:18.223286 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-24 00:17:18.867270 | controller | changed: "logs" 2025-11-24 00:17:19.444343 | controller | changed: "artifacts" 2025-11-24 00:17:20.037212 | controller | changed: "docs" 2025-11-24 00:17:20.088708 | 2025-11-24 00:17:20.088842 | PLAY RECAP 2025-11-24 00:17:20.088919 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-24 00:17:20.088970 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-24 00:17:20.089006 | 2025-11-24 00:17:20.216149 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:17:20.218071 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:17:20.811729 | 2025-11-24 00:17:20.811835 | PLAY [all] 2025-11-24 00:17:20.834065 | 2025-11-24 00:17:20.834170 | TASK [Install binary dependencies] 2025-11-24 00:17:20.921465 | controller | ok 2025-11-24 00:17:20.962145 | 2025-11-24 00:17:20.962298 | TASK [bindep : Include find tasks] 2025-11-24 00:17:20.995936 | controller | ok 2025-11-24 00:17:21.008697 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-24 00:17:21.019295 | 2025-11-24 00:17:21.019438 | TASK [bindep : Look for bindep.txt] 2025-11-24 00:17:21.925847 | controller | ok 2025-11-24 00:17:21.940421 | 2025-11-24 00:17:21.940639 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:17:21.957631 | controller | skipping: Conditional result was False 2025-11-24 00:17:21.972998 | 2025-11-24 00:17:21.973220 | TASK [bindep : Look for other-requirements.txt] 2025-11-24 00:17:22.599703 | controller | ok 2025-11-24 00:17:22.607799 | 2025-11-24 00:17:22.607891 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:17:22.642715 | controller | skipping: Conditional result was False 2025-11-24 00:17:22.650995 | 2025-11-24 00:17:22.651115 | TASK [bindep : Look for bindep fallback file] 2025-11-24 00:17:22.686049 | controller | skipping: Conditional result was False 2025-11-24 00:17:22.694692 | 2025-11-24 00:17:22.694806 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:17:22.729054 | controller | skipping: Conditional result was False 2025-11-24 00:17:22.737183 | 2025-11-24 00:17:22.737280 | TASK [bindep : Include bindep tasks] 2025-11-24 00:17:22.761767 | controller | skipping: Conditional result was False 2025-11-24 00:17:22.770073 | 2025-11-24 00:17:22.770178 | TASK [bindep : Include install tasks] 2025-11-24 00:17:22.794659 | controller | skipping: Conditional result was False 2025-11-24 00:17:22.803162 | 2025-11-24 00:17:22.803270 | LOOP [bindep : Include package tasks] 2025-11-24 00:17:22.874097 | 2025-11-24 00:17:22.874293 | TASK [Run test-setup role] 2025-11-24 00:17:22.896886 | controller | ok 2025-11-24 00:17:22.923955 | 2025-11-24 00:17:22.924135 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-24 00:17:23.650110 | controller | ok 2025-11-24 00:17:23.666434 | 2025-11-24 00:17:23.666580 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-24 00:17:24.035327 | controller | skipping: Conditional result was False 2025-11-24 00:17:24.065149 | 2025-11-24 00:17:24.065251 | PLAY RECAP 2025-11-24 00:17:24.065290 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:17:24.065310 | 2025-11-24 00:17:24.165520 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:17:24.167191 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:17:24.789247 | 2025-11-24 00:17:24.789380 | PLAY [controller] 2025-11-24 00:17:24.811242 | 2025-11-24 00:17:24.811558 | TASK [Create the /root directory] 2025-11-24 00:17:25.827716 | controller | ok 2025-11-24 00:17:25.839278 | 2025-11-24 00:17:25.839446 | TASK [Install glibc-langpack-en] 2025-11-24 00:17:33.174842 | controller | ok: Nothing to do 2025-11-24 00:17:33.188680 | 2025-11-24 00:17:33.188835 | TASK [Ensure controller directory exists] 2025-11-24 00:17:34.017092 | controller | changed 2025-11-24 00:17:34.031449 | 2025-11-24 00:17:34.031622 | TASK [Install container runtime] 2025-11-24 00:17:34.113825 | controller | ok 2025-11-24 00:17:34.176398 | 2025-11-24 00:17:34.176540 | LOOP [ensure-podman : Find distribution installation] 2025-11-24 00:17:34.218366 | controller | ok: "/var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-24 00:17:34.238090 | controller | included: /var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-24 00:17:34.253898 | 2025-11-24 00:17:34.254104 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-24 00:19:24.480003 | controller | changed 2025-11-24 00:19:24.493863 | 2025-11-24 00:19:24.494063 | TASK [ensure-podman : Fetch podman version] 2025-11-24 00:19:25.622359 | controller | Client: Podman Engine 2025-11-24 00:19:25.622494 | controller | Version: 4.6.2 2025-11-24 00:19:25.622540 | controller | API Version: 4.6.2 2025-11-24 00:19:25.622582 | controller | Go Version: go1.19.12 2025-11-24 00:19:25.622646 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:19:25.622688 | controller | OS/Arch: linux/amd64 2025-11-24 00:19:25.870534 | controller | ok: Runtime: 0:00:00.274882 2025-11-24 00:19:25.882151 | 2025-11-24 00:19:25.882333 | TASK [ensure-podman : Print podman version installed] 2025-11-24 00:19:25.921960 | Podman version: Client: Podman Engine 2025-11-24 00:19:25.922229 | Version: 4.6.2 2025-11-24 00:19:25.922272 | API Version: 4.6.2 2025-11-24 00:19:25.922302 | Go Version: go1.19.12 2025-11-24 00:19:25.922328 | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:19:25.922358 | OS/Arch: linux/amd64 2025-11-24 00:19:25.932111 | 2025-11-24 00:19:25.932248 | TASK [ensure-podman : Validate podman engine] 2025-11-24 00:19:26.299391 | controller | skipping: Conditional result was False 2025-11-24 00:19:26.306762 | 2025-11-24 00:19:26.306843 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-24 00:19:26.330545 | controller | skipping: Conditional result was False 2025-11-24 00:19:26.342568 | 2025-11-24 00:19:26.342641 | TASK [Ensure python3.8 is present] 2025-11-24 00:19:26.356744 | controller | skipping: Conditional result was False 2025-11-24 00:19:26.364409 | 2025-11-24 00:19:26.364521 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-24 00:19:26.385496 | controller | ok 2025-11-24 00:19:26.409967 | 2025-11-24 00:19:26.410113 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-24 00:19:29.781371 | controller | ok: Nothing to do 2025-11-24 00:19:29.800268 | 2025-11-24 00:19:29.800388 | TASK [our-ensure-python : Also install python3-devel] 2025-11-24 00:19:45.013270 | controller | changed 2025-11-24 00:19:45.044169 | 2025-11-24 00:19:45.044308 | TASK [Run ensure-virtualenv role] 2025-11-24 00:19:45.109950 | controller | ok 2025-11-24 00:19:45.136011 | 2025-11-24 00:19:45.136166 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-24 00:19:45.853284 | controller | /usr/bin/virtualenv 2025-11-24 00:19:45.996889 | controller | ok: Runtime: 0:00:00.006806 2025-11-24 00:19:46.014235 | 2025-11-24 00:19:46.014416 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-24 00:19:46.041455 | controller | skipping: Conditional result was False 2025-11-24 00:19:46.041830 | controller | ok: All items complete 2025-11-24 00:19:46.041869 | 2025-11-24 00:19:46.067105 | 2025-11-24 00:19:46.067354 | TASK [Find the full path of the Python interpreter] 2025-11-24 00:19:46.664072 | controller | /usr/bin/python3 2025-11-24 00:19:46.934161 | controller | ok 2025-11-24 00:19:46.953608 | 2025-11-24 00:19:46.953869 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-24 00:19:48.650071 | controller | created virtual environment CPython3.11.0.final.0-64 in 823ms 2025-11-24 00:19:48.715629 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-24 00:19:48.715720 | 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/.local/share/virtualenv) 2025-11-24 00:19:48.715739 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-24 00:19:48.715769 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-24 00:19:48.855843 | controller | changed 2025-11-24 00:19:48.869797 | 2025-11-24 00:19:48.869950 | TASK [Set selinux package] 2025-11-24 00:19:48.909735 | controller | ok 2025-11-24 00:19:48.921753 | 2025-11-24 00:19:48.921971 | TASK [Set selinux package (Fedora)] 2025-11-24 00:19:48.957666 | controller | ok 2025-11-24 00:19:48.964970 | 2025-11-24 00:19:48.965084 | TASK [Install selinux into virtualenv] 2025-11-24 00:19:51.636290 | controller | Collecting selinux-please-lie-to-me 2025-11-24 00:19:51.695013 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-24 00:19:52.139468 | controller | Collecting setuptools<50.0.0 2025-11-24 00:19:52.145380 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-24 00:19:52.189883 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 20.5 MB/s eta 0:00:00 2025-11-24 00:19:52.308034 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-24 00:19:52.308220 | controller | Attempting uninstall: setuptools 2025-11-24 00:19:52.311947 | controller | Found existing installation: setuptools 62.6.0 2025-11-24 00:19:52.403134 | controller | Uninstalling setuptools-62.6.0: 2025-11-24 00:19:52.415300 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-24 00:19:53.062200 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-24 00:19:53.236318 | controller | 2025-11-24 00:19:53.605627 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:19:53.605713 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:19:53.867394 | controller | ok: Runtime: 0:00:03.873685 2025-11-24 00:19:53.873323 | 2025-11-24 00:19:53.873403 | TASK [Install pytest-forked into virtualenv] 2025-11-24 00:19:55.242967 | controller | Collecting pytest-forked 2025-11-24 00:19:55.296432 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-24 00:19:55.352262 | controller | Collecting py 2025-11-24 00:19:55.357474 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-24 00:19:55.387477 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.7 MB/s eta 0:00:00 2025-11-24 00:19:55.530932 | controller | Collecting pytest>=3.10 2025-11-24 00:19:55.536598 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-11-24 00:19:55.555697 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 24.6 MB/s eta 0:00:00 2025-11-24 00:19:55.605100 | controller | Collecting iniconfig>=1.0.1 2025-11-24 00:19:55.610077 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-24 00:19:55.669710 | controller | Collecting packaging>=22 2025-11-24 00:19:55.674649 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-24 00:19:55.684565 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.8 MB/s eta 0:00:00 2025-11-24 00:19:55.728979 | controller | Collecting pluggy<2,>=1.5 2025-11-24 00:19:55.733980 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-24 00:19:55.798443 | controller | Collecting pygments>=2.7.2 2025-11-24 00:19:55.803478 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-24 00:19:55.827115 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 62.0 MB/s eta 0:00:00 2025-11-24 00:19:55.924469 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-24 00:19:57.997158 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.1 pytest-forked-1.6.0 2025-11-24 00:19:58.010637 | controller | 2025-11-24 00:19:58.372012 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:19:58.372102 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:19:58.734941 | controller | ok: Runtime: 0:00:03.767124 2025-11-24 00:19:58.741869 | 2025-11-24 00:19:58.741987 | TASK [Update pip] 2025-11-24 00:20:00.033914 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-24 00:20:00.353713 | controller | Collecting pip 2025-11-24 00:20:00.416274 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-24 00:20:00.492902 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.9 MB/s eta 0:00:00 2025-11-24 00:20:00.601694 | controller | Installing collected packages: pip 2025-11-24 00:20:00.602088 | controller | Attempting uninstall: pip 2025-11-24 00:20:00.606728 | controller | Found existing installation: pip 22.2.2 2025-11-24 00:20:00.807462 | controller | Uninstalling pip-22.2.2: 2025-11-24 00:20:00.831500 | controller | Successfully uninstalled pip-22.2.2 2025-11-24 00:20:02.402918 | controller | Successfully installed pip-25.3 2025-11-24 00:20:03.112308 | controller | ok: Runtime: 0:00:03.219081 2025-11-24 00:20:03.122562 | 2025-11-24 00:20:03.122719 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-24 00:20:03.986987 | controller | changed 2025-11-24 00:20:03.996209 | 2025-11-24 00:20:03.996308 | TASK [Install ansible into virtualenv] 2025-11-24 00:20:05.373404 | controller | Processing ./src/github.com/ansible/ansible 2025-11-24 00:20:05.381569 | controller | Installing build dependencies: started 2025-11-24 00:20:07.233195 | controller | Installing build dependencies: finished with status 'done' 2025-11-24 00:20:08.582330 | controller | Getting requirements to build wheel: started 2025-11-24 00:20:08.582452 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-24 00:20:08.583920 | controller | Preparing metadata (pyproject.toml): started 2025-11-24 00:20:09.363437 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-24 00:20:09.367598 | 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-11-24 00:20:09.371356 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-24 00:20:09.891165 | controller | ERROR 2025-11-24 00:20:09.891357 | controller | { 2025-11-24 00:20:09.891388 | controller | "delta": "0:00:04.912504", 2025-11-24 00:20:09.891409 | controller | "end": "2025-11-24 00:20:09.546052", 2025-11-24 00:20:09.891427 | controller | "msg": "non-zero return code", 2025-11-24 00:20:09.891458 | controller | "rc": 1, 2025-11-24 00:20:09.891476 | controller | "start": "2025-11-24 00:20:04.633548" 2025-11-24 00:20:09.891492 | controller | } failure 2025-11-24 00:20:09.892840 | 2025-11-24 00:20:09.892886 | PLAY RECAP 2025-11-24 00:20:09.892926 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-24 00:20:09.892946 | 2025-11-24 00:20:10.007822 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:20:10.008991 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:20:10.701144 | 2025-11-24 00:20:10.701267 | PLAY [all] 2025-11-24 00:20:10.722786 | 2025-11-24 00:20:10.722890 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-24 00:20:12.571921 | controller | changed: non-zero return code 2025-11-24 00:20:12.586167 | 2025-11-24 00:20:12.586509 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-24 00:20:12.613861 | controller | skipping: Conditional result was False 2025-11-24 00:20:12.623001 | 2025-11-24 00:20:12.623169 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-24 00:20:12.658870 | 2025-11-24 00:20:12.659104 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-24 00:20:12.695176 | 2025-11-24 00:20:12.695399 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-24 00:20:12.714366 | controller | skipping: Conditional result was False 2025-11-24 00:20:12.725287 | 2025-11-24 00:20:12.725413 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-24 00:20:12.754994 | 2025-11-24 00:20:12.755284 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-24 00:20:12.784060 | controller | skipping: Conditional result was False 2025-11-24 00:20:12.792802 | 2025-11-24 00:20:12.792918 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-24 00:20:12.808201 | controller | skipping: Conditional result was False 2025-11-24 00:20:12.818282 | 2025-11-24 00:20:12.818395 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-24 00:20:12.833346 | controller | skipping: Conditional result was False 2025-11-24 00:20:12.870786 | 2025-11-24 00:20:12.870928 | PLAY RECAP 2025-11-24 00:20:12.870993 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:20:12.871077 | 2025-11-24 00:20:12.986635 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:20:12.987599 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-24 00:20:13.672228 | 2025-11-24 00:20:13.672367 | PLAY [all:!appliance*] 2025-11-24 00:20:13.699297 | 2025-11-24 00:20:13.699408 | TASK [unregister the node] 2025-11-24 00:20:14.054723 | controller | skipping: Conditional result was False 2025-11-24 00:20:14.061269 | 2025-11-24 00:20:14.061379 | TASK [include_role : fetch-output] 2025-11-24 00:20:14.102130 | controller | ok 2025-11-24 00:20:14.126334 | 2025-11-24 00:20:14.126484 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-24 00:20:14.173468 | controller | skipping: Conditional result was False 2025-11-24 00:20:14.179816 | 2025-11-24 00:20:14.179902 | TASK [fetch-output : Set log path for single node] 2025-11-24 00:20:14.224899 | controller | ok 2025-11-24 00:20:14.233394 | 2025-11-24 00:20:14.233500 | LOOP [fetch-output : Ensure local output dirs] 2025-11-24 00:20:14.689367 | controller -> localhost | ok: "/var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/logs" 2025-11-24 00:20:14.916978 | controller -> localhost | changed: "/var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/artifacts" 2025-11-24 00:20:15.138817 | controller -> localhost | changed: "/var/lib/zuul/builds/8d35e288b4ae47b08d81b26f8adac1db/work/docs" 2025-11-24 00:20:15.154831 | 2025-11-24 00:20:15.154963 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-24 00:20:17.397433 | controller | changed: 2025-11-24 00:20:17.397820 | controller | .d..t...... ./ 2025-11-24 00:20:17.397873 | controller | cd+++++++++ controller/ 2025-11-24 00:20:17.397932 | controller | changed: All items complete 2025-11-24 00:20:17.397967 | 2025-11-24 00:20:19.425962 | controller | changed: .d..t...... ./ 2025-11-24 00:20:21.477638 | controller | changed: .d..t...... ./ 2025-11-24 00:20:21.513452 | 2025-11-24 00:20:21.513609 | TASK [include_role : fetch-output-openshift] 2025-11-24 00:20:21.529990 | controller | skipping: Conditional result was False 2025-11-24 00:20:21.545821 | 2025-11-24 00:20:21.546115 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-24 00:20:21.578733 | controller | skipping: Conditional result was False 2025-11-24 00:20:21.590493 | controller | skipping: Conditional result was False 2025-11-24 00:20:21.622656 | 2025-11-24 00:20:21.622764 | PLAY [localhost] 2025-11-24 00:20:21.638277 | 2025-11-24 00:20:21.638393 | TASK [Run Zuul manifest role] 2025-11-24 00:20:21.657338 | localhost | ok 2025-11-24 00:20:21.671441 | 2025-11-24 00:20:21.671556 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-24 00:20:22.093346 | localhost | changed 2025-11-24 00:20:22.104036 | 2025-11-24 00:20:22.104175 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-24 00:20:22.134157 | localhost | ok 2025-11-24 00:20:22.143156 | 2025-11-24 00:20:22.143242 | TASK [Set zuul-log-path fact] 2025-11-24 00:20:22.162338 | localhost | ok 2025-11-24 00:20:22.202160 | 2025-11-24 00:20:22.202279 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:20:22.242786 | localhost | ok 2025-11-24 00:20:22.254072 | 2025-11-24 00:20:22.254202 | LOOP [Run upload-logs-swift role] 2025-11-24 00:20:22.290107 | localhost | Output suppressed because no_log was given 2025-11-24 00:20:22.317316 | 2025-11-24 00:20:22.317439 | TASK [Set zuul-log-path fact] 2025-11-24 00:20:22.352861 | localhost | skipping: Conditional result was False 2025-11-24 00:20:22.359245 | 2025-11-24 00:20:22.359345 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-24 00:20:22.771313 | localhost -> localhost | ok: Runtime: 0:00:00.009571 2025-11-24 00:20:22.777216 | 2025-11-24 00:20:22.777304 | TASK [upload-logs-swift : Upload logs to swift]