2026-08-12 06:22:43.142436 | Job console starting 2026-08-12 06:22:43.160921 | Updating git repos 2026-08-12 06:22:43.189079 | Cloning repos into workspace 2026-08-12 06:22:43.218726 | Restoring repo states 2026-08-12 06:22:43.228879 | Merging changes 2026-08-12 06:22:43.577576 | Checking out repos 2026-08-12 06:22:43.617200 | Preparing playbooks 2026-08-12 06:22:44.785200 | Running Ansible setup 2026-08-12 06:22:48.015681 | PRE-RUN START: [trusted : github.com/vexxhost/zuul-config/playbooks/base/pre.yaml@main] 2026-08-12 06:22:48.627329 | 2026-08-12 06:22:48.627469 | PLAY [localhost] 2026-08-12 06:22:48.634910 | 2026-08-12 06:22:48.634979 | TASK [Gathering Facts] 2026-08-12 06:22:49.495316 | localhost | ok 2026-08-12 06:22:49.506310 | 2026-08-12 06:22:49.506504 | TASK [Setup log path fact] 2026-08-12 06:22:49.527846 | localhost | ok 2026-08-12 06:22:49.541689 | 2026-08-12 06:22:49.541759 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-08-12 06:22:49.573491 | localhost | ok 2026-08-12 06:22:49.582354 | 2026-08-12 06:22:49.582445 | TASK [emit-job-header : Print job information] 2026-08-12 06:22:49.624877 | # Job Information 2026-08-12 06:22:49.625067 | Ansible Version: 2.16.18 2026-08-12 06:22:49.625114 | Job: ansible-collection-containers-molecule-forget-package-ubuntu-focal 2026-08-12 06:22:49.625147 | Pipeline: check 2026-08-12 06:22:49.625176 | Executor: 2d72f0692154 2026-08-12 06:22:49.625203 | Triggered by: https://github.com/vexxhost/ansible-collection-containers/pull/146 2026-08-12 06:22:49.625233 | Event ID: 81931b50-9614-11f1-80c7-536fa37cd523 2026-08-12 06:22:49.629019 | 2026-08-12 06:22:49.629110 | LOOP [emit-job-header : Print node information] 2026-08-12 06:22:49.727081 | localhost | ok: 2026-08-12 06:22:49.727319 | localhost | # Node Information 2026-08-12 06:22:49.727365 | localhost | Inventory Hostname: ubuntu-focal 2026-08-12 06:22:49.727397 | localhost | Hostname: np0000188891 2026-08-12 06:22:49.727433 | localhost | Username: zuul 2026-08-12 06:22:49.727482 | localhost | Distro: Ubuntu 20.04 2026-08-12 06:22:49.727527 | localhost | Provider: yul1 2026-08-12 06:22:49.727567 | localhost | Region: ca-ymq-1 2026-08-12 06:22:49.727602 | localhost | Label: ubuntu-focal 2026-08-12 06:22:49.727632 | localhost | Product Name: OpenStack Nova 2026-08-12 06:22:49.727660 | localhost | Interface IP: 199.204.45.182 2026-08-12 06:22:49.738605 | 2026-08-12 06:22:49.738711 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2026-08-12 06:22:50.140044 | localhost -> localhost | changed 2026-08-12 06:22:50.150275 | 2026-08-12 06:22:50.150418 | TASK [log-inventory : Copy ansible inventory to logs dir] 2026-08-12 06:22:51.007143 | localhost -> localhost | changed 2026-08-12 06:22:51.019119 | 2026-08-12 06:22:51.019232 | PLAY [all] 2026-08-12 06:22:51.028142 | 2026-08-12 06:22:51.028209 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2026-08-12 06:22:51.255902 | ubuntu-focal -> localhost | ok 2026-08-12 06:22:51.264012 | 2026-08-12 06:22:51.266861 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2026-08-12 06:22:51.304071 | ubuntu-focal | ok 2026-08-12 06:22:51.327287 | ubuntu-focal | included: /var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2026-08-12 06:22:51.332917 | 2026-08-12 06:22:51.333042 | TASK [add-build-sshkey : Create Temp SSH key] 2026-08-12 06:22:52.168615 | ubuntu-focal -> localhost | Generating public/private rsa key pair. 2026-08-12 06:22:52.168832 | ubuntu-focal -> localhost | Your identification has been saved in /var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/9824320767b34bfb9c6a0869e587bb1d_id_rsa 2026-08-12 06:22:52.168875 | ubuntu-focal -> localhost | Your public key has been saved in /var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/9824320767b34bfb9c6a0869e587bb1d_id_rsa.pub 2026-08-12 06:22:52.168907 | ubuntu-focal -> localhost | The key fingerprint is: 2026-08-12 06:22:52.168936 | ubuntu-focal -> localhost | SHA256:k4n2MPLNXrlzNF52ZK34eweL00sWVN3NSUtyBrubIf0 zuul-build-sshkey 2026-08-12 06:22:52.169072 | ubuntu-focal -> localhost | The key's randomart image is: 2026-08-12 06:22:52.169113 | ubuntu-focal -> localhost | +---[RSA 3072]----+ 2026-08-12 06:22:52.169152 | ubuntu-focal -> localhost | | oo**| 2026-08-12 06:22:52.169183 | ubuntu-focal -> localhost | | *o*| 2026-08-12 06:22:52.169211 | ubuntu-focal -> localhost | | ....| 2026-08-12 06:22:52.169240 | ubuntu-focal -> localhost | | . o ... +| 2026-08-12 06:22:52.169267 | ubuntu-focal -> localhost | | . = S . =.+ | 2026-08-12 06:22:52.169294 | ubuntu-focal -> localhost | | + * . .= X..| 2026-08-12 06:22:52.169320 | ubuntu-focal -> localhost | | . + oo XoE | 2026-08-12 06:22:52.169347 | ubuntu-focal -> localhost | | . ...=o+ o| 2026-08-12 06:22:52.169378 | ubuntu-focal -> localhost | | . .o .o+.| 2026-08-12 06:22:52.169406 | ubuntu-focal -> localhost | +----[SHA256]-----+ 2026-08-12 06:22:52.169471 | ubuntu-focal -> localhost | ok: Runtime: 0:00:00.410660 2026-08-12 06:22:52.176373 | 2026-08-12 06:22:52.176461 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2026-08-12 06:22:52.210496 | ubuntu-focal | ok 2026-08-12 06:22:52.221292 | ubuntu-focal | included: /var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2026-08-12 06:22:52.229337 | 2026-08-12 06:22:52.229400 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2026-08-12 06:22:52.254578 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:22:52.262883 | 2026-08-12 06:22:52.262973 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2026-08-12 06:22:52.686144 | ubuntu-focal | changed 2026-08-12 06:22:52.693706 | 2026-08-12 06:22:52.693773 | TASK [add-build-sshkey : Make sure user has a .ssh] 2026-08-12 06:22:52.868870 | ubuntu-focal | ok 2026-08-12 06:22:52.875587 | 2026-08-12 06:22:52.875677 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2026-08-12 06:22:53.316576 | ubuntu-focal | changed 2026-08-12 06:22:53.411542 | 2026-08-12 06:22:53.411654 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2026-08-12 06:22:53.859542 | ubuntu-focal | changed 2026-08-12 06:22:53.866434 | 2026-08-12 06:22:53.866522 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2026-08-12 06:22:53.891121 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:22:53.899794 | 2026-08-12 06:22:53.899879 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2026-08-12 06:22:54.259105 | ubuntu-focal -> localhost | changed 2026-08-12 06:22:54.278296 | 2026-08-12 06:22:54.278386 | TASK [add-build-sshkey : Add back temp key] 2026-08-12 06:22:54.554587 | ubuntu-focal -> localhost | Identity added: /var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/9824320767b34bfb9c6a0869e587bb1d_id_rsa (zuul-build-sshkey) 2026-08-12 06:22:54.554890 | ubuntu-focal -> localhost | ok: Runtime: 0:00:00.012377 2026-08-12 06:22:54.561574 | 2026-08-12 06:22:54.561662 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2026-08-12 06:22:54.872113 | ubuntu-focal | ok 2026-08-12 06:22:54.890888 | 2026-08-12 06:22:54.890965 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2026-08-12 06:22:54.921722 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:22:54.938124 | 2026-08-12 06:22:54.938194 | TASK [prepare-workspace : Start zuul_console daemon.] 2026-08-12 06:22:55.254628 | ubuntu-focal | ok 2026-08-12 06:22:55.262711 | 2026-08-12 06:22:55.262804 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2026-08-12 06:22:55.988241 | ubuntu-focal | Output suppressed because no_log was given 2026-08-12 06:22:55.998757 | 2026-08-12 06:22:55.998826 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2026-08-12 06:22:56.182020 | ubuntu-focal | ok: "logs" 2026-08-12 06:22:56.182889 | ubuntu-focal | ok: All items complete 2026-08-12 06:22:56.182937 | 2026-08-12 06:22:56.390364 | ubuntu-focal | ok: "artifacts" 2026-08-12 06:22:56.485403 | ubuntu-focal | ok: "docs" 2026-08-12 06:22:56.504357 | 2026-08-12 06:22:56.504493 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2026-08-12 06:22:56.687021 | ubuntu-focal | changed: "logs" 2026-08-12 06:22:56.831815 | ubuntu-focal | changed: "artifacts" 2026-08-12 06:22:56.977455 | ubuntu-focal | changed: "docs" 2026-08-12 06:22:56.999194 | 2026-08-12 06:22:56.999328 | PLAY RECAP 2026-08-12 06:22:56.999396 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-08-12 06:22:56.999440 | ubuntu-focal | ok: 15 changed: 8 unreachable: 0 failed: 0 skipped: 3 rescued: 0 ignored: 0 2026-08-12 06:22:56.999471 | 2026-08-12 06:22:57.182842 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/vexxhost/zuul-config/playbooks/base/pre.yaml@main] 2026-08-12 06:22:57.185264 | PRE-RUN START: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/pre.yaml@main] 2026-08-12 06:22:57.770948 | 2026-08-12 06:22:57.771158 | PLAY [all] 2026-08-12 06:22:57.784821 | 2026-08-12 06:22:57.784923 | TASK [setup-uv : Extract archive] 2026-08-12 06:22:59.974477 | ubuntu-focal | changed 2026-08-12 06:22:59.982727 | 2026-08-12 06:22:59.982809 | TASK [setup-uv : Print version] 2026-08-12 06:23:00.317913 | ubuntu-focal | uv 0.8.13 2026-08-12 06:23:00.522369 | ubuntu-focal | ok: Runtime: 0:00:00.009347 2026-08-12 06:23:00.534874 | 2026-08-12 06:23:00.534951 | TASK [Install Ansible collection siblings] 2026-08-12 06:23:00.892864 | ubuntu-focal | ok: 2026-08-12 06:23:00.893105 | ubuntu-focal | Skipping ansible.posix: no checked-out sibling 2026-08-12 06:23:00.893147 | ubuntu-focal | Skipping community.general: no checked-out sibling 2026-08-12 06:23:00.895347 | 2026-08-12 06:23:00.895409 | PLAY RECAP 2026-08-12 06:23:00.895468 | ubuntu-focal | ok: 3 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-08-12 06:23:00.895499 | 2026-08-12 06:23:01.030536 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/pre.yaml@main] 2026-08-12 06:23:01.032945 | RUN START: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/run.yaml@main] 2026-08-12 06:23:01.624072 | 2026-08-12 06:23:01.624245 | PLAY [all] 2026-08-12 06:23:01.637026 | 2026-08-12 06:23:01.637121 | LOOP [Check inventory directories] 2026-08-12 06:23:01.921661 | ubuntu-focal | ok: "src/github.com/vexxhost/ansible-collection-containers" 2026-08-12 06:23:02.070060 | ubuntu-focal | ok: "src/github.com/vexxhost/ansible-collection-containers/molecule/forget-package/inventory" 2026-08-12 06:23:02.211201 | ubuntu-focal | ok: "src/github.com/vexxhost/ansible-collection-containers/extensions/molecule/forget-package/inventory" 2026-08-12 06:23:02.225345 | 2026-08-12 06:23:02.225569 | LOOP [Copy inventory file for Zuul] 2026-08-12 06:23:02.959781 | ubuntu-focal | changed: 2026-08-12 06:23:02.960114 | ubuntu-focal | { 2026-08-12 06:23:02.960166 | ubuntu-focal | "ansible_loop_var": "item", 2026-08-12 06:23:02.960199 | ubuntu-focal | "changed": false, 2026-08-12 06:23:02.960227 | ubuntu-focal | "failed": false, 2026-08-12 06:23:02.960264 | ubuntu-focal | "invocation": { 2026-08-12 06:23:02.960292 | ubuntu-focal | "module_args": { 2026-08-12 06:23:02.960318 | ubuntu-focal | "checksum_algorithm": "sha1", 2026-08-12 06:23:02.960343 | ubuntu-focal | "follow": true, 2026-08-12 06:23:02.960368 | ubuntu-focal | "get_attributes": true, 2026-08-12 06:23:02.960394 | ubuntu-focal | "get_checksum": true, 2026-08-12 06:23:02.960419 | ubuntu-focal | "get_mime": true, 2026-08-12 06:23:02.960443 | ubuntu-focal | "path": "src/github.com/vexxhost/ansible-collection-containers" 2026-08-12 06:23:02.960469 | ubuntu-focal | } 2026-08-12 06:23:02.960493 | ubuntu-focal | }, 2026-08-12 06:23:02.960518 | ubuntu-focal | "item": "src/github.com/vexxhost/ansible-collection-containers", 2026-08-12 06:23:02.960558 | ubuntu-focal | "stat": { 2026-08-12 06:23:02.960584 | ubuntu-focal | "atime": 1786515775.9032423, 2026-08-12 06:23:02.960609 | ubuntu-focal | "attr_flags": "e", 2026-08-12 06:23:02.960633 | ubuntu-focal | "attributes": [ 2026-08-12 06:23:02.960657 | ubuntu-focal | "extents" 2026-08-12 06:23:02.960681 | ubuntu-focal | ], 2026-08-12 06:23:02.960706 | ubuntu-focal | "block_size": 4096, 2026-08-12 06:23:02.960730 | ubuntu-focal | "blocks": 8, 2026-08-12 06:23:02.960755 | ubuntu-focal | "charset": "binary", 2026-08-12 06:23:02.960781 | ubuntu-focal | "ctime": 1786515775.9032423, 2026-08-12 06:23:02.960805 | ubuntu-focal | "dev": 64513, 2026-08-12 06:23:02.960829 | ubuntu-focal | "device_type": 0, 2026-08-12 06:23:02.960853 | ubuntu-focal | "executable": true, 2026-08-12 06:23:02.960877 | ubuntu-focal | "exists": true, 2026-08-12 06:23:02.960902 | ubuntu-focal | "gid": 1000, 2026-08-12 06:23:02.960927 | ubuntu-focal | "gr_name": "zuul", 2026-08-12 06:23:02.960979 | ubuntu-focal | "inode": 1035293, 2026-08-12 06:23:02.961072 | ubuntu-focal | "isblk": false, 2026-08-12 06:23:02.961107 | ubuntu-focal | "ischr": false, 2026-08-12 06:23:02.961134 | ubuntu-focal | "isdir": true, 2026-08-12 06:23:02.961159 | ubuntu-focal | "isfifo": false, 2026-08-12 06:23:02.961184 | ubuntu-focal | "isgid": false, 2026-08-12 06:23:02.961209 | ubuntu-focal | "islnk": false, 2026-08-12 06:23:02.961233 | ubuntu-focal | "isreg": false, 2026-08-12 06:23:02.961257 | ubuntu-focal | "issock": false, 2026-08-12 06:23:02.961281 | ubuntu-focal | "isuid": false, 2026-08-12 06:23:02.961305 | ubuntu-focal | "mimetype": "inode/directory", 2026-08-12 06:23:02.961329 | ubuntu-focal | "mode": "0755", 2026-08-12 06:23:02.961352 | ubuntu-focal | "mtime": 1786515763.2491658, 2026-08-12 06:23:02.961376 | ubuntu-focal | "nlink": 11, 2026-08-12 06:23:02.961400 | ubuntu-focal | "path": "src/github.com/vexxhost/ansible-collection-containers", 2026-08-12 06:23:02.961425 | ubuntu-focal | "pw_name": "zuul", 2026-08-12 06:23:02.961455 | ubuntu-focal | "readable": true, 2026-08-12 06:23:02.961485 | ubuntu-focal | "rgrp": true, 2026-08-12 06:23:02.961510 | ubuntu-focal | "roth": true, 2026-08-12 06:23:02.961535 | ubuntu-focal | "rusr": true, 2026-08-12 06:23:02.961560 | ubuntu-focal | "size": 4096, 2026-08-12 06:23:02.961585 | ubuntu-focal | "uid": 1000, 2026-08-12 06:23:02.961611 | ubuntu-focal | "version": "2490442611", 2026-08-12 06:23:02.961637 | ubuntu-focal | "wgrp": false, 2026-08-12 06:23:02.961665 | ubuntu-focal | "woth": false, 2026-08-12 06:23:02.961690 | ubuntu-focal | "writeable": true, 2026-08-12 06:23:02.961715 | ubuntu-focal | "wusr": true, 2026-08-12 06:23:02.961740 | ubuntu-focal | "xgrp": true, 2026-08-12 06:23:02.961764 | ubuntu-focal | "xoth": true, 2026-08-12 06:23:02.961789 | ubuntu-focal | "xusr": true 2026-08-12 06:23:02.961814 | ubuntu-focal | } 2026-08-12 06:23:02.961839 | ubuntu-focal | } 2026-08-12 06:23:02.961891 | ubuntu-focal | ok: All items complete 2026-08-12 06:23:02.961922 | 2026-08-12 06:23:02.963742 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:23:02.964590 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:23:02.983342 | 2026-08-12 06:23:02.983528 | LOOP [Switch "ansible_host" to private IP] 2026-08-12 06:23:03.322018 | ubuntu-focal | changed: 1 replacements made 2026-08-12 06:23:03.323835 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:23:03.324706 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:23:03.339686 | 2026-08-12 06:23:03.339854 | TASK [Run Molecule scenario] 2026-08-12 06:23:04.024048 | ubuntu-focal | Downloading cpython-3.13.7-linux-x86_64-gnu (download) (30.9MiB) 2026-08-12 06:23:04.720305 | ubuntu-focal | Downloading cpython-3.13.7-linux-x86_64-gnu (download) 2026-08-12 06:23:04.907748 | ubuntu-focal | Using CPython 3.13.7 2026-08-12 06:23:04.907839 | ubuntu-focal | Creating virtual environment at: .venv 2026-08-12 06:23:05.134169 | ubuntu-focal | Downloading ansible-core (2.3MiB) 2026-08-12 06:23:05.134343 | ubuntu-focal | Downloading pygments (1.2MiB) 2026-08-12 06:23:05.141260 | ubuntu-focal | Downloading cryptography (4.3MiB) 2026-08-12 06:23:05.303254 | ubuntu-focal | Downloading cryptography 2026-08-12 06:23:05.341366 | ubuntu-focal | Downloading pygments 2026-08-12 06:23:05.485732 | ubuntu-focal | Downloading ansible-core 2026-08-12 06:23:05.513441 | ubuntu-focal | Installed 36 packages in 27ms 2026-08-12 06:23:06.627714 | ubuntu-focal | INFO Collection 'vexxhost.containers' detected. 2026-08-12 06:23:06.627786 | ubuntu-focal | INFO Scenarios will be used from 'extensions/molecule' 2026-08-12 06:23:07.461186 | ubuntu-focal | CRITICAL 'extensions/molecule/default/molecule.yml' glob failed. Exiting. 2026-08-12 06:23:07.461262 | ubuntu-focal | INFO default scenario not found, disabling shared state. 2026-08-12 06:23:07.461321 | ubuntu-focal | INFO [forget-package > discovery] scenario test matrix: dependency, cleanup, destroy, syntax, create, prepare, converge, idempotence, side_effect, verify, cleanup, destroy 2026-08-12 06:23:07.461393 | ubuntu-focal | INFO [forget-package > prerun] Performing prerun with role_name_check=0... 2026-08-12 06:23:28.931382 | ubuntu-focal | INFO [forget-package > dependency] Executing 2026-08-12 06:23:28.931559 | ubuntu-focal | WARNING [forget-package > dependency] Missing roles requirements file: requirements.yml 2026-08-12 06:23:28.931759 | ubuntu-focal | WARNING [forget-package > dependency] Missing collections requirements file: collections.yml 2026-08-12 06:23:28.931903 | ubuntu-focal | WARNING [forget-package > dependency] Executed: 2 missing (Remove from test_sequence to suppress) 2026-08-12 06:23:28.942121 | ubuntu-focal | INFO [forget-package > cleanup] Executing 2026-08-12 06:23:28.942830 | ubuntu-focal | WARNING [forget-package > cleanup] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-08-12 06:23:28.949127 | ubuntu-focal | INFO [forget-package > destroy] Executing 2026-08-12 06:23:28.949193 | ubuntu-focal | WARNING [forget-package > destroy] Skipping, '--destroy=never' requested. 2026-08-12 06:23:28.949271 | ubuntu-focal | INFO [forget-package > destroy] Executed: Successful 2026-08-12 06:23:28.954268 | ubuntu-focal | INFO [forget-package > syntax] Executing 2026-08-12 06:23:29.467819 | ubuntu-focal | [WARNING]: Deprecation warnings can be disabled by setting `deprecation_warnings=False` in ansible.cfg. 2026-08-12 06:23:29.468009 | ubuntu-focal | [DEPRECATION WARNING]: DEFAULT_MANAGED_STR option. Reason: The `ansible_managed` variable can be set just like any other variable, or a different variable can be used. 2026-08-12 06:23:29.468146 | ubuntu-focal | Alternatives: Set the `ansible_managed` variable, or use any custom variable in templates. This feature will be removed from ansible-core version 2.23. 2026-08-12 06:23:29.468270 | ubuntu-focal | 2026-08-12 06:23:29.814512 | ubuntu-focal | 2026-08-12 06:23:29.814673 | ubuntu-focal | playbook: /home/zuul/src/github.com/vexxhost/ansible-collection-containers/extensions/molecule/forget-package/converge.yml 2026-08-12 06:23:29.875953 | ubuntu-focal | INFO [forget-package > syntax] Executed: Successful 2026-08-12 06:23:29.885962 | ubuntu-focal | INFO [forget-package > create] Executing 2026-08-12 06:23:29.887351 | ubuntu-focal | WARNING [forget-package > create] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-08-12 06:23:29.892322 | ubuntu-focal | INFO [forget-package > prepare] Executing 2026-08-12 06:23:30.340568 | ubuntu-focal | [WARNING]: Deprecation warnings can be disabled by setting `deprecation_warnings=False` in ansible.cfg. 2026-08-12 06:23:30.340880 | ubuntu-focal | [DEPRECATION WARNING]: DEFAULT_MANAGED_STR option. Reason: The `ansible_managed` variable can be set just like any other variable, or a different variable can be used. 2026-08-12 06:23:30.341184 | ubuntu-focal | Alternatives: Set the `ansible_managed` variable, or use any custom variable in templates. This feature will be removed from ansible-core version 2.23. 2026-08-12 06:23:30.341390 | ubuntu-focal | 2026-08-12 06:23:30.695982 | ubuntu-focal | 2026-08-12 06:23:30.696066 | ubuntu-focal | PLAY [Prepare] ***************************************************************** 2026-08-12 06:23:30.696105 | ubuntu-focal | 2026-08-12 06:23:30.696191 | ubuntu-focal | TASK [Gathering Facts] ********************************************************* 2026-08-12 06:23:30.696269 | ubuntu-focal | Wednesday 12 August 2026 06:23:30 +0000 (0:00:00.030) 0:00:00.030 ****** 2026-08-12 06:23:31.884609 | ubuntu-focal | [WARNING]: Host 'ubuntu-focal' is using the discovered Python interpreter at '/usr/bin/python3.8', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.19/reference_appendices/interpreter_discovery.html for more information. 2026-08-12 06:23:31.885539 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:31.885728 | ubuntu-focal | 2026-08-12 06:23:31.885932 | ubuntu-focal | TASK [Install NGINX] *********************************************************** 2026-08-12 06:23:31.886130 | ubuntu-focal | Wednesday 12 August 2026 06:23:31 +0000 (0:00:01.190) 0:00:01.220 ****** 2026-08-12 06:23:45.166326 | ubuntu-focal | changed: [ubuntu-focal] 2026-08-12 06:23:45.166466 | ubuntu-focal | 2026-08-12 06:23:45.166668 | ubuntu-focal | TASK [Ensure NGINX is running] ************************************************* 2026-08-12 06:23:45.166911 | ubuntu-focal | Wednesday 12 August 2026 06:23:45 +0000 (0:00:13.279) 0:00:14.500 ****** 2026-08-12 06:23:45.782444 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:45.782591 | ubuntu-focal | 2026-08-12 06:23:45.782831 | ubuntu-focal | PLAY RECAP ********************************************************************* 2026-08-12 06:23:45.783069 | ubuntu-focal | ubuntu-focal : ok=3 changed=1 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-08-12 06:23:45.783275 | ubuntu-focal | 2026-08-12 06:23:45.783438 | ubuntu-focal | 2026-08-12 06:23:45.783640 | ubuntu-focal | TASKS RECAP ******************************************************************** 2026-08-12 06:23:45.783839 | ubuntu-focal | Wednesday 12 August 2026 06:23:45 +0000 (0:00:00.617) 0:00:15.117 ****** 2026-08-12 06:23:45.783998 | ubuntu-focal | =============================================================================== 2026-08-12 06:23:45.784170 | ubuntu-focal | Install NGINX ---------------------------------------------------------- 13.28s 2026-08-12 06:23:45.784346 | ubuntu-focal | Gathering Facts --------------------------------------------------------- 1.19s 2026-08-12 06:23:45.784522 | ubuntu-focal | Ensure NGINX is running ------------------------------------------------- 0.62s 2026-08-12 06:23:45.859367 | ubuntu-focal | INFO [forget-package > prepare] Executed: Successful 2026-08-12 06:23:45.868475 | ubuntu-focal | INFO [forget-package > converge] Executing 2026-08-12 06:23:46.330168 | ubuntu-focal | [WARNING]: Deprecation warnings can be disabled by setting `deprecation_warnings=False` in ansible.cfg. 2026-08-12 06:23:46.330252 | ubuntu-focal | [DEPRECATION WARNING]: DEFAULT_MANAGED_STR option. Reason: The `ansible_managed` variable can be set just like any other variable, or a different variable can be used. 2026-08-12 06:23:46.330481 | ubuntu-focal | Alternatives: Set the `ansible_managed` variable, or use any custom variable in templates. This feature will be removed from ansible-core version 2.23. 2026-08-12 06:23:46.330637 | ubuntu-focal | 2026-08-12 06:23:46.623304 | ubuntu-focal | 2026-08-12 06:23:46.623477 | ubuntu-focal | PLAY [Converge] **************************************************************** 2026-08-12 06:23:46.623718 | ubuntu-focal | 2026-08-12 06:23:46.623903 | ubuntu-focal | TASK [Gathering Facts] ********************************************************* 2026-08-12 06:23:46.624077 | ubuntu-focal | Wednesday 12 August 2026 06:23:46 +0000 (0:00:00.007) 0:00:00.007 ****** 2026-08-12 06:23:47.663858 | ubuntu-focal | [WARNING]: Host 'ubuntu-focal' is using the discovered Python interpreter at '/usr/bin/python3.8', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.19/reference_appendices/interpreter_discovery.html for more information. 2026-08-12 06:23:47.665756 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:47.665861 | ubuntu-focal | 2026-08-12 06:23:47.665982 | ubuntu-focal | TASK [vexxhost.containers.forget_package : Forget package] ********************* 2026-08-12 06:23:47.666098 | ubuntu-focal | Wednesday 12 August 2026 06:23:47 +0000 (0:00:01.043) 0:00:01.050 ****** 2026-08-12 06:23:48.011981 | ubuntu-focal | [WARNING]: Module remote_tmp /root/.ansible/tmp did not exist and was created with a mode of 0700, this may cause issues when running as another user. To avoid this, create the remote_tmp dir with the correct permissions manually 2026-08-12 06:23:48.015905 | ubuntu-focal | changed: [ubuntu-focal] 2026-08-12 06:23:48.016118 | ubuntu-focal | 2026-08-12 06:23:48.016315 | ubuntu-focal | PLAY RECAP ********************************************************************* 2026-08-12 06:23:48.016527 | ubuntu-focal | ubuntu-focal : ok=2 changed=1 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-08-12 06:23:48.016701 | ubuntu-focal | 2026-08-12 06:23:48.016868 | ubuntu-focal | 2026-08-12 06:23:48.017063 | ubuntu-focal | TASKS RECAP ******************************************************************** 2026-08-12 06:23:48.017253 | ubuntu-focal | Wednesday 12 August 2026 06:23:48 +0000 (0:00:00.350) 0:00:01.400 ****** 2026-08-12 06:23:48.017426 | ubuntu-focal | =============================================================================== 2026-08-12 06:23:48.017609 | ubuntu-focal | Gathering Facts --------------------------------------------------------- 1.04s 2026-08-12 06:23:48.017795 | ubuntu-focal | vexxhost.containers.forget_package : Forget package --------------------- 0.35s 2026-08-12 06:23:48.143058 | ubuntu-focal | INFO [forget-package > converge] Executed: Successful 2026-08-12 06:23:48.152146 | ubuntu-focal | INFO [forget-package > idempotence] Executing 2026-08-12 06:23:48.638104 | ubuntu-focal | [WARNING]: Deprecation warnings can be disabled by setting `deprecation_warnings=False` in ansible.cfg. 2026-08-12 06:23:48.638199 | ubuntu-focal | [DEPRECATION WARNING]: DEFAULT_MANAGED_STR option. Reason: The `ansible_managed` variable can be set just like any other variable, or a different variable can be used. 2026-08-12 06:23:48.638499 | ubuntu-focal | Alternatives: Set the `ansible_managed` variable, or use any custom variable in templates. This feature will be removed from ansible-core version 2.23. 2026-08-12 06:23:48.638743 | ubuntu-focal | 2026-08-12 06:23:48.929452 | ubuntu-focal | 2026-08-12 06:23:48.929547 | ubuntu-focal | PLAY [Converge] **************************************************************** 2026-08-12 06:23:48.929737 | ubuntu-focal | 2026-08-12 06:23:48.929992 | ubuntu-focal | TASK [Gathering Facts] ********************************************************* 2026-08-12 06:23:48.930228 | ubuntu-focal | Wednesday 12 August 2026 06:23:48 +0000 (0:00:00.007) 0:00:00.007 ****** 2026-08-12 06:23:49.940561 | ubuntu-focal | [WARNING]: Host 'ubuntu-focal' is using the discovered Python interpreter at '/usr/bin/python3.8', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.19/reference_appendices/interpreter_discovery.html for more information. 2026-08-12 06:23:49.942210 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:49.942385 | ubuntu-focal | 2026-08-12 06:23:49.942573 | ubuntu-focal | TASK [vexxhost.containers.forget_package : Forget package] ********************* 2026-08-12 06:23:49.942783 | ubuntu-focal | Wednesday 12 August 2026 06:23:49 +0000 (0:00:01.013) 0:00:01.020 ****** 2026-08-12 06:23:50.286732 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:50.286880 | ubuntu-focal | 2026-08-12 06:23:50.287075 | ubuntu-focal | PLAY RECAP ********************************************************************* 2026-08-12 06:23:50.287303 | ubuntu-focal | ubuntu-focal : ok=2 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-08-12 06:23:50.287467 | ubuntu-focal | 2026-08-12 06:23:50.287649 | ubuntu-focal | 2026-08-12 06:23:50.287825 | ubuntu-focal | TASKS RECAP ******************************************************************** 2026-08-12 06:23:50.288025 | ubuntu-focal | Wednesday 12 August 2026 06:23:50 +0000 (0:00:00.344) 0:00:01.365 ****** 2026-08-12 06:23:50.288231 | ubuntu-focal | =============================================================================== 2026-08-12 06:23:50.288398 | ubuntu-focal | Gathering Facts --------------------------------------------------------- 1.01s 2026-08-12 06:23:50.288571 | ubuntu-focal | vexxhost.containers.forget_package : Forget package --------------------- 0.34s 2026-08-12 06:23:50.364376 | ubuntu-focal | INFO [forget-package > idempotence] Executed: Successful 2026-08-12 06:23:50.373036 | ubuntu-focal | INFO [forget-package > side_effect] Executing 2026-08-12 06:23:50.373449 | ubuntu-focal | WARNING [forget-package > side_effect] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-08-12 06:23:50.378870 | ubuntu-focal | INFO [forget-package > verify] Executing 2026-08-12 06:23:50.860595 | ubuntu-focal | [WARNING]: Deprecation warnings can be disabled by setting `deprecation_warnings=False` in ansible.cfg. 2026-08-12 06:23:50.860809 | ubuntu-focal | [DEPRECATION WARNING]: DEFAULT_MANAGED_STR option. Reason: The `ansible_managed` variable can be set just like any other variable, or a different variable can be used. 2026-08-12 06:23:50.860991 | ubuntu-focal | Alternatives: Set the `ansible_managed` variable, or use any custom variable in templates. This feature will be removed from ansible-core version 2.23. 2026-08-12 06:23:50.861139 | ubuntu-focal | 2026-08-12 06:23:51.167283 | ubuntu-focal | 2026-08-12 06:23:51.167762 | ubuntu-focal | PLAY [Verify] ****************************************************************** 2026-08-12 06:23:51.168076 | ubuntu-focal | 2026-08-12 06:23:51.168400 | ubuntu-focal | TASK [Gathering Facts] ********************************************************* 2026-08-12 06:23:51.168619 | ubuntu-focal | Wednesday 12 August 2026 06:23:51 +0000 (0:00:00.007) 0:00:00.007 ****** 2026-08-12 06:23:52.159224 | ubuntu-focal | [WARNING]: Host 'ubuntu-focal' is using the discovered Python interpreter at '/usr/bin/python3.8', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.19/reference_appendices/interpreter_discovery.html for more information. 2026-08-12 06:23:52.162128 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:52.162245 | ubuntu-focal | 2026-08-12 06:23:52.162374 | ubuntu-focal | TASK [Populate package facts] ************************************************** 2026-08-12 06:23:52.162501 | ubuntu-focal | Wednesday 12 August 2026 06:23:52 +0000 (0:00:00.995) 0:00:01.002 ****** 2026-08-12 06:23:54.063577 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:54.063664 | ubuntu-focal | 2026-08-12 06:23:54.063677 | ubuntu-focal | TASK [Populate service facts] ************************************************** 2026-08-12 06:23:54.063773 | ubuntu-focal | Wednesday 12 August 2026 06:23:54 +0000 (0:00:01.901) 0:00:02.904 ****** 2026-08-12 06:23:55.761673 | ubuntu-focal | ok: [ubuntu-focal] 2026-08-12 06:23:55.761760 | ubuntu-focal | 2026-08-12 06:23:55.761836 | ubuntu-focal | TASK [Assert that the NGINX package is not installed] ************************** 2026-08-12 06:23:55.761947 | ubuntu-focal | Wednesday 12 August 2026 06:23:55 +0000 (0:00:01.698) 0:00:04.602 ****** 2026-08-12 06:23:55.790645 | ubuntu-focal | ok: [ubuntu-focal] => { 2026-08-12 06:23:55.790755 | ubuntu-focal | "changed": false, 2026-08-12 06:23:55.790869 | ubuntu-focal | "msg": "All assertions passed" 2026-08-12 06:23:55.790977 | ubuntu-focal | } 2026-08-12 06:23:55.791077 | ubuntu-focal | 2026-08-12 06:23:55.791191 | ubuntu-focal | TASK [Assert that the NGINX service is still up] ******************************* 2026-08-12 06:23:55.791302 | ubuntu-focal | Wednesday 12 August 2026 06:23:55 +0000 (0:00:00.029) 0:00:04.631 ****** 2026-08-12 06:23:55.816935 | ubuntu-focal | ok: [ubuntu-focal] => { 2026-08-12 06:23:55.817063 | ubuntu-focal | "changed": false, 2026-08-12 06:23:55.817276 | ubuntu-focal | "msg": "All assertions passed" 2026-08-12 06:23:55.817438 | ubuntu-focal | } 2026-08-12 06:23:55.817593 | ubuntu-focal | 2026-08-12 06:23:55.817755 | ubuntu-focal | PLAY RECAP ********************************************************************* 2026-08-12 06:23:55.817943 | ubuntu-focal | ubuntu-focal : ok=5 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-08-12 06:23:55.818093 | ubuntu-focal | 2026-08-12 06:23:55.818244 | ubuntu-focal | 2026-08-12 06:23:55.818405 | ubuntu-focal | TASKS RECAP ******************************************************************** 2026-08-12 06:23:55.818576 | ubuntu-focal | Wednesday 12 August 2026 06:23:55 +0000 (0:00:00.026) 0:00:04.657 ****** 2026-08-12 06:23:55.818774 | ubuntu-focal | =============================================================================== 2026-08-12 06:23:55.818948 | ubuntu-focal | Populate package facts -------------------------------------------------- 1.90s 2026-08-12 06:23:55.819116 | ubuntu-focal | Populate service facts -------------------------------------------------- 1.70s 2026-08-12 06:23:55.819283 | ubuntu-focal | Gathering Facts --------------------------------------------------------- 1.00s 2026-08-12 06:23:55.819453 | ubuntu-focal | Assert that the NGINX package is not installed -------------------------- 0.03s 2026-08-12 06:23:55.819619 | ubuntu-focal | Assert that the NGINX service is still up ------------------------------- 0.03s 2026-08-12 06:23:55.973645 | ubuntu-focal | INFO [forget-package > verify] Executed: Successful 2026-08-12 06:23:55.983459 | ubuntu-focal | INFO [forget-package > cleanup] Executing 2026-08-12 06:23:55.983954 | ubuntu-focal | WARNING [forget-package > cleanup] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-08-12 06:23:55.989505 | ubuntu-focal | INFO [forget-package > destroy] Executing 2026-08-12 06:23:55.989570 | ubuntu-focal | WARNING [forget-package > destroy] Skipping, '--destroy=never' requested. 2026-08-12 06:23:55.989637 | ubuntu-focal | INFO [forget-package > destroy] Executed: Successful 2026-08-12 06:23:55.989906 | ubuntu-focal | WARNING Molecule executed 1 scenario (1 missing files) 2026-08-12 06:23:56.577399 | ubuntu-focal | ok: Runtime: 0:00:52.388382 2026-08-12 06:23:56.581745 | 2026-08-12 06:23:56.581794 | PLAY RECAP 2026-08-12 06:23:56.581837 | ubuntu-focal | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-08-12 06:23:56.581860 | 2026-08-12 06:23:56.693713 | RUN END RESULT_NORMAL: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/run.yaml@main] 2026-08-12 06:23:56.696393 | POST-RUN START: [trusted : github.com/vexxhost/zuul-config/playbooks/base/post.yaml@main] 2026-08-12 06:23:57.281545 | 2026-08-12 06:23:57.281767 | PLAY [all] 2026-08-12 06:23:57.294080 | 2026-08-12 06:23:57.294242 | TASK [fetch-output : Set log path for multiple nodes] 2026-08-12 06:23:57.339728 | ubuntu-focal | skipping: Conditional result was False 2026-08-12 06:23:57.348990 | 2026-08-12 06:23:57.349230 | TASK [fetch-output : Set log path for single node] 2026-08-12 06:23:57.394533 | ubuntu-focal | ok 2026-08-12 06:23:57.402341 | 2026-08-12 06:23:57.402522 | LOOP [fetch-output : Ensure local output dirs] 2026-08-12 06:23:57.784702 | ubuntu-focal -> localhost | ok: "/var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/logs" 2026-08-12 06:23:57.991841 | ubuntu-focal -> localhost | changed: "/var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/artifacts" 2026-08-12 06:23:58.194595 | ubuntu-focal -> localhost | changed: "/var/lib/zuul/builds/9824320767b34bfb9c6a0869e587bb1d/work/docs" 2026-08-12 06:23:58.209497 | 2026-08-12 06:23:58.209689 | LOOP [fetch-output : Collect logs, artifacts and docs] 2026-08-12 06:23:58.808046 | ubuntu-focal | ok 2026-08-12 06:23:58.808398 | ubuntu-focal | changed: All items complete 2026-08-12 06:23:58.808462 | 2026-08-12 06:23:59.212815 | ubuntu-focal | changed: .d..t...... ./ 2026-08-12 06:23:59.614028 | ubuntu-focal | changed: .d..t...... ./ 2026-08-12 06:23:59.643773 | 2026-08-12 06:23:59.643943 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2026-08-12 06:24:00.071974 | ubuntu-focal -> localhost | ok: Item: artifacts Runtime: 0:00:00.005774 2026-08-12 06:24:00.290595 | ubuntu-focal -> localhost | ok: Item: docs Runtime: 0:00:00.008272 2026-08-12 06:24:00.304984 | 2026-08-12 06:24:00.305111 | PLAY [all] 2026-08-12 06:24:00.311082 | 2026-08-12 06:24:00.311149 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2026-08-12 06:24:00.719294 | ubuntu-focal | changed 2026-08-12 06:24:00.725708 | 2026-08-12 06:24:00.725762 | PLAY RECAP 2026-08-12 06:24:00.725823 | ubuntu-focal | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2026-08-12 06:24:00.725847 | 2026-08-12 06:24:00.867843 | POST-RUN END RESULT_NORMAL: [trusted : github.com/vexxhost/zuul-config/playbooks/base/post.yaml@main] 2026-08-12 06:24:00.871467 | POST-RUN START: [trusted : github.com/vexxhost/zuul-config/playbooks/base/post-logs.yaml@main] 2026-08-12 06:24:01.455854 | 2026-08-12 06:24:01.455988 | PLAY [localhost] 2026-08-12 06:24:01.466851 | 2026-08-12 06:24:01.466937 | TASK [Generate Zuul manifest] 2026-08-12 06:24:01.499454 | localhost | ok 2026-08-12 06:24:01.518153 | 2026-08-12 06:24:01.518235 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2026-08-12 06:24:01.894441 | localhost | changed 2026-08-12 06:24:01.906170 | 2026-08-12 06:24:01.906246 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2026-08-12 06:24:01.939375 | localhost | ok 2026-08-12 06:24:01.948396 | 2026-08-12 06:24:01.948485 | TASK [Upload logs] 2026-08-12 06:24:01.968748 | localhost | ok 2026-08-12 06:24:02.027804 | 2026-08-12 06:24:02.027902 | TASK [Set zuul-log-path fact] 2026-08-12 06:24:02.048108 | localhost | ok 2026-08-12 06:24:02.061218 | 2026-08-12 06:24:02.061285 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-08-12 06:24:02.092374 | localhost | ok 2026-08-12 06:24:02.101679 | 2026-08-12 06:24:02.101745 | TASK [upload-logs : Create log directories] 2026-08-12 06:24:02.524753 | localhost | changed 2026-08-12 06:24:02.533209 | 2026-08-12 06:24:02.533305 | TASK [upload-logs : Ensure logs are readable before uploading] 2026-08-12 06:24:02.961454 | localhost -> localhost | ok: Runtime: 0:00:00.004890 2026-08-12 06:24:02.967892 | 2026-08-12 06:24:02.967960 | TASK [upload-logs : Upload logs to log server] 2026-08-12 06:24:03.443041 | localhost | Output suppressed because no_log was given 2026-08-12 06:24:03.447502 | 2026-08-12 06:24:03.447571 | LOOP [upload-logs : Compress console log and json output] 2026-08-12 06:24:03.494718 | localhost | skipping: Conditional result was False 2026-08-12 06:24:03.501842 | localhost | skipping: Conditional result was False 2026-08-12 06:24:03.511080 | 2026-08-12 06:24:03.511280 | LOOP [upload-logs : Upload compressed console log and json output] 2026-08-12 06:24:03.553891 | localhost | skipping: Conditional result was False 2026-08-12 06:24:03.554266 | 2026-08-12 06:24:03.558320 | localhost | skipping: Conditional result was False 2026-08-12 06:24:03.577010 | 2026-08-12 06:24:03.577236 | LOOP [upload-logs : Upload console log and json output]