2025-10-13 00:11:46.984909 | Job console starting...
2025-10-13 00:11:46.995015 | Updating repositories
2025-10-13 00:11:47.114311 | Preparing job workspace
2025-10-13 00:11:52.022795 | Running Ansible setup...
2025-10-13 00:11:58.808877 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:11:59.463520 | 
2025-10-13 00:11:59.463640 | PLAY [localhost]
2025-10-13 00:11:59.473115 | 
2025-10-13 00:11:59.473184 | TASK [Gathering Facts]
2025-10-13 00:12:00.527384 | localhost | ok
2025-10-13 00:12:00.563747 | 
2025-10-13 00:12:00.563966 | TASK [Setup log path fact]
2025-10-13 00:12:00.590304 | localhost | ok
2025-10-13 00:12:00.611445 | 
2025-10-13 00:12:00.611550 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:12:00.641234 | localhost | ok
2025-10-13 00:12:00.652885 | 
2025-10-13 00:12:00.652991 | TASK [emit-job-header : Print job information]
2025-10-13 00:12:00.683286 | # Job Information
2025-10-13 00:12:00.683465 | Ansible Version: 2.15.12
2025-10-13 00:12:00.683508 | Job: ansible-test-sanity-docker-devel
2025-10-13 00:12:00.683536 | Pipeline: periodic
2025-10-13 00:12:00.683562 | Executor: ze04.softwarefactory-project.io
2025-10-13 00:12:00.683588 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-13 00:12:00.683617 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/dd4/ansible/dd4e98b6edc049c2b75c991a8577d5dd/
2025-10-13 00:12:00.683643 | Event ID: 5c3858b4bf9e4fdab660facb3b50ba54
2025-10-13 00:12:00.688997 | 
2025-10-13 00:12:00.689127 | LOOP [emit-job-header : Print node information]
2025-10-13 00:12:00.815371 | localhost | ok:
2025-10-13 00:12:00.815575 | localhost | # Node Information
2025-10-13 00:12:00.815613 | localhost | Inventory Hostname: controller
2025-10-13 00:12:00.815636 | localhost | Hostname: ip-172-16-116-170
2025-10-13 00:12:00.815656 | localhost | Username: zuul-worker
2025-10-13 00:12:00.815683 | localhost | Distro: Fedora 37
2025-10-13 00:12:00.815911 | localhost | Provider: ansible-us-east-2
2025-10-13 00:12:00.815944 | localhost | Region: us-east-2
2025-10-13 00:12:00.815964 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-13 00:12:00.815983 | localhost | Product Name: t3.small
2025-10-13 00:12:00.816002 | localhost | Interface IP: 13.58.134.75
2025-10-13 00:12:00.825384 | 
2025-10-13 00:12:00.825509 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 00:12:01.245805 | localhost -> localhost | changed
2025-10-13 00:12:01.252221 | 
2025-10-13 00:12:01.252311 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 00:12:02.084136 | localhost -> localhost | changed
2025-10-13 00:12:02.104482 | 
2025-10-13 00:12:02.104590 | PLAY [all:!appliance*]
2025-10-13 00:12:02.132711 | 
2025-10-13 00:12:02.132856 | TASK [include_role : start-zuul-console]
2025-10-13 00:12:02.151816 | controller | ok
2025-10-13 00:12:02.164654 | 
2025-10-13 00:12:02.164785 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 00:12:03.294636 | controller | ok
2025-10-13 00:12:03.310867 | 
2025-10-13 00:12:03.311009 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-13 00:12:05.138070 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-13 00:12:05.153208 | 
2025-10-13 00:12:05.153347 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-13 00:12:05.299763 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.306094 | 
2025-10-13 00:12:05.306180 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-13 00:12:05.332280 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.339033 | 
2025-10-13 00:12:05.339123 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-13 00:12:05.372213 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.378548 | 
2025-10-13 00:12:05.378616 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-13 00:12:05.406528 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.412417 | 
2025-10-13 00:12:05.412499 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-13 00:12:05.430086 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.436216 | 
2025-10-13 00:12:05.436293 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-13 00:12:05.460225 | controller | skipping: Conditional result was False
2025-10-13 00:12:05.474299 | 
2025-10-13 00:12:05.474373 | TASK [Disable Fedora Modular]
2025-10-13 00:12:06.224506 | controller | changed
2025-10-13 00:12:06.234208 | 
2025-10-13 00:12:06.234369 | TASK [Enable EPEL]
2025-10-13 00:12:06.270766 | controller | skipping: Conditional result was False
2025-10-13 00:12:06.280851 | 
2025-10-13 00:12:06.280998 | TASK [Register the RHEL node]
2025-10-13 00:12:06.449468 | 
2025-10-13 00:12:06.449726 | TASK [Show the subscription-manager status]
2025-10-13 00:12:06.640606 | controller | skipping: Conditional result was False
2025-10-13 00:12:06.647932 | 
2025-10-13 00:12:06.648031 | TASK [Enable EPEL on RHEL]
2025-10-13 00:12:06.805326 | controller | skipping: Conditional result was False
2025-10-13 00:12:06.819436 | 
2025-10-13 00:12:06.819578 | TASK [Install git and tox]
2025-10-13 00:13:37.336965 | controller | changed
2025-10-13 00:13:37.349109 | 
2025-10-13 00:13:37.349295 | TASK [include_role : prepare-workspace]
2025-10-13 00:13:37.374907 | controller | ok
2025-10-13 00:13:37.408000 | 
2025-10-13 00:13:37.408116 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 00:13:37.885286 | controller | ok
2025-10-13 00:13:37.896458 | 
2025-10-13 00:13:37.896600 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 00:13:50.686619 | controller | Output suppressed because no_log was given
2025-10-13 00:13:50.712298 | 
2025-10-13 00:13:50.712474 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 00:13:50.740581 | controller | skipping: Conditional result was False
2025-10-13 00:13:50.801624 | 
2025-10-13 00:13:50.801740 | PLAY [all:!appliance]
2025-10-13 00:13:50.817847 | 
2025-10-13 00:13:50.817919 | TASK [Run add-build-sshkey role (RSA)]
2025-10-13 00:13:50.838451 | controller | ok
2025-10-13 00:13:50.854058 | 
2025-10-13 00:13:50.854134 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:13:51.122799 | controller -> localhost | ok
2025-10-13 00:13:51.132334 | 
2025-10-13 00:13:51.132461 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:13:51.165538 | controller | ok
2025-10-13 00:13:51.187343 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:13:51.197186 | 
2025-10-13 00:13:51.197282 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:13:51.850078 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 00:13:51.850449 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_rsa.
2025-10-13 00:13:51.850516 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_rsa.pub.
2025-10-13 00:13:51.850572 | controller -> localhost | The key fingerprint is:
2025-10-13 00:13:51.850635 | controller -> localhost | SHA256:BBzjowMSkgD+1utxCdHilg+Yv0lmsTQkRjQ7gm+klnM zuul-build-sshkey
2025-10-13 00:13:51.850719 | controller -> localhost | The key's randomart image is:
2025-10-13 00:13:51.850778 | controller -> localhost | +---[RSA 2048]----+
2025-10-13 00:13:51.850822 | controller -> localhost | |B..+ .+.         |
2025-10-13 00:13:51.850865 | controller -> localhost | |=.. o.oo         |
2025-10-13 00:13:51.850906 | controller -> localhost | |ooo= +o..        |
2025-10-13 00:13:51.850948 | controller -> localhost | | ==.O.+o         |
2025-10-13 00:13:51.850988 | controller -> localhost | |.+oEo@  S        |
2025-10-13 00:13:51.851088 | controller -> localhost | |..+ +.O .        |
2025-10-13 00:13:51.851147 | controller -> localhost | |     O +         |
2025-10-13 00:13:51.851194 | controller -> localhost | |    = =          |
2025-10-13 00:13:51.851236 | controller -> localhost | |     +           |
2025-10-13 00:13:51.851285 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:13:51.851399 | controller -> localhost | ok: Runtime: 0:00:00.198082
2025-10-13 00:13:51.865830 | 
2025-10-13 00:13:51.866008 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:13:51.906436 | controller | ok
2025-10-13 00:13:51.929090 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:13:51.942777 | 
2025-10-13 00:13:51.942875 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:13:51.969243 | controller | skipping: Conditional result was False
2025-10-13 00:13:51.979496 | 
2025-10-13 00:13:51.979625 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:13:52.617980 | controller | changed
2025-10-13 00:13:52.632271 | 
2025-10-13 00:13:52.632460 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:13:52.975373 | controller | ok
2025-10-13 00:13:52.983144 | 
2025-10-13 00:13:52.983356 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:13:54.307572 | controller | changed
2025-10-13 00:13:54.320381 | 
2025-10-13 00:13:54.320525 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:13:55.590296 | controller | changed
2025-10-13 00:13:55.598590 | 
2025-10-13 00:13:55.598745 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:13:55.624011 | controller | skipping: Conditional result was False
2025-10-13 00:13:55.631471 | 
2025-10-13 00:13:55.631576 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:13:56.044495 | controller -> localhost | changed
2025-10-13 00:13:56.056179 | 
2025-10-13 00:13:56.056269 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:13:56.326937 | controller -> localhost | Identity added: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_rsa (zuul-build-sshkey)
2025-10-13 00:13:56.327365 | controller -> localhost | ok: Runtime: 0:00:00.010950
2025-10-13 00:13:56.340070 | 
2025-10-13 00:13:56.340196 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:13:56.857200 | controller | ok
2025-10-13 00:13:56.871783 | 
2025-10-13 00:13:56.872006 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:13:56.920145 | controller | skipping: Conditional result was False
2025-10-13 00:13:56.934784 | 
2025-10-13 00:13:56.934909 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-13 00:13:56.967914 | controller | ok
2025-10-13 00:13:56.989050 | 
2025-10-13 00:13:56.989171 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:13:57.260519 | controller -> localhost | ok
2025-10-13 00:13:57.271570 | 
2025-10-13 00:13:57.271743 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:13:57.303652 | controller | ok
2025-10-13 00:13:57.315695 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:13:57.321378 | 
2025-10-13 00:13:57.321465 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:13:57.590003 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-13 00:13:57.590250 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_ecdsa.
2025-10-13 00:13:57.590302 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_ecdsa.pub.
2025-10-13 00:13:57.590355 | controller -> localhost | The key fingerprint is:
2025-10-13 00:13:57.590387 | controller -> localhost | SHA256:9pVThQc+J3kijg1qRuMTaFE61I4tOY1NB8Cjk5p/Rms zuul-build-sshkey
2025-10-13 00:13:57.590416 | controller -> localhost | The key's randomart image is:
2025-10-13 00:13:57.590445 | controller -> localhost | +---[ECDSA 521]---+
2025-10-13 00:13:57.590470 | controller -> localhost | |     .++o.    .o.|
2025-10-13 00:13:57.590495 | controller -> localhost | |     .o+o .  ..o.|
2025-10-13 00:13:57.590518 | controller -> localhost | |     o=@+.. . B.o|
2025-10-13 00:13:57.590542 | controller -> localhost | |    +.*+=+ = + * |
2025-10-13 00:13:57.590565 | controller -> localhost | |   o . oS . *    |
2025-10-13 00:13:57.590589 | controller -> localhost | |  o   .+ o . .   |
2025-10-13 00:13:57.590612 | controller -> localhost | |   . . .  .      |
2025-10-13 00:13:57.590635 | controller -> localhost | |    . E          |
2025-10-13 00:13:57.590658 | controller -> localhost | |     +           |
2025-10-13 00:13:57.590705 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:13:57.590775 | controller -> localhost | ok: Runtime: 0:00:00.009989
2025-10-13 00:13:57.605553 | 
2025-10-13 00:13:57.605737 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:13:57.637279 | controller | ok
2025-10-13 00:13:57.654114 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:13:57.668056 | 
2025-10-13 00:13:57.668168 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:13:57.694247 | controller | skipping: Conditional result was False
2025-10-13 00:13:57.710337 | 
2025-10-13 00:13:57.710549 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:13:58.168179 | controller | changed
2025-10-13 00:13:58.182553 | 
2025-10-13 00:13:58.182945 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:13:58.524842 | controller | ok
2025-10-13 00:13:58.534847 | 
2025-10-13 00:13:58.535012 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:13:59.851316 | controller | changed
2025-10-13 00:13:59.865502 | 
2025-10-13 00:13:59.865661 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:14:01.244164 | controller | changed
2025-10-13 00:14:01.256975 | 
2025-10-13 00:14:01.257159 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:14:01.276496 | controller | skipping: Conditional result was False
2025-10-13 00:14:01.292156 | 
2025-10-13 00:14:01.292328 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:14:01.544482 | controller -> localhost | changed
2025-10-13 00:14:01.556900 | 
2025-10-13 00:14:01.557010 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:14:01.910239 | controller -> localhost | Identity added: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/dd4e98b6edc049c2b75c991a8577d5dd_id_ecdsa (zuul-build-sshkey)
2025-10-13 00:14:01.910651 | controller -> localhost | ok: Runtime: 0:00:00.014812
2025-10-13 00:14:01.928739 | 
2025-10-13 00:14:01.928978 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:14:02.856829 | controller | ok
2025-10-13 00:14:02.864297 | 
2025-10-13 00:14:02.864389 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:14:02.901169 | controller | skipping: Conditional result was False
2025-10-13 00:14:02.926864 | 
2025-10-13 00:14:02.927061 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 00:14:02.954479 | controller | skipping: Conditional result was False
2025-10-13 00:14:02.968547 | 
2025-10-13 00:14:02.968777 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 00:14:04.661818 | controller | ok: "logs"
2025-10-13 00:14:04.662398 | controller | ok: All items complete
2025-10-13 00:14:04.662467 | 
2025-10-13 00:14:05.043442 | controller | ok: "artifacts"
2025-10-13 00:14:05.327559 | controller | ok: "docs"
2025-10-13 00:14:05.349464 | 
2025-10-13 00:14:05.349727 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 00:14:05.661944 | controller | changed: "logs"
2025-10-13 00:14:05.951918 | controller | changed: "artifacts"
2025-10-13 00:14:06.249882 | controller | changed: "docs"
2025-10-13 00:14:06.311023 | 
2025-10-13 00:14:06.311143 | PLAY RECAP
2025-10-13 00:14:06.311204 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-13 00:14:06.311243 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 00:14:06.311271 | 
2025-10-13 00:14:06.431849 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:14:06.432717 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:14:07.039902 | 
2025-10-13 00:14:07.040024 | PLAY [all]
2025-10-13 00:14:07.064273 | 
2025-10-13 00:14:07.064427 | TASK [Install binary dependencies]
2025-10-13 00:14:07.135798 | controller | ok
2025-10-13 00:14:07.156469 | 
2025-10-13 00:14:07.156617 | TASK [bindep : Include find tasks]
2025-10-13 00:14:07.186761 | controller | ok
2025-10-13 00:14:07.194622 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 00:14:07.200967 | 
2025-10-13 00:14:07.201039 | TASK [bindep : Look for bindep.txt]
2025-10-13 00:14:07.733005 | controller | ok
2025-10-13 00:14:07.739409 | 
2025-10-13 00:14:07.739497 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:14:07.753889 | controller | skipping: Conditional result was False
2025-10-13 00:14:07.764012 | 
2025-10-13 00:14:07.764175 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 00:14:08.062519 | controller | ok
2025-10-13 00:14:08.069473 | 
2025-10-13 00:14:08.069662 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:14:08.105649 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.111920 | 
2025-10-13 00:14:08.111987 | TASK [bindep : Look for bindep fallback file]
2025-10-13 00:14:08.145860 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.152466 | 
2025-10-13 00:14:08.152540 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:14:08.176762 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.183137 | 
2025-10-13 00:14:08.183226 | TASK [bindep : Include bindep tasks]
2025-10-13 00:14:08.207557 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.221408 | 
2025-10-13 00:14:08.221654 | TASK [bindep : Include install tasks]
2025-10-13 00:14:08.247299 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.257154 | 
2025-10-13 00:14:08.257263 | LOOP [bindep : Include package tasks]
2025-10-13 00:14:08.347304 | 
2025-10-13 00:14:08.347483 | TASK [Run test-setup role]
2025-10-13 00:14:08.370137 | controller | ok
2025-10-13 00:14:08.393063 | 
2025-10-13 00:14:08.393160 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 00:14:08.737081 | controller | ok
2025-10-13 00:14:08.751967 | 
2025-10-13 00:14:08.752127 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 00:14:08.910910 | controller | skipping: Conditional result was False
2025-10-13 00:14:08.966365 | 
2025-10-13 00:14:08.966542 | PLAY RECAP
2025-10-13 00:14:08.966607 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:14:08.966642 | 
2025-10-13 00:14:09.094520 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:14:09.095450 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:14:09.726575 | 
2025-10-13 00:14:09.726722 | PLAY [controller]
2025-10-13 00:14:09.745982 | 
2025-10-13 00:14:09.746084 | TASK [Create the /root directory]
2025-10-13 00:14:10.498572 | controller | ok
2025-10-13 00:14:10.511620 | 
2025-10-13 00:14:10.511850 | TASK [Install glibc-langpack-en]
2025-10-13 00:14:18.457759 | controller | ok: Nothing to do
2025-10-13 00:14:18.466358 | 
2025-10-13 00:14:18.466497 | TASK [Ensure controller directory exists]
2025-10-13 00:14:18.966954 | controller | changed
2025-10-13 00:14:18.974955 | 
2025-10-13 00:14:18.975045 | TASK [Install container runtime]
2025-10-13 00:14:19.048301 | controller | ok
2025-10-13 00:14:19.094973 | 
2025-10-13 00:14:19.095108 | LOOP [ensure-podman : Find distribution installation]
2025-10-13 00:14:19.134046 | controller | ok: "/var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-13 00:14:19.150257 | controller | included: /var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-13 00:14:19.159420 | 
2025-10-13 00:14:19.159519 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-13 00:15:36.274128 | controller | changed
2025-10-13 00:15:36.293177 | 
2025-10-13 00:15:36.293362 | TASK [ensure-podman : Fetch podman version]
2025-10-13 00:15:37.067026 | controller | Client:       Podman Engine
2025-10-13 00:15:37.067110 | controller | Version:      4.6.2
2025-10-13 00:15:37.067141 | controller | API Version:  4.6.2
2025-10-13 00:15:37.067167 | controller | Go Version:   go1.19.12
2025-10-13 00:15:37.067204 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:15:37.067232 | controller | OS/Arch:      linux/amd64
2025-10-13 00:15:37.951832 | controller | ok: Runtime: 0:00:00.221166
2025-10-13 00:15:37.958414 | 
2025-10-13 00:15:37.958525 | TASK [ensure-podman : Print podman version installed]
2025-10-13 00:15:37.989534 | Podman version: Client:       Podman Engine
2025-10-13 00:15:37.990029 | Version:      4.6.2
2025-10-13 00:15:37.990069 | API Version:  4.6.2
2025-10-13 00:15:37.990095 | Go Version:   go1.19.12
2025-10-13 00:15:37.990120 | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:15:37.990144 | OS/Arch:      linux/amd64
2025-10-13 00:15:37.997315 | 
2025-10-13 00:15:37.997396 | TASK [ensure-podman : Validate podman engine]
2025-10-13 00:15:38.130669 | controller | skipping: Conditional result was False
2025-10-13 00:15:38.144303 | 
2025-10-13 00:15:38.144458 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-13 00:15:38.162657 | controller | skipping: Conditional result was False
2025-10-13 00:15:38.177599 | 
2025-10-13 00:15:38.177751 | TASK [Ensure python3.8 is present]
2025-10-13 00:15:38.192536 | controller | skipping: Conditional result was False
2025-10-13 00:15:38.200054 | 
2025-10-13 00:15:38.200141 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-13 00:15:38.221145 | controller | ok
2025-10-13 00:15:38.247556 | 
2025-10-13 00:15:38.247711 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-13 00:15:42.020486 | controller | ok: Nothing to do
2025-10-13 00:15:42.027546 | 
2025-10-13 00:15:42.027641 | TASK [our-ensure-python : Also install python3-devel]
2025-10-13 00:15:55.218291 | controller | changed
2025-10-13 00:15:55.244604 | 
2025-10-13 00:15:55.244855 | TASK [Run ensure-virtualenv role]
2025-10-13 00:15:55.275051 | controller | ok
2025-10-13 00:15:55.313166 | 
2025-10-13 00:15:55.313326 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-13 00:15:55.689712 | controller | /usr/bin/virtualenv
2025-10-13 00:15:55.955150 | controller | ok: Runtime: 0:00:00.004496
2025-10-13 00:15:55.968987 | 
2025-10-13 00:15:55.969141 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-13 00:15:56.001180 | controller | skipping: Conditional result was False
2025-10-13 00:15:56.001447 | controller | ok: All items complete
2025-10-13 00:15:56.001492 | 
2025-10-13 00:15:56.048252 | 
2025-10-13 00:15:56.048383 | TASK [Find the full path of the Python interpreter]
2025-10-13 00:15:56.460808 | controller | /usr/bin/python3
2025-10-13 00:15:56.680578 | controller | ok
2025-10-13 00:15:56.693814 | 
2025-10-13 00:15:56.693998 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-13 00:15:58.179672 | controller | created virtual environment CPython3.11.0.final.0-64 in 820ms
2025-10-13 00:15:58.225382 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-13 00:15:58.225441 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-10-13 00:15:58.225457 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-13 00:15:58.225479 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-13 00:15:58.355582 | controller | changed
2025-10-13 00:15:58.361494 | 
2025-10-13 00:15:58.361572 | TASK [Set selinux package]
2025-10-13 00:15:58.390832 | controller | ok
2025-10-13 00:15:58.396396 | 
2025-10-13 00:15:58.396488 | TASK [Set selinux package (Fedora)]
2025-10-13 00:15:58.446895 | controller | ok
2025-10-13 00:15:58.452285 | 
2025-10-13 00:15:58.452392 | TASK [Install selinux into virtualenv]
2025-10-13 00:16:01.049930 | controller | Collecting selinux-please-lie-to-me
2025-10-13 00:16:01.142631 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-13 00:16:01.690617 | controller | Collecting setuptools<50.0.0
2025-10-13 00:16:01.706137 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-13 00:16:01.806889 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.4 MB/s eta 0:00:00
2025-10-13 00:16:02.306767 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-13 00:16:02.307221 | controller |   Attempting uninstall: setuptools
2025-10-13 00:16:02.316628 | controller |     Found existing installation: setuptools 62.6.0
2025-10-13 00:16:02.562363 | controller |     Uninstalling setuptools-62.6.0:
2025-10-13 00:16:02.588581 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-13 00:16:03.391782 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-13 00:16:03.604082 | controller |
2025-10-13 00:16:03.818530 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:16:03.818577 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:16:04.157169 | controller | ok: Runtime: 0:00:04.908146
2025-10-13 00:16:04.170358 | 
2025-10-13 00:16:04.170501 | TASK [Install pytest-forked into virtualenv]
2025-10-13 00:16:05.370137 | controller | Collecting pytest-forked
2025-10-13 00:16:05.480161 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-13 00:16:05.537145 | controller | Collecting py
2025-10-13 00:16:05.551410 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-13 00:16:05.588583 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00
2025-10-13 00:16:05.764819 | controller | Collecting pytest>=3.10
2025-10-13 00:16:05.779602 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-13 00:16:05.840461 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-13 00:16:05.894122 | controller | Collecting iniconfig>=1
2025-10-13 00:16:05.908663 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-13 00:16:05.972735 | controller | Collecting packaging>=20
2025-10-13 00:16:05.987215 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-13 00:16:05.999294 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.0 MB/s eta 0:00:00
2025-10-13 00:16:06.044217 | controller | Collecting pluggy<2,>=1.5
2025-10-13 00:16:06.058355 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-13 00:16:06.130255 | controller | Collecting pygments>=2.7.2
2025-10-13 00:16:06.144513 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-13 00:16:06.276722 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.5 MB/s eta 0:00:00
2025-10-13 00:16:06.407153 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-13 00:16:08.589324 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-13 00:16:08.605310 | controller |
2025-10-13 00:16:08.781801 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:16:08.781844 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:16:08.841099 | controller | ok: Runtime: 0:00:04.140346
2025-10-13 00:16:08.850222 | 
2025-10-13 00:16:08.850336 | TASK [Update pip]
2025-10-13 00:16:09.961052 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-13 00:16:10.253800 | controller | Collecting pip
2025-10-13 00:16:10.356018 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-13 00:16:10.598660 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 7.8 MB/s eta 0:00:00
2025-10-13 00:16:10.747501 | controller | Installing collected packages: pip
2025-10-13 00:16:10.747930 | controller |   Attempting uninstall: pip
2025-10-13 00:16:10.752407 | controller |     Found existing installation: pip 22.2.2
2025-10-13 00:16:11.011524 | controller |     Uninstalling pip-22.2.2:
2025-10-13 00:16:11.041592 | controller |       Successfully uninstalled pip-22.2.2
2025-10-13 00:16:12.834905 | controller | Successfully installed pip-25.2
2025-10-13 00:16:13.524898 | controller | ok: Runtime: 0:00:03.673041
2025-10-13 00:16:13.536343 | 
2025-10-13 00:16:13.536490 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-13 00:16:14.073593 | controller | changed
2025-10-13 00:16:14.087555 | 
2025-10-13 00:16:14.087750 | TASK [Install ansible into virtualenv]
2025-10-13 00:16:15.182075 | controller | Processing ./src/github.com/ansible/ansible
2025-10-13 00:16:15.188570 | controller |   Installing build dependencies: started
2025-10-13 00:16:17.184344 | controller |   Installing build dependencies: finished with status 'done'
2025-10-13 00:16:17.184977 | controller |   Getting requirements to build wheel: started
2025-10-13 00:16:18.723472 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-13 00:16:19.646916 | controller |   Preparing metadata (pyproject.toml): started
2025-10-13 00:16:19.646972 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-13 00:16:19.650086 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-10-13 00:16:19.655015 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-13 00:16:20.260200 | controller | ERROR
2025-10-13 00:16:20.260407 | controller | {
2025-10-13 00:16:20.260437 | controller |   "delta": "0:00:05.258082",
2025-10-13 00:16:20.260456 | controller |   "end": "2025-10-13 00:16:19.810735",
2025-10-13 00:16:20.260474 | controller |   "msg": "non-zero return code",
2025-10-13 00:16:20.260503 | controller |   "rc": 1,
2025-10-13 00:16:20.260520 | controller |   "start": "2025-10-13 00:16:14.552653"
2025-10-13 00:16:20.260536 | controller | }
failure
2025-10-13 00:16:20.262259 | 
2025-10-13 00:16:20.262306 | PLAY RECAP
2025-10-13 00:16:20.262347 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-13 00:16:20.262366 | 
2025-10-13 00:16:20.376549 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:16:20.379852 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:16:20.978411 | 
2025-10-13 00:16:20.978539 | PLAY [all]
2025-10-13 00:16:21.000981 | 
2025-10-13 00:16:21.001098 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 00:16:21.793975 | controller | changed: non-zero return code
2025-10-13 00:16:21.802342 | 
2025-10-13 00:16:21.802498 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 00:16:21.818170 | controller | skipping: Conditional result was False
2025-10-13 00:16:21.825001 | 
2025-10-13 00:16:21.825138 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 00:16:21.855407 | 
2025-10-13 00:16:21.855560 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 00:16:21.885066 | 
2025-10-13 00:16:21.885219 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 00:16:21.908735 | controller | skipping: Conditional result was False
2025-10-13 00:16:21.915329 | 
2025-10-13 00:16:21.915444 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 00:16:21.946479 | 
2025-10-13 00:16:21.946639 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 00:16:21.960361 | controller | skipping: Conditional result was False
2025-10-13 00:16:21.968383 | 
2025-10-13 00:16:21.968479 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 00:16:21.983070 | controller | skipping: Conditional result was False
2025-10-13 00:16:21.991210 | 
2025-10-13 00:16:21.991301 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 00:16:22.005948 | controller | skipping: Conditional result was False
2025-10-13 00:16:22.046367 | 
2025-10-13 00:16:22.046448 | PLAY RECAP
2025-10-13 00:16:22.046488 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:16:22.046508 | 
2025-10-13 00:16:22.136571 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:16:22.138398 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-13 00:16:22.723922 | 
2025-10-13 00:16:22.724024 | PLAY [all:!appliance*]
2025-10-13 00:16:22.745463 | 
2025-10-13 00:16:22.745586 | TASK [unregister the node]
2025-10-13 00:16:22.889610 | controller | skipping: Conditional result was False
2025-10-13 00:16:22.902501 | 
2025-10-13 00:16:22.902751 | TASK [include_role : fetch-output]
2025-10-13 00:16:22.952770 | controller | ok
2025-10-13 00:16:22.996881 | 
2025-10-13 00:16:22.997220 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 00:16:23.096556 | controller | skipping: Conditional result was False
2025-10-13 00:16:23.110192 | 
2025-10-13 00:16:23.110404 | TASK [fetch-output : Set log path for single node]
2025-10-13 00:16:23.171262 | controller | ok
2025-10-13 00:16:23.185166 | 
2025-10-13 00:16:23.185335 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 00:16:23.674302 | controller -> localhost | ok: "/var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/logs"
2025-10-13 00:16:23.908644 | controller -> localhost | changed: "/var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/artifacts"
2025-10-13 00:16:24.131250 | controller -> localhost | changed: "/var/lib/zuul/builds/dd4e98b6edc049c2b75c991a8577d5dd/work/docs"
2025-10-13 00:16:24.141016 | 
2025-10-13 00:16:24.141096 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 00:16:25.340244 | controller | changed:
2025-10-13 00:16:25.340430 | controller | .d..t...... ./
2025-10-13 00:16:25.340458 | controller | cd+++++++++ controller/
2025-10-13 00:16:25.340492 | controller | changed: All items complete
2025-10-13 00:16:25.340514 | 
2025-10-13 00:16:26.396631 | controller | changed: .d..t...... ./
2025-10-13 00:16:27.452238 | controller | changed: .d..t...... ./
2025-10-13 00:16:27.471301 | 
2025-10-13 00:16:27.471426 | TASK [include_role : fetch-output-openshift]
2025-10-13 00:16:27.485142 | controller | skipping: Conditional result was False
2025-10-13 00:16:27.491925 | 
2025-10-13 00:16:27.492024 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 00:16:27.528873 | controller | skipping: Conditional result was False
2025-10-13 00:16:27.545122 | controller | skipping: Conditional result was False
2025-10-13 00:16:27.573733 | 
2025-10-13 00:16:27.573937 | PLAY [localhost]
2025-10-13 00:16:27.587726 | 
2025-10-13 00:16:27.587842 | TASK [Run Zuul manifest role]
2025-10-13 00:16:27.606822 | localhost | ok
2025-10-13 00:16:27.620651 | 
2025-10-13 00:16:27.620780 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 00:16:28.006293 | localhost | changed
2025-10-13 00:16:28.011046 | 
2025-10-13 00:16:28.011109 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 00:16:28.050516 | localhost | ok
2025-10-13 00:16:28.059239 | 
2025-10-13 00:16:28.059326 | TASK [Set zuul-log-path fact]
2025-10-13 00:16:28.078088 | localhost | ok
2025-10-13 00:16:28.093151 | 
2025-10-13 00:16:28.093276 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:16:28.122391 | localhost | ok
2025-10-13 00:16:28.131540 | 
2025-10-13 00:16:28.131632 | LOOP [Run upload-logs-swift role]
2025-10-13 00:16:28.181500 | localhost | Output suppressed because no_log was given
2025-10-13 00:16:28.209220 | 
2025-10-13 00:16:28.209344 | TASK [Set zuul-log-path fact]
2025-10-13 00:16:28.235389 | localhost | skipping: Conditional result was False
2025-10-13 00:16:28.241353 | 
2025-10-13 00:16:28.241433 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-13 00:16:28.684181 | localhost -> localhost | ok: Runtime: 0:00:00.004869
2025-10-13 00:16:28.689950 | 
2025-10-13 00:16:28.690071 | TASK [upload-logs-swift : Upload logs to swift]