2025-12-30 00:06:39.180418 | Job console starting... 2025-12-30 00:06:39.190399 | Updating repositories 2025-12-30 00:06:39.406965 | Preparing job workspace 2025-12-30 00:06:48.073250 | Running Ansible setup... 2025-12-30 00:06:54.754262 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-30 00:06:55.539050 | 2025-12-30 00:06:55.539246 | PLAY [localhost] 2025-12-30 00:06:55.548863 | 2025-12-30 00:06:55.548943 | TASK [Gathering Facts] 2025-12-30 00:06:56.611515 | localhost | ok 2025-12-30 00:06:56.629472 | 2025-12-30 00:06:56.629586 | TASK [Setup log path fact] 2025-12-30 00:06:56.648178 | localhost | ok 2025-12-30 00:06:56.661461 | 2025-12-30 00:06:56.661570 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-30 00:06:56.690536 | localhost | ok 2025-12-30 00:06:56.698728 | 2025-12-30 00:06:56.698861 | TASK [emit-job-header : Print job information] 2025-12-30 00:06:56.739123 | # Job Information 2025-12-30 00:06:56.739305 | Ansible Version: 2.15.12 2025-12-30 00:06:56.739349 | Job: ansible-test-sanity-docker-milestone 2025-12-30 00:06:56.739379 | Pipeline: periodic 2025-12-30 00:06:56.739405 | Executor: ze01.softwarefactory-project.io 2025-12-30 00:06:56.739431 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-30 00:06:56.739462 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/389/ansible/3897fa97ee4f4000aa5e25ba3816f787/ 2025-12-30 00:06:56.739489 | Event ID: 3253ff496aa2446d86190793a25a6b45 2025-12-30 00:06:56.746065 | 2025-12-30 00:06:56.746156 | LOOP [emit-job-header : Print node information] 2025-12-30 00:06:56.879947 | localhost | ok: 2025-12-30 00:06:56.880128 | localhost | # Node Information 2025-12-30 00:06:56.880156 | localhost | Inventory Hostname: controller 2025-12-30 00:06:56.880177 | localhost | Hostname: np0005572374 2025-12-30 00:06:56.880196 | localhost | Username: zuul 2025-12-30 00:06:56.880220 | localhost | Distro: Fedora 37 2025-12-30 00:06:56.880239 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-30 00:06:56.880257 | localhost | Region: ca-ymq-1 2025-12-30 00:06:56.880274 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-30 00:06:56.880291 | localhost | Product Name: OpenStack Nova 2025-12-30 00:06:56.880308 | localhost | Interface IP: 162.253.55.74 2025-12-30 00:06:56.891207 | 2025-12-30 00:06:56.891328 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-30 00:06:57.315906 | localhost -> localhost | changed 2025-12-30 00:06:57.321595 | 2025-12-30 00:06:57.321677 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-30 00:06:58.761550 | localhost -> localhost | changed 2025-12-30 00:06:58.793587 | 2025-12-30 00:06:58.793673 | PLAY [all:!appliance*] 2025-12-30 00:06:58.810801 | 2025-12-30 00:06:58.810927 | TASK [include_role : start-zuul-console] 2025-12-30 00:06:58.831643 | controller | ok 2025-12-30 00:06:58.844642 | 2025-12-30 00:06:58.844910 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-30 00:06:59.225172 | controller | ok 2025-12-30 00:06:59.237123 | 2025-12-30 00:06:59.237223 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-30 00:07:06.805135 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-30 00:07:06.818265 | 2025-12-30 00:07:06.818445 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-30 00:07:07.361977 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.373271 | 2025-12-30 00:07:07.373398 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-30 00:07:07.398951 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.409470 | 2025-12-30 00:07:07.409607 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-30 00:07:07.435481 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.444848 | 2025-12-30 00:07:07.444944 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-30 00:07:07.469744 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.478752 | 2025-12-30 00:07:07.478847 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-30 00:07:07.504448 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.513308 | 2025-12-30 00:07:07.513399 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-30 00:07:07.538883 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.586237 | 2025-12-30 00:07:07.586357 | TASK [Disable Fedora Modular] 2025-12-30 00:07:07.925310 | controller | changed 2025-12-30 00:07:07.934535 | 2025-12-30 00:07:07.934634 | TASK [Enable EPEL] 2025-12-30 00:07:07.969917 | controller | skipping: Conditional result was False 2025-12-30 00:07:07.979009 | 2025-12-30 00:07:07.979126 | TASK [Register the RHEL node] 2025-12-30 00:07:08.537329 | 2025-12-30 00:07:08.537638 | TASK [Show the subscription-manager status] 2025-12-30 00:07:09.114958 | controller | skipping: Conditional result was False 2025-12-30 00:07:09.131055 | 2025-12-30 00:07:09.131196 | TASK [Enable EPEL on RHEL] 2025-12-30 00:07:09.707315 | controller | skipping: Conditional result was False 2025-12-30 00:07:09.720487 | 2025-12-30 00:07:09.720638 | TASK [Install git and tox] 2025-12-30 00:08:07.541771 | controller | changed 2025-12-30 00:08:07.548830 | 2025-12-30 00:08:07.548963 | TASK [include_role : prepare-workspace] 2025-12-30 00:08:07.582766 | controller | ok 2025-12-30 00:08:07.612826 | 2025-12-30 00:08:07.612991 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-30 00:08:07.860642 | controller | ok 2025-12-30 00:08:07.867622 | 2025-12-30 00:08:07.867910 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-30 00:08:27.801640 | controller | Output suppressed because no_log was given 2025-12-30 00:08:27.813914 | 2025-12-30 00:08:27.814004 | TASK [include_role : prepare-workspace-openshift] 2025-12-30 00:08:27.830662 | controller | skipping: Conditional result was False 2025-12-30 00:08:27.853086 | 2025-12-30 00:08:27.853181 | PLAY [all:!appliance] 2025-12-30 00:08:27.870372 | 2025-12-30 00:08:27.870494 | TASK [Run add-build-sshkey role (RSA)] 2025-12-30 00:08:27.899985 | controller | ok 2025-12-30 00:08:27.915656 | 2025-12-30 00:08:27.915774 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-30 00:08:28.229260 | controller -> localhost | ok 2025-12-30 00:08:28.239936 | 2025-12-30 00:08:28.240164 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-30 00:08:28.265939 | controller | ok 2025-12-30 00:08:28.290921 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-30 00:08:28.300635 | 2025-12-30 00:08:28.300743 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-30 00:08:28.773897 | controller -> localhost | Generating public/private rsa key pair. 2025-12-30 00:08:28.774166 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_rsa. 2025-12-30 00:08:28.774208 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_rsa.pub. 2025-12-30 00:08:28.774239 | controller -> localhost | The key fingerprint is: 2025-12-30 00:08:28.774263 | controller -> localhost | SHA256:SXYs8GhOc3R+LhpHHBtFeEJbbMqWff32GLFbqec7XHQ zuul-build-sshkey 2025-12-30 00:08:28.774286 | controller -> localhost | The key's randomart image is: 2025-12-30 00:08:28.774309 | controller -> localhost | +---[RSA 2048]----+ 2025-12-30 00:08:28.774330 | controller -> localhost | | . ..==+ | 2025-12-30 00:08:28.774352 | controller -> localhost | | = =o*+ | 2025-12-30 00:08:28.774373 | controller -> localhost | | = *.OB. . | 2025-12-30 00:08:28.774393 | controller -> localhost | | + = ==o. o E| 2025-12-30 00:08:28.774414 | controller -> localhost | | . S.o .. ++| 2025-12-30 00:08:28.774446 | controller -> localhost | | + . o.=| 2025-12-30 00:08:28.774473 | controller -> localhost | | . o*o| 2025-12-30 00:08:28.774497 | controller -> localhost | | .o+.| 2025-12-30 00:08:28.774519 | controller -> localhost | | ooo| 2025-12-30 00:08:28.774542 | controller -> localhost | +----[SHA256]-----+ 2025-12-30 00:08:28.774599 | controller -> localhost | ok: Runtime: 0:00:00.071629 2025-12-30 00:08:28.783431 | 2025-12-30 00:08:28.783517 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-30 00:08:28.827259 | controller | ok 2025-12-30 00:08:28.841303 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-30 00:08:28.854245 | 2025-12-30 00:08:28.854358 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-30 00:08:28.868709 | controller | skipping: Conditional result was False 2025-12-30 00:08:28.876730 | 2025-12-30 00:08:28.876822 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-30 00:08:29.332637 | controller | changed 2025-12-30 00:08:29.344531 | 2025-12-30 00:08:29.344635 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-30 00:08:29.579252 | controller | ok 2025-12-30 00:08:29.587798 | 2025-12-30 00:08:29.587889 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-30 00:08:30.258667 | controller | changed 2025-12-30 00:08:30.274162 | 2025-12-30 00:08:30.274356 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-30 00:08:30.915925 | controller | changed 2025-12-30 00:08:30.924998 | 2025-12-30 00:08:30.925137 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-30 00:08:30.950262 | controller | skipping: Conditional result was False 2025-12-30 00:08:30.959384 | 2025-12-30 00:08:30.959479 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-30 00:08:31.415847 | controller -> localhost | changed 2025-12-30 00:08:31.428451 | 2025-12-30 00:08:31.428565 | TASK [add-build-sshkey : Add back temp key] 2025-12-30 00:08:31.731404 | controller -> localhost | Identity added: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_rsa (zuul-build-sshkey) 2025-12-30 00:08:31.731799 | controller -> localhost | ok: Runtime: 0:00:00.013641 2025-12-30 00:08:31.747283 | 2025-12-30 00:08:31.747457 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-30 00:08:32.111256 | controller | ok 2025-12-30 00:08:32.129362 | 2025-12-30 00:08:32.129478 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-30 00:08:32.155815 | controller | skipping: Conditional result was False 2025-12-30 00:08:32.175220 | 2025-12-30 00:08:32.175371 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-30 00:08:32.205687 | controller | ok 2025-12-30 00:08:32.223223 | 2025-12-30 00:08:32.223346 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-30 00:08:32.471070 | controller -> localhost | ok 2025-12-30 00:08:32.480571 | 2025-12-30 00:08:32.480677 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-30 00:08:32.511169 | controller | ok 2025-12-30 00:08:32.522649 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-30 00:08:32.529082 | 2025-12-30 00:08:32.529146 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-30 00:08:32.869820 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-30 00:08:32.870070 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_ecdsa. 2025-12-30 00:08:32.870100 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_ecdsa.pub. 2025-12-30 00:08:32.870130 | controller -> localhost | The key fingerprint is: 2025-12-30 00:08:32.870151 | controller -> localhost | SHA256:ZUeHZfp2malhQ2pbeaiB6cTpLDP6uxL7wrsksrKNH00 zuul-build-sshkey 2025-12-30 00:08:32.870169 | controller -> localhost | The key's randomart image is: 2025-12-30 00:08:32.870187 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-30 00:08:32.870204 | controller -> localhost | | .o+ | 2025-12-30 00:08:32.870221 | controller -> localhost | | ..+ | 2025-12-30 00:08:32.870237 | controller -> localhost | | o o. | 2025-12-30 00:08:32.870254 | controller -> localhost | | .o+.o.o +| 2025-12-30 00:08:32.870270 | controller -> localhost | | E S* + Bo=.| 2025-12-30 00:08:32.870286 | controller -> localhost | | o . = . *.=. | 2025-12-30 00:08:32.870302 | controller -> localhost | | ...o.o+ + o . | 2025-12-30 00:08:32.870318 | controller -> localhost | |.oo.o=. + | 2025-12-30 00:08:32.870334 | controller -> localhost | |++o +B=o | 2025-12-30 00:08:32.870350 | controller -> localhost | +----[SHA256]-----+ 2025-12-30 00:08:32.870403 | controller -> localhost | ok: Runtime: 0:00:00.016312 2025-12-30 00:08:32.877994 | 2025-12-30 00:08:32.878094 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-30 00:08:32.909773 | controller | ok 2025-12-30 00:08:32.918478 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-30 00:08:32.930821 | 2025-12-30 00:08:32.930924 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-30 00:08:32.955795 | controller | skipping: Conditional result was False 2025-12-30 00:08:32.963335 | 2025-12-30 00:08:32.963434 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-30 00:08:33.252516 | controller | changed 2025-12-30 00:08:33.262368 | 2025-12-30 00:08:33.262485 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-30 00:08:33.478288 | controller | ok 2025-12-30 00:08:33.485670 | 2025-12-30 00:08:33.485785 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-30 00:08:34.158749 | controller | changed 2025-12-30 00:08:34.168763 | 2025-12-30 00:08:34.168858 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-30 00:08:34.805341 | controller | changed 2025-12-30 00:08:34.811453 | 2025-12-30 00:08:34.811526 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-30 00:08:34.845692 | controller | skipping: Conditional result was False 2025-12-30 00:08:34.855900 | 2025-12-30 00:08:34.856038 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-30 00:08:35.126891 | controller -> localhost | changed 2025-12-30 00:08:35.140237 | 2025-12-30 00:08:35.140380 | TASK [add-build-sshkey : Add back temp key] 2025-12-30 00:08:35.491308 | controller -> localhost | Identity added: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/3897fa97ee4f4000aa5e25ba3816f787_id_ecdsa (zuul-build-sshkey) 2025-12-30 00:08:35.491686 | controller -> localhost | ok: Runtime: 0:00:00.009282 2025-12-30 00:08:35.508253 | 2025-12-30 00:08:35.508433 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-30 00:08:35.731758 | controller | ok 2025-12-30 00:08:35.747208 | 2025-12-30 00:08:35.747375 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-30 00:08:35.795255 | controller | skipping: Conditional result was False 2025-12-30 00:08:35.823572 | 2025-12-30 00:08:35.823753 | TASK [include_role : remove-zuul-sshkey] 2025-12-30 00:08:35.852838 | controller | skipping: Conditional result was False 2025-12-30 00:08:35.868711 | 2025-12-30 00:08:35.868900 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-30 00:08:36.106089 | controller | ok: "logs" 2025-12-30 00:08:36.106979 | controller | ok: All items complete 2025-12-30 00:08:36.107109 | 2025-12-30 00:08:36.314120 | controller | ok: "artifacts" 2025-12-30 00:08:36.496820 | controller | ok: "docs" 2025-12-30 00:08:36.507386 | 2025-12-30 00:08:36.507473 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-30 00:08:36.752492 | controller | changed: "logs" 2025-12-30 00:08:36.936221 | controller | changed: "artifacts" 2025-12-30 00:08:37.126940 | controller | changed: "docs" 2025-12-30 00:08:37.153909 | 2025-12-30 00:08:37.153960 | PLAY RECAP 2025-12-30 00:08:37.154000 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-30 00:08:37.154045 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-30 00:08:37.154065 | 2025-12-30 00:08:37.257064 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-30 00:08:37.258225 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-30 00:08:37.874267 | 2025-12-30 00:08:37.874438 | PLAY [all] 2025-12-30 00:08:37.899262 | 2025-12-30 00:08:37.899399 | TASK [Install binary dependencies] 2025-12-30 00:08:37.960001 | controller | ok 2025-12-30 00:08:37.981544 | 2025-12-30 00:08:37.981678 | TASK [bindep : Include find tasks] 2025-12-30 00:08:38.032628 | controller | ok 2025-12-30 00:08:38.040736 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-30 00:08:38.047326 | 2025-12-30 00:08:38.047419 | TASK [bindep : Look for bindep.txt] 2025-12-30 00:08:38.405449 | controller | ok 2025-12-30 00:08:38.422053 | 2025-12-30 00:08:38.422367 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:08:38.450750 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.459891 | 2025-12-30 00:08:38.459992 | TASK [bindep : Look for other-requirements.txt] 2025-12-30 00:08:38.685525 | controller | ok 2025-12-30 00:08:38.699571 | 2025-12-30 00:08:38.699780 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:08:38.737706 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.752643 | 2025-12-30 00:08:38.752795 | TASK [bindep : Look for bindep fallback file] 2025-12-30 00:08:38.801000 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.818708 | 2025-12-30 00:08:38.818897 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:08:38.855553 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.864831 | 2025-12-30 00:08:38.864923 | TASK [bindep : Include bindep tasks] 2025-12-30 00:08:38.900837 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.915896 | 2025-12-30 00:08:38.916112 | TASK [bindep : Include install tasks] 2025-12-30 00:08:38.943444 | controller | skipping: Conditional result was False 2025-12-30 00:08:38.957398 | 2025-12-30 00:08:38.957550 | LOOP [bindep : Include package tasks] 2025-12-30 00:08:39.040430 | 2025-12-30 00:08:39.040719 | TASK [Run test-setup role] 2025-12-30 00:08:39.073576 | controller | ok 2025-12-30 00:08:39.102180 | 2025-12-30 00:08:39.102343 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-30 00:08:39.320215 | controller | ok 2025-12-30 00:08:39.329456 | 2025-12-30 00:08:39.329564 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-30 00:08:39.880069 | controller | skipping: Conditional result was False 2025-12-30 00:08:39.964485 | 2025-12-30 00:08:39.964627 | PLAY RECAP 2025-12-30 00:08:39.964677 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-30 00:08:39.964699 | 2025-12-30 00:08:40.085166 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-30 00:08:40.086047 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-30 00:08:40.747674 | 2025-12-30 00:08:40.747810 | PLAY [controller] 2025-12-30 00:08:40.768725 | 2025-12-30 00:08:40.768838 | TASK [Create the /root directory] 2025-12-30 00:08:41.163186 | controller | ok 2025-12-30 00:08:41.175966 | 2025-12-30 00:08:41.176149 | TASK [Install glibc-langpack-en] 2025-12-30 00:08:45.091325 | controller | ok: Nothing to do 2025-12-30 00:08:45.106503 | 2025-12-30 00:08:45.106707 | TASK [Ensure controller directory exists] 2025-12-30 00:08:45.325424 | controller | changed 2025-12-30 00:08:45.331990 | 2025-12-30 00:08:45.332101 | TASK [Install container runtime] 2025-12-30 00:08:45.381487 | controller | ok 2025-12-30 00:08:45.423811 | 2025-12-30 00:08:45.423937 | LOOP [ensure-podman : Find distribution installation] 2025-12-30 00:08:45.461069 | controller | ok: "/var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-30 00:08:45.485661 | controller | included: /var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-30 00:08:45.495813 | 2025-12-30 00:08:45.495911 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-30 00:09:51.427732 | controller | changed 2025-12-30 00:09:51.435463 | 2025-12-30 00:09:51.435580 | TASK [ensure-podman : Fetch podman version] 2025-12-30 00:09:51.934705 | controller | Client: Podman Engine 2025-12-30 00:09:51.934796 | controller | Version: 4.6.2 2025-12-30 00:09:51.934841 | controller | API Version: 4.6.2 2025-12-30 00:09:51.934883 | controller | Go Version: go1.19.12 2025-12-30 00:09:51.934934 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-30 00:09:51.934994 | controller | OS/Arch: linux/amd64 2025-12-30 00:09:52.008030 | controller | ok: Runtime: 0:00:00.167304 2025-12-30 00:09:52.018497 | 2025-12-30 00:09:52.018706 | TASK [ensure-podman : Print podman version installed] 2025-12-30 00:09:52.064499 | Podman version: Client: Podman Engine 2025-12-30 00:09:52.064812 | Version: 4.6.2 2025-12-30 00:09:52.064852 | API Version: 4.6.2 2025-12-30 00:09:52.064881 | Go Version: go1.19.12 2025-12-30 00:09:52.064906 | Built: Mon Aug 28 19:38:31 2023 2025-12-30 00:09:52.064931 | OS/Arch: linux/amd64 2025-12-30 00:09:52.078928 | 2025-12-30 00:09:52.079093 | TASK [ensure-podman : Validate podman engine] 2025-12-30 00:09:52.624667 | controller | skipping: Conditional result was False 2025-12-30 00:09:52.634781 | 2025-12-30 00:09:52.634975 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-30 00:09:52.671206 | controller | skipping: Conditional result was False 2025-12-30 00:09:52.695112 | 2025-12-30 00:09:52.695244 | TASK [Ensure python3.8 is present] 2025-12-30 00:09:52.710100 | controller | skipping: Conditional result was False 2025-12-30 00:09:52.721093 | 2025-12-30 00:09:52.721308 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-30 00:09:52.755567 | controller | ok 2025-12-30 00:09:52.832669 | 2025-12-30 00:09:52.832798 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-30 00:09:54.198816 | controller | ok: Nothing to do 2025-12-30 00:09:54.210755 | 2025-12-30 00:09:54.210956 | TASK [our-ensure-python : Also install python3-devel] 2025-12-30 00:10:03.914935 | controller | changed 2025-12-30 00:10:03.940835 | 2025-12-30 00:10:03.940952 | TASK [Run ensure-virtualenv role] 2025-12-30 00:10:04.021601 | controller | ok 2025-12-30 00:10:04.062948 | 2025-12-30 00:10:04.063119 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-30 00:10:04.394878 | controller | /usr/bin/virtualenv 2025-12-30 00:10:04.712998 | controller | ok: Runtime: 0:00:00.004425 2025-12-30 00:10:04.720612 | 2025-12-30 00:10:04.720715 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-30 00:10:04.777109 | controller | skipping: Conditional result was False 2025-12-30 00:10:04.777371 | controller | ok: All items complete 2025-12-30 00:10:04.777399 | 2025-12-30 00:10:04.795700 | 2025-12-30 00:10:04.795845 | TASK [Find the full path of the Python interpreter] 2025-12-30 00:10:05.091844 | controller | /usr/bin/python3 2025-12-30 00:10:05.368996 | controller | ok 2025-12-30 00:10:05.378598 | 2025-12-30 00:10:05.378725 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-30 00:10:06.376515 | controller | created virtual environment CPython3.11.0.final.0-64 in 451ms 2025-12-30 00:10:06.393100 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-30 00:10:06.393115 | 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-12-30 00:10:06.393130 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-30 00:10:06.393143 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-30 00:10:06.467318 | controller | changed 2025-12-30 00:10:06.487636 | 2025-12-30 00:10:06.487761 | TASK [Set selinux package] 2025-12-30 00:10:06.546532 | controller | ok 2025-12-30 00:10:06.570742 | 2025-12-30 00:10:06.571126 | TASK [Set selinux package (Fedora)] 2025-12-30 00:10:06.632349 | controller | ok 2025-12-30 00:10:06.640675 | 2025-12-30 00:10:06.640802 | TASK [Install selinux into virtualenv] 2025-12-30 00:10:32.167048 | controller | Collecting selinux-please-lie-to-me 2025-12-30 00:10:44.401485 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-30 00:10:44.727798 | controller | Collecting setuptools<50.0.0 2025-12-30 00:10:44.733748 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-30 00:10:44.799277 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 13.4 MB/s eta 0:00:00 2025-12-30 00:10:44.878490 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-30 00:10:44.878669 | controller | Attempting uninstall: setuptools 2025-12-30 00:10:44.881009 | controller | Found existing installation: setuptools 62.6.0 2025-12-30 00:10:44.939380 | controller | Uninstalling setuptools-62.6.0: 2025-12-30 00:10:44.947274 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-30 00:10:45.287084 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-30 00:10:58.700245 | controller | 2025-12-30 00:10:58.785066 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-30 00:10:58.785107 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-30 00:10:59.230656 | controller | ok: Runtime: 0:00:51.917709 2025-12-30 00:10:59.251861 | 2025-12-30 00:10:59.252045 | TASK [Install pytest-forked into virtualenv] 2025-12-30 00:11:19.320718 | controller | Collecting pytest-forked 2025-12-30 00:11:31.568770 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-30 00:11:31.608569 | controller | Collecting py 2025-12-30 00:11:31.612884 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-30 00:11:31.633895 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.4 MB/s eta 0:00:00 2025-12-30 00:11:31.743103 | controller | Collecting pytest>=3.10 2025-12-30 00:11:31.747401 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-30 00:11:31.765822 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 25.4 MB/s eta 0:00:00 2025-12-30 00:11:31.801822 | controller | Collecting iniconfig>=1.0.1 2025-12-30 00:11:31.805845 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-30 00:11:31.846095 | controller | Collecting packaging>=22 2025-12-30 00:11:31.851621 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-30 00:11:31.857740 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 18.6 MB/s eta 0:00:00 2025-12-30 00:11:31.889551 | controller | Collecting pluggy<2,>=1.5 2025-12-30 00:11:31.892794 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-30 00:11:31.937399 | controller | Collecting pygments>=2.7.2 2025-12-30 00:11:31.962599 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-30 00:11:32.007871 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 30.2 MB/s eta 0:00:00 2025-12-30 00:11:32.078098 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-30 00:11:33.148262 | 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.2 pytest-forked-1.6.0 2025-12-30 00:11:33.157182 | controller | 2025-12-30 00:11:33.234413 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-30 00:11:33.234453 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-30 00:11:33.337762 | controller | ok: Runtime: 0:00:33.741640 2025-12-30 00:11:33.347011 | 2025-12-30 00:11:33.347148 | TASK [Update pip] 2025-12-30 00:11:33.868348 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-30 00:11:58.266189 | controller | Collecting pip 2025-12-30 00:12:10.423593 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-30 00:12:10.499994 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 25.0 MB/s eta 0:00:00 2025-12-30 00:12:10.563091 | controller | Installing collected packages: pip 2025-12-30 00:12:10.563217 | controller | Attempting uninstall: pip 2025-12-30 00:12:10.565326 | controller | Found existing installation: pip 22.2.2 2025-12-30 00:12:10.701539 | controller | Uninstalling pip-22.2.2: 2025-12-30 00:12:10.716245 | controller | Successfully uninstalled pip-22.2.2 2025-12-30 00:12:11.526790 | controller | Successfully installed pip-25.3 2025-12-30 00:12:11.909637 | controller | ok: Runtime: 0:00:38.066820 2025-12-30 00:12:11.916865 | 2025-12-30 00:12:11.916958 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-30 00:12:12.133892 | controller | changed 2025-12-30 00:12:12.192854 | 2025-12-30 00:12:12.193002 | TASK [Install ansible into virtualenv] 2025-12-30 00:12:12.698764 | controller | Processing ./src/github.com/ansible/ansible 2025-12-30 00:12:12.702072 | controller | Installing build dependencies: started 2025-12-30 00:12:47.672278 | controller | Installing build dependencies: finished with status 'done' 2025-12-30 00:12:47.674707 | controller | Getting requirements to build wheel: started 2025-12-30 00:12:48.399464 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-30 00:12:48.400915 | controller | Preparing metadata (pyproject.toml): started 2025-12-30 00:12:48.865154 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-30 00:12:48.870316 | 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-12-30 00:12:48.875824 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-30 00:12:49.246057 | controller | ERROR 2025-12-30 00:12:49.246286 | controller | { 2025-12-30 00:12:49.246317 | controller | "delta": "0:00:36.525343", 2025-12-30 00:12:49.246338 | controller | "end": "2025-12-30 00:12:48.934279", 2025-12-30 00:12:49.246358 | controller | "msg": "non-zero return code", 2025-12-30 00:12:49.246391 | controller | "rc": 1, 2025-12-30 00:12:49.246410 | controller | "start": "2025-12-30 00:12:12.408936" 2025-12-30 00:12:49.246427 | controller | } failure 2025-12-30 00:12:49.248252 | 2025-12-30 00:12:49.248323 | PLAY RECAP 2025-12-30 00:12:49.248384 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-30 00:12:49.248418 | 2025-12-30 00:12:49.402552 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-30 00:12:49.403706 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-30 00:12:50.116249 | 2025-12-30 00:12:50.116433 | PLAY [all] 2025-12-30 00:12:50.149376 | 2025-12-30 00:12:50.149553 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-30 00:12:50.403174 | controller | changed: non-zero return code 2025-12-30 00:12:50.411514 | 2025-12-30 00:12:50.411736 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-30 00:12:50.441764 | controller | skipping: Conditional result was False 2025-12-30 00:12:50.449096 | 2025-12-30 00:12:50.449233 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-30 00:12:50.485380 | 2025-12-30 00:12:50.485590 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-30 00:12:50.520613 | 2025-12-30 00:12:50.521207 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-30 00:12:50.536648 | controller | skipping: Conditional result was False 2025-12-30 00:12:50.548170 | 2025-12-30 00:12:50.548350 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-30 00:12:50.586892 | 2025-12-30 00:12:50.587136 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-30 00:12:50.603116 | controller | skipping: Conditional result was False 2025-12-30 00:12:50.614345 | 2025-12-30 00:12:50.614516 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-30 00:12:50.633500 | controller | skipping: Conditional result was False 2025-12-30 00:12:50.641516 | 2025-12-30 00:12:50.641628 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-30 00:12:50.667385 | controller | skipping: Conditional result was False 2025-12-30 00:12:50.711735 | 2025-12-30 00:12:50.711875 | PLAY RECAP 2025-12-30 00:12:50.711956 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-30 00:12:50.711984 | 2025-12-30 00:12:50.865275 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-30 00:12:50.866380 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-30 00:12:51.536277 | 2025-12-30 00:12:51.536450 | PLAY [all:!appliance*] 2025-12-30 00:12:51.565373 | 2025-12-30 00:12:51.565563 | TASK [unregister the node] 2025-12-30 00:12:52.111216 | controller | skipping: Conditional result was False 2025-12-30 00:12:52.118690 | 2025-12-30 00:12:52.118829 | TASK [include_role : fetch-output] 2025-12-30 00:12:52.151121 | controller | ok 2025-12-30 00:12:52.174943 | 2025-12-30 00:12:52.175121 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-30 00:12:52.231049 | controller | skipping: Conditional result was False 2025-12-30 00:12:52.238329 | 2025-12-30 00:12:52.238450 | TASK [fetch-output : Set log path for single node] 2025-12-30 00:12:52.278716 | controller | ok 2025-12-30 00:12:52.284289 | 2025-12-30 00:12:52.284364 | LOOP [fetch-output : Ensure local output dirs] 2025-12-30 00:12:52.766596 | controller -> localhost | ok: "/var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/logs" 2025-12-30 00:12:53.072275 | controller -> localhost | changed: "/var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/artifacts" 2025-12-30 00:12:53.329392 | controller -> localhost | changed: "/var/lib/zuul/builds/3897fa97ee4f4000aa5e25ba3816f787/work/docs" 2025-12-30 00:12:53.345424 | 2025-12-30 00:12:53.345594 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-30 00:12:54.078078 | controller | changed: 2025-12-30 00:12:54.078346 | controller | .d..t...... ./ 2025-12-30 00:12:54.078387 | controller | cd+++++++++ controller/ 2025-12-30 00:12:54.078435 | controller | changed: All items complete 2025-12-30 00:12:54.078465 | 2025-12-30 00:12:54.577503 | controller | changed: .d..t...... ./ 2025-12-30 00:12:55.055817 | controller | changed: .d..t...... ./ 2025-12-30 00:12:55.076672 | 2025-12-30 00:12:55.076801 | TASK [include_role : fetch-output-openshift] 2025-12-30 00:12:55.093126 | controller | skipping: Conditional result was False 2025-12-30 00:12:55.102557 | 2025-12-30 00:12:55.102688 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-30 00:12:55.136335 | controller | skipping: Conditional result was False 2025-12-30 00:12:55.145005 | controller | skipping: Conditional result was False 2025-12-30 00:12:55.196723 | 2025-12-30 00:12:55.196857 | PLAY [localhost] 2025-12-30 00:12:55.218178 | 2025-12-30 00:12:55.218321 | TASK [Run Zuul manifest role] 2025-12-30 00:12:55.244237 | localhost | ok 2025-12-30 00:12:55.265857 | 2025-12-30 00:12:55.265997 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-30 00:12:55.689285 | localhost | changed 2025-12-30 00:12:55.695997 | 2025-12-30 00:12:55.696105 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-30 00:12:55.728385 | localhost | ok 2025-12-30 00:12:55.740282 | 2025-12-30 00:12:55.740435 | TASK [Set zuul-log-path fact] 2025-12-30 00:12:55.764396 | localhost | ok 2025-12-30 00:12:55.790295 | 2025-12-30 00:12:55.790453 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-30 00:12:55.822573 | localhost | ok 2025-12-30 00:12:55.834995 | 2025-12-30 00:12:55.835129 | LOOP [Run upload-logs-swift role] 2025-12-30 00:12:55.871011 | localhost | Output suppressed because no_log was given 2025-12-30 00:12:55.912551 | 2025-12-30 00:12:55.912694 | TASK [Set zuul-log-path fact] 2025-12-30 00:12:55.938444 | localhost | skipping: Conditional result was False 2025-12-30 00:12:55.946649 | 2025-12-30 00:12:55.946766 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-30 00:12:56.427975 | localhost -> localhost | ok: Runtime: 0:00:00.005411 2025-12-30 00:12:56.433569 | 2025-12-30 00:12:56.433654 | TASK [upload-logs-swift : Upload logs to swift]