2025-09-23 00:11:52.413816 | Job console starting... 2025-09-23 00:11:52.423211 | Updating repositories 2025-09-23 00:11:52.541181 | Preparing job workspace 2025-09-23 00:11:56.045859 | Running Ansible setup... 2025-09-23 00:12:02.297275 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-23 00:12:02.981059 | 2025-09-23 00:12:02.981210 | PLAY [localhost] 2025-09-23 00:12:02.990300 | 2025-09-23 00:12:02.990403 | TASK [Gathering Facts] 2025-09-23 00:12:04.002376 | localhost | ok 2025-09-23 00:12:04.022909 | 2025-09-23 00:12:04.023055 | TASK [Setup log path fact] 2025-09-23 00:12:04.043540 | localhost | ok 2025-09-23 00:12:04.057722 | 2025-09-23 00:12:04.057875 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-23 00:12:04.095848 | localhost | ok 2025-09-23 00:12:04.103389 | 2025-09-23 00:12:04.103529 | TASK [emit-job-header : Print job information] 2025-09-23 00:12:04.132191 | # Job Information 2025-09-23 00:12:04.132368 | Ansible Version: 2.15.12 2025-09-23 00:12:04.132406 | Job: ansible-test-sanity-docker-devel 2025-09-23 00:12:04.132432 | Pipeline: periodic 2025-09-23 00:12:04.132454 | Executor: ze03.softwarefactory-project.io 2025-09-23 00:12:04.132475 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-23 00:12:04.132499 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/eea/ansible/eea14462c64741b9a0559f158eca6b93/ 2025-09-23 00:12:04.132522 | Event ID: ce90a15208884c3e9ebd24fbd880974e 2025-09-23 00:12:04.136713 | 2025-09-23 00:12:04.136810 | LOOP [emit-job-header : Print node information] 2025-09-23 00:12:04.244480 | localhost | ok: 2025-09-23 00:12:04.244714 | localhost | # Node Information 2025-09-23 00:12:04.244789 | localhost | Inventory Hostname: controller 2025-09-23 00:12:04.244811 | localhost | Hostname: ip-172-16-62-143 2025-09-23 00:12:04.244832 | localhost | Username: zuul-worker 2025-09-23 00:12:04.244853 | localhost | Distro: Fedora 37 2025-09-23 00:12:04.244873 | localhost | Provider: ansible-us-east-2 2025-09-23 00:12:04.244891 | localhost | Region: us-east-2 2025-09-23 00:12:04.244909 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-23 00:12:04.244925 | localhost | Product Name: t3.small 2025-09-23 00:12:04.244943 | localhost | Interface IP: 18.189.14.175 2025-09-23 00:12:04.260721 | 2025-09-23 00:12:04.260852 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-23 00:12:04.654018 | localhost -> localhost | changed 2025-09-23 00:12:04.664913 | 2025-09-23 00:12:04.665029 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-23 00:12:05.558054 | localhost -> localhost | changed 2025-09-23 00:12:05.577573 | 2025-09-23 00:12:05.577666 | PLAY [all:!appliance*] 2025-09-23 00:12:05.594371 | 2025-09-23 00:12:05.594487 | TASK [include_role : start-zuul-console] 2025-09-23 00:12:05.613392 | controller | ok 2025-09-23 00:12:05.627704 | 2025-09-23 00:12:05.627835 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-23 00:12:06.308104 | controller | ok 2025-09-23 00:12:06.318978 | 2025-09-23 00:12:06.319073 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-23 00:12:07.846783 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-23 00:12:07.863543 | 2025-09-23 00:12:07.863666 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-23 00:12:08.010884 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.028216 | 2025-09-23 00:12:08.028427 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-23 00:12:08.056876 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.076240 | 2025-09-23 00:12:08.076398 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-23 00:12:08.101326 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.110878 | 2025-09-23 00:12:08.111000 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-23 00:12:08.136151 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.145103 | 2025-09-23 00:12:08.145224 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-23 00:12:08.170827 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.180040 | 2025-09-23 00:12:08.180182 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-23 00:12:08.207178 | controller | skipping: Conditional result was False 2025-09-23 00:12:08.224979 | 2025-09-23 00:12:08.225098 | TASK [Disable Fedora Modular] 2025-09-23 00:12:09.049449 | controller | changed 2025-09-23 00:12:09.058360 | 2025-09-23 00:12:09.058466 | TASK [Enable EPEL] 2025-09-23 00:12:09.083033 | controller | skipping: Conditional result was False 2025-09-23 00:12:09.089285 | 2025-09-23 00:12:09.089361 | TASK [Register the RHEL node] 2025-09-23 00:12:09.240154 | 2025-09-23 00:12:09.240339 | TASK [Show the subscription-manager status] 2025-09-23 00:12:09.387824 | controller | skipping: Conditional result was False 2025-09-23 00:12:09.425036 | 2025-09-23 00:12:09.425154 | TASK [Enable EPEL on RHEL] 2025-09-23 00:12:09.568584 | controller | skipping: Conditional result was False 2025-09-23 00:12:09.574586 | 2025-09-23 00:12:09.574665 | TASK [Install git and tox] 2025-09-23 00:13:46.896449 | controller | changed 2025-09-23 00:13:46.911182 | 2025-09-23 00:13:46.911337 | TASK [include_role : prepare-workspace] 2025-09-23 00:13:46.941999 | controller | ok 2025-09-23 00:13:46.980024 | 2025-09-23 00:13:46.980184 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-23 00:13:47.477002 | controller | ok 2025-09-23 00:13:47.491422 | 2025-09-23 00:13:47.491582 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-23 00:14:00.423912 | controller | Output suppressed because no_log was given 2025-09-23 00:14:00.435272 | 2025-09-23 00:14:00.435358 | TASK [include_role : prepare-workspace-openshift] 2025-09-23 00:14:00.452248 | controller | skipping: Conditional result was False 2025-09-23 00:14:00.489559 | 2025-09-23 00:14:00.489678 | PLAY [all:!appliance] 2025-09-23 00:14:00.514518 | 2025-09-23 00:14:00.514611 | TASK [Run add-build-sshkey role (RSA)] 2025-09-23 00:14:00.545850 | controller | ok 2025-09-23 00:14:00.563256 | 2025-09-23 00:14:00.563357 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-23 00:14:00.811820 | controller -> localhost | ok 2025-09-23 00:14:00.829705 | 2025-09-23 00:14:00.830096 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-23 00:14:00.939750 | controller | ok 2025-09-23 00:14:00.960494 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-23 00:14:00.967409 | 2025-09-23 00:14:00.967504 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-23 00:14:01.452246 | controller -> localhost | Generating public/private rsa key pair. 2025-09-23 00:14:01.452429 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_rsa. 2025-09-23 00:14:01.452459 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_rsa.pub. 2025-09-23 00:14:01.452481 | controller -> localhost | The key fingerprint is: 2025-09-23 00:14:01.452503 | controller -> localhost | SHA256:VfqvokBpzYGZ7FzZAx09l1iiP4gkDZcUD5FpNW9al3c zuul-build-sshkey 2025-09-23 00:14:01.452523 | controller -> localhost | The key's randomart image is: 2025-09-23 00:14:01.452543 | controller -> localhost | +---[RSA 2048]----+ 2025-09-23 00:14:01.452562 | controller -> localhost | | ..BO+ooo.. | 2025-09-23 00:14:01.452581 | controller -> localhost | | . B=*.*+.o. | 2025-09-23 00:14:01.452600 | controller -> localhost | | *.* B +oo E| 2025-09-23 00:14:01.452618 | controller -> localhost | | o B + O . ..| 2025-09-23 00:14:01.452636 | controller -> localhost | | * S o + | 2025-09-23 00:14:01.452663 | controller -> localhost | | o o | 2025-09-23 00:14:01.452691 | controller -> localhost | | . . | 2025-09-23 00:14:01.452741 | controller -> localhost | | . . . | 2025-09-23 00:14:01.452819 | controller -> localhost | | .. .. | 2025-09-23 00:14:01.452854 | controller -> localhost | +----[SHA256]-----+ 2025-09-23 00:14:01.452915 | controller -> localhost | ok: Runtime: 0:00:00.054777 2025-09-23 00:14:01.459318 | 2025-09-23 00:14:01.459387 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-23 00:14:01.479368 | controller | ok 2025-09-23 00:14:01.491195 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-23 00:14:01.501316 | 2025-09-23 00:14:01.501413 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-23 00:14:01.516045 | controller | skipping: Conditional result was False 2025-09-23 00:14:01.523184 | 2025-09-23 00:14:01.523275 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-23 00:14:02.760984 | controller | changed 2025-09-23 00:14:02.770631 | 2025-09-23 00:14:02.770802 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-23 00:14:03.781239 | controller | ok 2025-09-23 00:14:03.787075 | 2025-09-23 00:14:03.787144 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-23 00:14:07.410364 | controller | changed 2025-09-23 00:14:07.419218 | 2025-09-23 00:14:07.419345 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-23 00:14:10.242555 | controller | changed 2025-09-23 00:14:10.250566 | 2025-09-23 00:14:10.250681 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-23 00:14:10.276181 | controller | skipping: Conditional result was False 2025-09-23 00:14:10.286684 | 2025-09-23 00:14:10.286874 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-23 00:14:10.670470 | controller -> localhost | changed 2025-09-23 00:14:10.695357 | 2025-09-23 00:14:10.695534 | TASK [add-build-sshkey : Add back temp key] 2025-09-23 00:14:10.988606 | controller -> localhost | Identity added: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_rsa (zuul-build-sshkey) 2025-09-23 00:14:10.989151 | controller -> localhost | ok: Runtime: 0:00:00.016059 2025-09-23 00:14:11.006058 | 2025-09-23 00:14:11.006267 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-23 00:14:11.858312 | controller | ok 2025-09-23 00:14:11.868198 | 2025-09-23 00:14:11.868302 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-23 00:14:11.913274 | controller | skipping: Conditional result was False 2025-09-23 00:14:11.924607 | 2025-09-23 00:14:11.924693 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-23 00:14:11.954058 | controller | ok 2025-09-23 00:14:11.970624 | 2025-09-23 00:14:11.970826 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-23 00:14:12.219227 | controller -> localhost | ok 2025-09-23 00:14:12.225996 | 2025-09-23 00:14:12.226063 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-23 00:14:12.256968 | controller | ok 2025-09-23 00:14:12.267898 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-23 00:14:12.274402 | 2025-09-23 00:14:12.274472 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-23 00:14:12.546442 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-23 00:14:12.546918 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_ecdsa. 2025-09-23 00:14:12.547000 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_ecdsa.pub. 2025-09-23 00:14:12.547067 | controller -> localhost | The key fingerprint is: 2025-09-23 00:14:12.547122 | controller -> localhost | SHA256:15E77lRYtR3RYRZkP+/V22aOVkcDtzpwBqO3guUuc/8 zuul-build-sshkey 2025-09-23 00:14:12.547179 | controller -> localhost | The key's randomart image is: 2025-09-23 00:14:12.547240 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-23 00:14:12.547307 | controller -> localhost | | .X*| 2025-09-23 00:14:12.547378 | controller -> localhost | | o o+o*| 2025-09-23 00:14:12.547434 | controller -> localhost | | . = +o+| 2025-09-23 00:14:12.547475 | controller -> localhost | | o + B o=| 2025-09-23 00:14:12.547514 | controller -> localhost | | S o X o.=| 2025-09-23 00:14:12.547553 | controller -> localhost | | . + o = .*| 2025-09-23 00:14:12.547591 | controller -> localhost | | . . o .o*| 2025-09-23 00:14:12.547627 | controller -> localhost | | o o o .= | 2025-09-23 00:14:12.547663 | controller -> localhost | | + ..oE. .| 2025-09-23 00:14:12.547700 | controller -> localhost | +----[SHA256]-----+ 2025-09-23 00:14:12.547860 | controller -> localhost | ok: Runtime: 0:00:00.014320 2025-09-23 00:14:12.563520 | 2025-09-23 00:14:12.563963 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-23 00:14:12.595817 | controller | ok 2025-09-23 00:14:12.613374 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-23 00:14:12.631979 | 2025-09-23 00:14:12.632134 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-23 00:14:12.648301 | controller | skipping: Conditional result was False 2025-09-23 00:14:12.658231 | 2025-09-23 00:14:12.658345 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-23 00:14:13.504131 | controller | changed 2025-09-23 00:14:13.517865 | 2025-09-23 00:14:13.518037 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-23 00:14:15.019083 | controller | ok 2025-09-23 00:14:15.032071 | 2025-09-23 00:14:15.032461 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-23 00:14:17.420567 | controller | changed 2025-09-23 00:14:17.434570 | 2025-09-23 00:14:17.434981 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-23 00:14:19.062217 | controller | changed 2025-09-23 00:14:19.068706 | 2025-09-23 00:14:19.068839 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-23 00:14:19.146069 | controller | skipping: Conditional result was False 2025-09-23 00:14:19.186829 | 2025-09-23 00:14:19.186976 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-23 00:14:19.406131 | controller -> localhost | changed 2025-09-23 00:14:19.432466 | 2025-09-23 00:14:19.432675 | TASK [add-build-sshkey : Add back temp key] 2025-09-23 00:14:19.745537 | controller -> localhost | Identity added: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/eea14462c64741b9a0559f158eca6b93_id_ecdsa (zuul-build-sshkey) 2025-09-23 00:14:19.745936 | controller -> localhost | ok: Runtime: 0:00:00.014191 2025-09-23 00:14:19.760257 | 2025-09-23 00:14:19.760402 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-23 00:14:20.212594 | controller | ok 2025-09-23 00:14:20.224542 | 2025-09-23 00:14:20.224677 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-23 00:14:20.270524 | controller | skipping: Conditional result was False 2025-09-23 00:14:20.285838 | 2025-09-23 00:14:20.285965 | TASK [include_role : remove-zuul-sshkey] 2025-09-23 00:14:20.311100 | controller | skipping: Conditional result was False 2025-09-23 00:14:20.319441 | 2025-09-23 00:14:20.319536 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-23 00:14:20.759081 | controller | ok: "logs" 2025-09-23 00:14:20.759689 | controller | ok: All items complete 2025-09-23 00:14:20.759835 | 2025-09-23 00:14:21.159356 | controller | ok: "artifacts" 2025-09-23 00:14:21.533883 | controller | ok: "docs" 2025-09-23 00:14:21.546280 | 2025-09-23 00:14:21.546443 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-23 00:14:21.957076 | controller | changed: "logs" 2025-09-23 00:14:22.336243 | controller | changed: "artifacts" 2025-09-23 00:14:22.697876 | controller | changed: "docs" 2025-09-23 00:14:22.740889 | 2025-09-23 00:14:22.740996 | PLAY RECAP 2025-09-23 00:14:22.741055 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-23 00:14:22.741093 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-23 00:14:22.741120 | 2025-09-23 00:14:22.865337 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-23 00:14:22.866352 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-23 00:14:23.473823 | 2025-09-23 00:14:23.473935 | PLAY [all] 2025-09-23 00:14:23.495457 | 2025-09-23 00:14:23.495571 | TASK [Install binary dependencies] 2025-09-23 00:14:23.557488 | controller | ok 2025-09-23 00:14:23.576916 | 2025-09-23 00:14:23.577008 | TASK [bindep : Include find tasks] 2025-09-23 00:14:23.606686 | controller | ok 2025-09-23 00:14:23.615124 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-23 00:14:23.621670 | 2025-09-23 00:14:23.621770 | TASK [bindep : Look for bindep.txt] 2025-09-23 00:14:24.163340 | controller | ok 2025-09-23 00:14:24.185369 | 2025-09-23 00:14:24.185575 | TASK [bindep : Define bindep_file fact] 2025-09-23 00:14:24.212016 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.220566 | 2025-09-23 00:14:24.220669 | TASK [bindep : Look for other-requirements.txt] 2025-09-23 00:14:24.598879 | controller | ok 2025-09-23 00:14:24.607216 | 2025-09-23 00:14:24.607326 | TASK [bindep : Define bindep_file fact] 2025-09-23 00:14:24.632819 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.641218 | 2025-09-23 00:14:24.641333 | TASK [bindep : Look for bindep fallback file] 2025-09-23 00:14:24.667082 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.678337 | 2025-09-23 00:14:24.678500 | TASK [bindep : Define bindep_file fact] 2025-09-23 00:14:24.706020 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.719041 | 2025-09-23 00:14:24.719243 | TASK [bindep : Include bindep tasks] 2025-09-23 00:14:24.746798 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.756981 | 2025-09-23 00:14:24.757102 | TASK [bindep : Include install tasks] 2025-09-23 00:14:24.784819 | controller | skipping: Conditional result was False 2025-09-23 00:14:24.799067 | 2025-09-23 00:14:24.799201 | LOOP [bindep : Include package tasks] 2025-09-23 00:14:24.865013 | 2025-09-23 00:14:24.865175 | TASK [Run test-setup role] 2025-09-23 00:14:24.884702 | controller | ok 2025-09-23 00:14:24.902929 | 2025-09-23 00:14:24.903031 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-23 00:14:25.278812 | controller | ok 2025-09-23 00:14:25.284798 | 2025-09-23 00:14:25.284865 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-23 00:14:25.421104 | controller | skipping: Conditional result was False 2025-09-23 00:14:25.460786 | 2025-09-23 00:14:25.460959 | PLAY RECAP 2025-09-23 00:14:25.461025 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-23 00:14:25.461057 | 2025-09-23 00:14:25.569512 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-23 00:14:25.570429 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-23 00:14:26.199791 | 2025-09-23 00:14:26.199957 | PLAY [controller] 2025-09-23 00:14:26.223219 | 2025-09-23 00:14:26.223355 | TASK [Create the /root directory] 2025-09-23 00:14:27.005597 | controller | ok 2025-09-23 00:14:27.018268 | 2025-09-23 00:14:27.018438 | TASK [Install glibc-langpack-en] 2025-09-23 00:14:35.279418 | controller | ok: Nothing to do 2025-09-23 00:14:35.291105 | 2025-09-23 00:14:35.291240 | TASK [Ensure controller directory exists] 2025-09-23 00:14:35.766594 | controller | changed 2025-09-23 00:14:35.778400 | 2025-09-23 00:14:35.778537 | TASK [Install container runtime] 2025-09-23 00:14:35.851924 | controller | ok 2025-09-23 00:14:35.891416 | 2025-09-23 00:14:35.891598 | LOOP [ensure-podman : Find distribution installation] 2025-09-23 00:14:35.927324 | controller | ok: "/var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-23 00:14:35.944198 | controller | included: /var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-23 00:14:35.960990 | 2025-09-23 00:14:35.961150 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-23 00:15:54.952463 | controller | changed 2025-09-23 00:15:54.960068 | 2025-09-23 00:15:54.960186 | TASK [ensure-podman : Fetch podman version] 2025-09-23 00:15:55.715558 | controller | Client: Podman Engine 2025-09-23 00:15:55.742671 | controller | Version: 4.6.2 2025-09-23 00:15:55.742717 | controller | API Version: 4.6.2 2025-09-23 00:15:55.742724 | controller | Go Version: go1.19.12 2025-09-23 00:15:55.742740 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-23 00:15:55.742747 | controller | OS/Arch: linux/amd64 2025-09-23 00:15:56.096986 | controller | ok: Runtime: 0:00:00.227290 2025-09-23 00:15:56.109710 | 2025-09-23 00:15:56.109909 | TASK [ensure-podman : Print podman version installed] 2025-09-23 00:15:56.147357 | Podman version: Client: Podman Engine 2025-09-23 00:15:56.147773 | Version: 4.6.2 2025-09-23 00:15:56.147875 | API Version: 4.6.2 2025-09-23 00:15:56.147924 | Go Version: go1.19.12 2025-09-23 00:15:56.147965 | Built: Mon Aug 28 19:38:31 2023 2025-09-23 00:15:56.148006 | OS/Arch: linux/amd64 2025-09-23 00:15:56.159404 | 2025-09-23 00:15:56.159537 | TASK [ensure-podman : Validate podman engine] 2025-09-23 00:15:56.297339 | controller | skipping: Conditional result was False 2025-09-23 00:15:56.305718 | 2025-09-23 00:15:56.305882 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-23 00:15:56.331313 | controller | skipping: Conditional result was False 2025-09-23 00:15:56.345846 | 2025-09-23 00:15:56.345957 | TASK [Ensure python3.8 is present] 2025-09-23 00:15:56.373857 | controller | skipping: Conditional result was False 2025-09-23 00:15:56.383177 | 2025-09-23 00:15:56.383311 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-23 00:15:56.416771 | controller | ok 2025-09-23 00:15:56.448141 | 2025-09-23 00:15:56.448301 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-23 00:16:00.464539 | controller | ok: Nothing to do 2025-09-23 00:16:00.472099 | 2025-09-23 00:16:00.472221 | TASK [our-ensure-python : Also install python3-devel] 2025-09-23 00:16:13.963981 | controller | changed 2025-09-23 00:16:13.989837 | 2025-09-23 00:16:13.989981 | TASK [Run ensure-virtualenv role] 2025-09-23 00:16:14.011528 | controller | ok 2025-09-23 00:16:14.031220 | 2025-09-23 00:16:14.031315 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-23 00:16:14.388818 | controller | /usr/bin/virtualenv 2025-09-23 00:16:14.655074 | controller | ok: Runtime: 0:00:00.004745 2025-09-23 00:16:14.666054 | 2025-09-23 00:16:14.666184 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-23 00:16:14.689970 | controller | skipping: Conditional result was False 2025-09-23 00:16:14.690236 | controller | ok: All items complete 2025-09-23 00:16:14.690263 | 2025-09-23 00:16:14.715682 | 2025-09-23 00:16:14.715894 | TASK [Find the full path of the Python interpreter] 2025-09-23 00:16:15.152559 | controller | /usr/bin/python3 2025-09-23 00:16:15.354636 | controller | ok 2025-09-23 00:16:15.362692 | 2025-09-23 00:16:15.362823 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-23 00:16:16.793031 | controller | created virtual environment CPython3.11.0.final.0-64 in 748ms 2025-09-23 00:16:16.848762 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-23 00:16:16.848812 | 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-09-23 00:16:16.848828 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-23 00:16:16.848852 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-23 00:16:17.007893 | controller | changed 2025-09-23 00:16:17.020294 | 2025-09-23 00:16:17.020429 | TASK [Set selinux package] 2025-09-23 00:16:17.049425 | controller | ok 2025-09-23 00:16:17.060305 | 2025-09-23 00:16:17.060436 | TASK [Set selinux package (Fedora)] 2025-09-23 00:16:17.099704 | controller | ok 2025-09-23 00:16:17.110491 | 2025-09-23 00:16:17.110623 | TASK [Install selinux into virtualenv] 2025-09-23 00:16:19.737780 | controller | Collecting selinux-please-lie-to-me 2025-09-23 00:16:19.828463 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-23 00:16:20.360909 | controller | Collecting setuptools<50.0.0 2025-09-23 00:16:20.374641 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-23 00:16:20.500734 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-09-23 00:16:20.656838 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-23 00:16:20.657288 | controller | Attempting uninstall: setuptools 2025-09-23 00:16:20.662275 | controller | Found existing installation: setuptools 62.6.0 2025-09-23 00:16:20.776179 | controller | Uninstalling setuptools-62.6.0: 2025-09-23 00:16:20.791692 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-23 00:16:21.511287 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-23 00:16:21.722684 | controller | 2025-09-23 00:16:21.937632 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-23 00:16:21.937684 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-23 00:16:22.299660 | controller | ok: Runtime: 0:00:04.334370 2025-09-23 00:16:22.309307 | 2025-09-23 00:16:22.309480 | TASK [Install pytest-forked into virtualenv] 2025-09-23 00:16:23.582250 | controller | Collecting pytest-forked 2025-09-23 00:16:23.670939 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-23 00:16:23.731689 | controller | Collecting py 2025-09-23 00:16:23.745130 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-23 00:16:23.779964 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-09-23 00:16:23.949009 | controller | Collecting pytest>=3.10 2025-09-23 00:16:23.962471 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-23 00:16:24.026013 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.0 MB/s eta 0:00:00 2025-09-23 00:16:24.079284 | controller | Collecting iniconfig>=1 2025-09-23 00:16:24.092702 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-23 00:16:24.160425 | controller | Collecting packaging>=20 2025-09-23 00:16:24.173115 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-23 00:16:24.186373 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.2 MB/s eta 0:00:00 2025-09-23 00:16:24.233167 | controller | Collecting pluggy<2,>=1.5 2025-09-23 00:16:24.247415 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-23 00:16:24.322316 | controller | Collecting pygments>=2.7.2 2025-09-23 00:16:24.335417 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-23 00:16:24.460984 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.0 MB/s eta 0:00:00 2025-09-23 00:16:24.594250 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-23 00:16:26.901380 | 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-09-23 00:16:26.917779 | controller | 2025-09-23 00:16:27.104338 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-23 00:16:27.104383 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-23 00:16:27.513892 | controller | ok: Runtime: 0:00:04.276768 2025-09-23 00:16:27.522354 | 2025-09-23 00:16:27.522483 | TASK [Update pip] 2025-09-23 00:16:28.640535 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-23 00:16:28.912188 | controller | Collecting pip 2025-09-23 00:16:29.017462 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-23 00:16:29.212546 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.2 MB/s eta 0:00:00 2025-09-23 00:16:29.371936 | controller | Installing collected packages: pip 2025-09-23 00:16:29.372379 | controller | Attempting uninstall: pip 2025-09-23 00:16:29.376894 | controller | Found existing installation: pip 22.2.2 2025-09-23 00:16:29.640000 | controller | Uninstalling pip-22.2.2: 2025-09-23 00:16:29.670134 | controller | Successfully uninstalled pip-22.2.2 2025-09-23 00:16:31.511905 | controller | Successfully installed pip-25.2 2025-09-23 00:16:32.173353 | controller | ok: Runtime: 0:00:03.663663 2025-09-23 00:16:32.182022 | 2025-09-23 00:16:32.182158 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-23 00:16:32.692879 | controller | changed 2025-09-23 00:16:32.698547 | 2025-09-23 00:16:32.698620 | TASK [Install ansible into virtualenv] 2025-09-23 00:16:33.818189 | controller | Processing ./src/github.com/ansible/ansible 2025-09-23 00:16:33.824650 | controller | Installing build dependencies: started 2025-09-23 00:16:35.890546 | controller | Installing build dependencies: finished with status 'done' 2025-09-23 00:16:37.433979 | controller | Getting requirements to build wheel: started 2025-09-23 00:16:37.434049 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-23 00:16:37.435541 | controller | Preparing metadata (pyproject.toml): started 2025-09-23 00:16:38.364205 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-23 00:16:38.368979 | 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-09-23 00:16:38.373880 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-23 00:16:38.837490 | controller | ERROR 2025-09-23 00:16:38.837957 | controller | { 2025-09-23 00:16:38.838049 | controller | "delta": "0:00:05.371546", 2025-09-23 00:16:38.838109 | controller | "end": "2025-09-23 00:16:38.525761", 2025-09-23 00:16:38.838158 | controller | "msg": "non-zero return code", 2025-09-23 00:16:38.838244 | controller | "rc": 1, 2025-09-23 00:16:38.838298 | controller | "start": "2025-09-23 00:16:33.154215" 2025-09-23 00:16:38.838345 | controller | } failure 2025-09-23 00:16:38.841466 | 2025-09-23 00:16:38.841614 | PLAY RECAP 2025-09-23 00:16:38.841700 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-23 00:16:38.841806 | 2025-09-23 00:16:39.051105 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-23 00:16:39.052171 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-23 00:16:39.691688 | 2025-09-23 00:16:39.691837 | PLAY [all] 2025-09-23 00:16:39.713934 | 2025-09-23 00:16:39.714066 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-23 00:16:40.519748 | controller | changed: non-zero return code 2025-09-23 00:16:40.525670 | 2025-09-23 00:16:40.525777 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-23 00:16:40.549843 | controller | skipping: Conditional result was False 2025-09-23 00:16:40.556159 | 2025-09-23 00:16:40.556403 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-23 00:16:40.587796 | 2025-09-23 00:16:40.587967 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-23 00:16:40.617598 | 2025-09-23 00:16:40.617812 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-23 00:16:40.641689 | controller | skipping: Conditional result was False 2025-09-23 00:16:40.647718 | 2025-09-23 00:16:40.647810 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-23 00:16:40.685504 | 2025-09-23 00:16:40.685959 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-23 00:16:40.703458 | controller | skipping: Conditional result was False 2025-09-23 00:16:40.717928 | 2025-09-23 00:16:40.718099 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-23 00:16:40.734189 | controller | skipping: Conditional result was False 2025-09-23 00:16:40.743835 | 2025-09-23 00:16:40.743986 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-23 00:16:40.768684 | controller | skipping: Conditional result was False 2025-09-23 00:16:40.817214 | 2025-09-23 00:16:40.817339 | PLAY RECAP 2025-09-23 00:16:40.817397 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-23 00:16:40.817427 | 2025-09-23 00:16:40.917073 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-23 00:16:40.918025 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-23 00:16:41.483230 | 2025-09-23 00:16:41.483344 | PLAY [all:!appliance*] 2025-09-23 00:16:41.505643 | 2025-09-23 00:16:41.505760 | TASK [unregister the node] 2025-09-23 00:16:41.637474 | controller | skipping: Conditional result was False 2025-09-23 00:16:41.643709 | 2025-09-23 00:16:41.643809 | TASK [include_role : fetch-output] 2025-09-23 00:16:41.691618 | controller | ok 2025-09-23 00:16:41.731616 | 2025-09-23 00:16:41.731758 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-23 00:16:41.808351 | controller | skipping: Conditional result was False 2025-09-23 00:16:41.822284 | 2025-09-23 00:16:41.822483 | TASK [fetch-output : Set log path for single node] 2025-09-23 00:16:41.873407 | controller | ok 2025-09-23 00:16:41.886907 | 2025-09-23 00:16:41.887111 | LOOP [fetch-output : Ensure local output dirs] 2025-09-23 00:16:42.339841 | controller -> localhost | ok: "/var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/logs" 2025-09-23 00:16:42.609447 | controller -> localhost | changed: "/var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/artifacts" 2025-09-23 00:16:42.893624 | controller -> localhost | changed: "/var/lib/zuul/builds/eea14462c64741b9a0559f158eca6b93/work/docs" 2025-09-23 00:16:42.911447 | 2025-09-23 00:16:42.911640 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-23 00:16:44.185492 | controller | changed: 2025-09-23 00:16:44.186051 | controller | .d..t...... ./ 2025-09-23 00:16:44.186121 | controller | cd+++++++++ controller/ 2025-09-23 00:16:44.186191 | controller | changed: All items complete 2025-09-23 00:16:44.186236 | 2025-09-23 00:16:45.255656 | controller | changed: .d..t...... ./ 2025-09-23 00:16:46.272794 | controller | changed: .d..t...... ./ 2025-09-23 00:16:46.309310 | 2025-09-23 00:16:46.309459 | TASK [include_role : fetch-output-openshift] 2025-09-23 00:16:46.334593 | controller | skipping: Conditional result was False 2025-09-23 00:16:46.342780 | 2025-09-23 00:16:46.342879 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-23 00:16:46.375883 | controller | skipping: Conditional result was False 2025-09-23 00:16:46.391771 | controller | skipping: Conditional result was False 2025-09-23 00:16:46.426783 | 2025-09-23 00:16:46.426935 | PLAY [localhost] 2025-09-23 00:16:46.439086 | 2025-09-23 00:16:46.439190 | TASK [Run Zuul manifest role] 2025-09-23 00:16:46.457566 | localhost | ok 2025-09-23 00:16:46.471096 | 2025-09-23 00:16:46.471189 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-23 00:16:46.880550 | localhost | changed 2025-09-23 00:16:46.886075 | 2025-09-23 00:16:46.886165 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-23 00:16:46.914315 | localhost | ok 2025-09-23 00:16:46.922663 | 2025-09-23 00:16:46.922796 | TASK [Set zuul-log-path fact] 2025-09-23 00:16:46.951245 | localhost | ok 2025-09-23 00:16:46.970539 | 2025-09-23 00:16:46.970645 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-23 00:16:46.999155 | localhost | ok 2025-09-23 00:16:47.008829 | 2025-09-23 00:16:47.008890 | LOOP [Run upload-logs-swift role] 2025-09-23 00:16:47.032991 | localhost | Output suppressed because no_log was given 2025-09-23 00:16:47.057037 | 2025-09-23 00:16:47.057153 | TASK [Set zuul-log-path fact] 2025-09-23 00:16:47.081625 | localhost | skipping: Conditional result was False 2025-09-23 00:16:47.087337 | 2025-09-23 00:16:47.087467 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-23 00:16:47.591797 | localhost -> localhost | ok: Runtime: 0:00:00.005115 2025-09-23 00:16:47.599414 | 2025-09-23 00:16:47.599553 | TASK [upload-logs-swift : Upload logs to swift]