2026-02-16 21:05:31.593826 | Job console starting 2026-02-16 21:05:31.603219 | Updating git repos 2026-02-16 21:05:31.710824 | Cloning repos into workspace 2026-02-16 21:05:31.767487 | Restoring repo states 2026-02-16 21:05:31.781242 | Merging changes 2026-02-16 21:05:32.231798 | Checking out repos 2026-02-16 21:05:32.279091 | Preparing playbooks 2026-02-16 21:05:33.317423 | Running Ansible setup 2026-02-16 21:05:37.017905 | PRE-RUN START: [trusted : vexxhost.dev/zuul-config/playbooks/base/pre.yaml@main] 2026-02-16 21:05:37.589287 | 2026-02-16 21:05:37.589423 | PLAY [localhost] 2026-02-16 21:05:37.596873 | 2026-02-16 21:05:37.596945 | TASK [Gathering Facts] 2026-02-16 21:05:38.475857 | localhost | ok 2026-02-16 21:05:38.482864 | 2026-02-16 21:05:38.482948 | TASK [Setup log path fact] 2026-02-16 21:05:38.506988 | localhost | ok 2026-02-16 21:05:38.521988 | 2026-02-16 21:05:38.522066 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-02-16 21:05:38.553229 | localhost | ok 2026-02-16 21:05:38.614017 | 2026-02-16 21:05:38.614130 | TASK [emit-job-header : Print job information] 2026-02-16 21:05:38.662155 | # Job Information 2026-02-16 21:05:38.662491 | Ansible Version: 2.16.15 2026-02-16 21:05:38.662579 | Job: ansible-collection-kubernetes-molecule-helm 2026-02-16 21:05:38.662629 | Pipeline: check 2026-02-16 21:05:38.662674 | Executor: 3a2793d2bd32 2026-02-16 21:05:38.662717 | Triggered by: https://github.com/vexxhost/ansible-collection-kubernetes/pull/228 2026-02-16 21:05:38.662765 | Event ID: 078dc310-0b7b-11f1-98c1-99ab71959742 2026-02-16 21:05:38.666292 | 2026-02-16 21:05:38.666363 | LOOP [emit-job-header : Print node information] 2026-02-16 21:05:38.761471 | localhost | ok: 2026-02-16 21:05:38.761667 | localhost | # Node Information 2026-02-16 21:05:38.761695 | localhost | Inventory Hostname: controller 2026-02-16 21:05:38.761716 | localhost | Hostname: np0000155763 2026-02-16 21:05:38.761735 | localhost | Username: zuul 2026-02-16 21:05:38.761756 | localhost | Distro: Debian 13.3 2026-02-16 21:05:38.761775 | localhost | Provider: yul1 2026-02-16 21:05:38.761793 | localhost | Region: ca-ymq-1 2026-02-16 21:05:38.761811 | localhost | Label: debian-trixie 2026-02-16 21:05:38.761829 | localhost | Product Name: OpenStack Nova 2026-02-16 21:05:38.761847 | localhost | Interface IP: 199.204.45.41 2026-02-16 21:05:38.769661 | 2026-02-16 21:05:38.791925 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2026-02-16 21:05:39.233785 | localhost -> localhost | changed 2026-02-16 21:05:39.239553 | 2026-02-16 21:05:39.239629 | TASK [log-inventory : Copy ansible inventory to logs dir] 2026-02-16 21:05:40.228817 | localhost -> localhost | changed 2026-02-16 21:05:40.238654 | 2026-02-16 21:05:40.238744 | PLAY [all] 2026-02-16 21:05:40.248796 | 2026-02-16 21:05:40.248868 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2026-02-16 21:05:40.518145 | controller -> localhost | ok 2026-02-16 21:05:40.523490 | 2026-02-16 21:05:40.523568 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2026-02-16 21:05:40.554073 | controller | ok 2026-02-16 21:05:40.569105 | controller | included: /var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2026-02-16 21:05:40.575231 | 2026-02-16 21:05:40.575293 | TASK [add-build-sshkey : Create Temp SSH key] 2026-02-16 21:05:44.105375 | controller -> localhost | Generating public/private rsa key pair. 2026-02-16 21:05:44.105907 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/0dd7ea616cfa4c7bb936cefbf4b93562_id_rsa 2026-02-16 21:05:44.105941 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/0dd7ea616cfa4c7bb936cefbf4b93562_id_rsa.pub 2026-02-16 21:05:44.105965 | controller -> localhost | The key fingerprint is: 2026-02-16 21:05:44.105987 | controller -> localhost | SHA256:lvXll0JqlqS6yTzDfwP5GldCmlfjPAySZJ9FBIS6PDQ zuul-build-sshkey 2026-02-16 21:05:44.106024 | controller -> localhost | The key's randomart image is: 2026-02-16 21:05:44.106046 | controller -> localhost | +---[RSA 3072]----+ 2026-02-16 21:05:44.106069 | controller -> localhost | | ooo++ | 2026-02-16 21:05:44.106090 | controller -> localhost | | o.o o | 2026-02-16 21:05:44.106109 | controller -> localhost | | .o.* +. | 2026-02-16 21:05:44.106129 | controller -> localhost | | E oB.Xo. .| 2026-02-16 21:05:44.106148 | controller -> localhost | | o S+.B.B...| 2026-02-16 21:05:44.106167 | controller -> localhost | | =.o+ o o. | 2026-02-16 21:05:44.106185 | controller -> localhost | | ....o. | 2026-02-16 21:05:44.106204 | controller -> localhost | | o+o o+ | 2026-02-16 21:05:44.106226 | controller -> localhost | | =+oo . | 2026-02-16 21:05:44.106246 | controller -> localhost | +----[SHA256]-----+ 2026-02-16 21:05:44.106292 | controller -> localhost | ok: Runtime: 0:00:03.043299 2026-02-16 21:05:44.110414 | 2026-02-16 21:05:44.110481 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2026-02-16 21:05:44.129358 | controller | ok 2026-02-16 21:05:44.136884 | controller | included: /var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2026-02-16 21:05:44.153107 | 2026-02-16 21:05:44.153256 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2026-02-16 21:05:44.168458 | controller | skipping: Conditional result was False 2026-02-16 21:05:44.174512 | 2026-02-16 21:05:44.176797 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2026-02-16 21:05:44.772775 | controller | changed 2026-02-16 21:05:44.779076 | 2026-02-16 21:05:44.779164 | TASK [add-build-sshkey : Make sure user has a .ssh] 2026-02-16 21:05:44.982395 | controller | ok 2026-02-16 21:05:44.988569 | 2026-02-16 21:05:45.035717 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2026-02-16 21:05:45.694725 | controller | changed 2026-02-16 21:05:45.701820 | 2026-02-16 21:05:45.701890 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2026-02-16 21:05:46.224093 | controller | changed 2026-02-16 21:05:46.228164 | 2026-02-16 21:05:46.228226 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2026-02-16 21:05:46.253382 | controller | skipping: Conditional result was False 2026-02-16 21:05:46.263987 | 2026-02-16 21:05:46.264161 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2026-02-16 21:05:46.627525 | controller -> localhost | changed 2026-02-16 21:05:46.642318 | 2026-02-16 21:05:46.642455 | TASK [add-build-sshkey : Add back temp key] 2026-02-16 21:05:46.944925 | controller -> localhost | Identity added: /var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/0dd7ea616cfa4c7bb936cefbf4b93562_id_rsa (zuul-build-sshkey) 2026-02-16 21:05:46.945298 | controller -> localhost | ok: Runtime: 0:00:00.013413 2026-02-16 21:05:46.950959 | 2026-02-16 21:05:46.951056 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2026-02-16 21:05:47.321979 | controller | ok 2026-02-16 21:05:47.328687 | 2026-02-16 21:05:47.328844 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2026-02-16 21:05:47.354685 | controller | skipping: Conditional result was False 2026-02-16 21:05:47.365634 | 2026-02-16 21:05:47.365808 | TASK [prepare-workspace : Start zuul_console daemon.] 2026-02-16 21:05:47.732075 | controller | ok 2026-02-16 21:05:47.738934 | 2026-02-16 21:05:47.739061 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2026-02-16 21:05:48.783610 | controller | Output suppressed because no_log was given 2026-02-16 21:05:48.798623 | 2026-02-16 21:05:48.798712 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2026-02-16 21:05:48.999121 | controller | ok: "logs" 2026-02-16 21:05:48.999390 | controller | ok: All items complete 2026-02-16 21:05:48.999419 | 2026-02-16 21:05:49.171364 | controller | ok: "artifacts" 2026-02-16 21:05:49.352945 | controller | ok: "docs" 2026-02-16 21:05:49.359655 | 2026-02-16 21:05:49.359795 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2026-02-16 21:05:49.584779 | controller | changed: "logs" 2026-02-16 21:05:49.769391 | controller | changed: "artifacts" 2026-02-16 21:05:49.942596 | controller | changed: "docs" 2026-02-16 21:05:49.959139 | 2026-02-16 21:05:49.959268 | PLAY RECAP 2026-02-16 21:05:49.959331 | controller | ok: 15 changed: 8 unreachable: 0 failed: 0 skipped: 3 rescued: 0 ignored: 0 2026-02-16 21:05:49.959370 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-02-16 21:05:49.959400 | 2026-02-16 21:05:50.085742 | PRE-RUN END RESULT_NORMAL: [trusted : vexxhost.dev/zuul-config/playbooks/base/pre.yaml@main] 2026-02-16 21:05:50.088621 | PRE-RUN START: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/pre.yaml@main] 2026-02-16 21:05:50.697211 | 2026-02-16 21:05:50.697442 | PLAY [all] 2026-02-16 21:05:50.709889 | 2026-02-16 21:05:50.710033 | TASK [setup-uv : Extract archive] 2026-02-16 21:05:52.978532 | controller | changed 2026-02-16 21:05:52.983802 | 2026-02-16 21:05:52.983879 | TASK [setup-uv : Print version] 2026-02-16 21:05:54.214291 | controller | uv 0.8.13 2026-02-16 21:05:53.515758 | controller | ok: Runtime: 0:00:00.013559 2026-02-16 21:05:53.529729 | 2026-02-16 21:05:53.529813 | PLAY RECAP 2026-02-16 21:05:53.529860 | controller | ok: 2 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-02-16 21:05:53.529885 | 2026-02-16 21:05:53.713756 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/pre.yaml@main] 2026-02-16 21:05:53.716578 | RUN START: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/run.yaml@main] 2026-02-16 21:05:54.330178 | 2026-02-16 21:05:54.330328 | PLAY [all] 2026-02-16 21:05:54.342727 | 2026-02-16 21:05:54.342917 | TASK [Copy inventory file for Zuul] 2026-02-16 21:05:55.327186 | controller | changed 2026-02-16 21:05:55.331467 | 2026-02-16 21:05:55.331544 | TASK [Switch "ansible_host" to private IP] 2026-02-16 21:05:55.644171 | controller | changed: 1 replacements made 2026-02-16 21:05:55.649407 | 2026-02-16 21:05:55.649511 | TASK [Run Molecule scenario] 2026-02-16 21:05:56.965193 | controller | Using CPython 3.13.5 interpreter at: /usr/bin/python3 2026-02-16 21:05:56.965270 | controller | Creating virtual environment at: .venv 2026-02-16 21:05:57.360758 | controller | Downloading pygments (1.2MiB) 2026-02-16 21:05:57.363098 | controller | Downloading ansible-core (2.3MiB) 2026-02-16 21:05:57.363797 | controller | Downloading cryptography (4.3MiB) 2026-02-16 21:05:57.557431 | controller | Downloading cryptography 2026-02-16 21:05:57.598135 | controller | Downloading pygments 2026-02-16 21:05:57.702550 | controller | Downloading ansible-core 2026-02-16 21:05:57.752052 | controller | Installed 36 packages in 48ms 2026-02-16 21:05:58.393339 | controller | INFO Collection 'vexxhost.kubernetes' detected. 2026-02-16 21:05:58.393399 | controller | INFO Scenarios will be used from 'extensions/molecule' 2026-02-16 21:05:59.130788 | controller | CRITICAL 'extensions/molecule/default/molecule.yml' glob failed. Exiting. 2026-02-16 21:05:59.130819 | controller | INFO default scenario not found, disabling shared state. 2026-02-16 21:05:59.130994 | controller | INFO [helm > discovery] scenario test matrix: dependency, cleanup, destroy, syntax, create, prepare, converge, idempotence, side_effect, verify, cleanup, destroy 2026-02-16 21:05:59.131071 | controller | INFO [helm > prerun] Performing prerun with role_name_check=0... 2026-02-16 21:07:20.707539 | controller | INFO [helm > dependency] Executing 2026-02-16 21:07:20.707688 | controller | WARNING [helm > dependency] Missing roles requirements file: requirements.yml 2026-02-16 21:07:20.707864 | controller | WARNING [helm > dependency] Missing collections requirements file: collections.yml 2026-02-16 21:07:20.707971 | controller | WARNING [helm > dependency] Executed: 2 missing (Remove from test_sequence to suppress) 2026-02-16 21:07:20.713241 | controller | INFO [helm > cleanup] Executing 2026-02-16 21:07:20.713559 | controller | WARNING [helm > cleanup] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-02-16 21:07:20.718945 | controller | INFO [helm > destroy] Executing 2026-02-16 21:07:20.719004 | controller | WARNING [helm > destroy] Skipping, '--destroy=never' requested. 2026-02-16 21:07:20.719067 | controller | INFO [helm > destroy] Executed: Successful 2026-02-16 21:07:20.724214 | controller | INFO [helm > syntax] Executing 2026-02-16 21:07:21.585078 | controller | 2026-02-16 21:07:21.585246 | controller | playbook: /home/zuul/src/github.com/vexxhost/ansible-collection-kubernetes/extensions/molecule/helm/converge.yml 2026-02-16 21:07:21.642483 | controller | INFO [helm > syntax] Executed: Successful 2026-02-16 21:07:21.650836 | controller | INFO [helm > create] Executing 2026-02-16 21:07:21.652306 | controller | WARNING [helm > create] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-02-16 21:07:21.657562 | controller | INFO [helm > prepare] Executing 2026-02-16 21:07:22.458569 | controller | 2026-02-16 21:07:22.458592 | controller | PLAY [Prepare] ***************************************************************** 2026-02-16 21:07:22.458597 | controller | 2026-02-16 21:07:22.458600 | controller | TASK [Gathering Facts] ********************************************************* 2026-02-16 21:07:22.458604 | controller | Monday 16 February 2026 21:07:22 +0000 (0:00:00.028) 0:00:00.028 ******* 2026-02-16 21:07:23.647489 | controller | [WARNING]: Host 'controller' is using the discovered Python interpreter at '/usr/bin/python3.13', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.20/reference_appendices/interpreter_discovery.html for more information. 2026-02-16 21:07:23.649429 | controller | ok: [controller] 2026-02-16 21:07:23.649534 | controller | 2026-02-16 21:07:23.649650 | controller | TASK [Install Debian packages] ************************************************* 2026-02-16 21:07:23.649764 | controller | Monday 16 February 2026 21:07:23 +0000 (0:00:01.192) 0:00:01.221 ******* 2026-02-16 21:07:28.446250 | controller | ok: [controller] 2026-02-16 21:07:28.446302 | controller | 2026-02-16 21:07:28.446446 | controller | PLAY RECAP ********************************************************************* 2026-02-16 21:07:28.446583 | controller | controller : ok=2 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-02-16 21:07:28.446693 | controller | 2026-02-16 21:07:28.446766 | controller | 2026-02-16 21:07:28.446852 | controller | TASKS RECAP ******************************************************************** 2026-02-16 21:07:28.446940 | controller | Monday 16 February 2026 21:07:28 +0000 (0:00:04.796) 0:00:06.018 ******* 2026-02-16 21:07:28.447023 | controller | =============================================================================== 2026-02-16 21:07:28.447107 | controller | Install Debian packages ------------------------------------------------- 4.80s 2026-02-16 21:07:28.447192 | controller | Gathering Facts --------------------------------------------------------- 1.19s 2026-02-16 21:07:28.522619 | controller | INFO [helm > prepare] Executed: Successful 2026-02-16 21:07:28.533112 | controller | INFO [helm > converge] Executing 2026-02-16 21:07:29.321301 | controller | 2026-02-16 21:07:29.321629 | controller | PLAY [Converge] **************************************************************** 2026-02-16 21:07:29.321855 | controller | 2026-02-16 21:07:29.322130 | controller | TASK [Gathering Facts] ********************************************************* 2026-02-16 21:07:29.323568 | controller | Monday 16 February 2026 21:07:29 +0000 (0:00:00.012) 0:00:00.012 ******* 2026-02-16 21:07:30.319938 | controller | [WARNING]: Host 'controller' is using the discovered Python interpreter at '/usr/bin/python3.13', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.20/reference_appendices/interpreter_discovery.html for more information. 2026-02-16 21:07:30.322298 | controller | ok: [controller] 2026-02-16 21:07:30.322382 | controller | 2026-02-16 21:07:30.322473 | controller | TASK [vexxhost.containers.forget_package : Forget package] ********************* 2026-02-16 21:07:30.322562 | controller | Monday 16 February 2026 21:07:30 +0000 (0:00:01.001) 0:00:01.014 ******* 2026-02-16 21:07:30.769993 | controller | ok: [controller] 2026-02-16 21:07:30.770013 | controller | 2026-02-16 21:07:30.770018 | controller | TASK [vexxhost.containers.package : Update state for tar] ********************** 2026-02-16 21:07:30.770021 | controller | Monday 16 February 2026 21:07:30 +0000 (0:00:00.445) 0:00:01.460 ******* 2026-02-16 21:07:31.902345 | controller | ok: [controller] 2026-02-16 21:07:31.902395 | controller | 2026-02-16 21:07:31.902469 | controller | TASK [vexxhost.containers.directory : Create directory (/var/lib/downloads)] *** 2026-02-16 21:07:31.902543 | controller | Monday 16 February 2026 21:07:31 +0000 (0:00:01.133) 0:00:02.594 ******* 2026-02-16 21:07:32.327574 | controller | changed: [controller] 2026-02-16 21:07:32.327633 | controller | 2026-02-16 21:07:32.327639 | controller | TASK [vexxhost.containers.download_artifact : Starting download of file] ******* 2026-02-16 21:07:32.327645 | controller | Monday 16 February 2026 21:07:32 +0000 (0:00:00.421) 0:00:03.016 ******* 2026-02-16 21:07:32.380046 | controller | ok: [controller] => { 2026-02-16 21:07:32.380247 | controller | "msg": "https://get.helm.sh/helm-v3.11.2-linux-amd64.tar.gz" 2026-02-16 21:07:32.380436 | controller | } 2026-02-16 21:07:32.380636 | controller | 2026-02-16 21:07:32.380904 | controller | TASK [vexxhost.containers.download_artifact : Download item] ******************* 2026-02-16 21:07:32.381107 | controller | Monday 16 February 2026 21:07:32 +0000 (0:00:00.055) 0:00:03.071 ******* 2026-02-16 21:07:33.176157 | controller | [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-02-16 21:07:33.182836 | controller | changed: [controller] 2026-02-16 21:07:33.183141 | controller | 2026-02-16 21:07:33.183423 | controller | TASK [vexxhost.containers.download_artifact : Extract archive] ***************** 2026-02-16 21:07:33.183762 | controller | Monday 16 February 2026 21:07:33 +0000 (0:00:00.803) 0:00:03.874 ******* 2026-02-16 21:07:35.226910 | controller | changed: [controller] 2026-02-16 21:07:35.227095 | controller | 2026-02-16 21:07:35.227270 | controller | TASK [vexxhost.kubernetes.helm : Remove Helm repository] *********************** 2026-02-16 21:07:35.227434 | controller | Monday 16 February 2026 21:07:35 +0000 (0:00:02.043) 0:00:05.918 ******* 2026-02-16 21:07:35.706229 | controller | ok: [controller] 2026-02-16 21:07:35.706251 | controller | 2026-02-16 21:07:35.706255 | controller | TASK [vexxhost.kubernetes.helm : Add bash autocomplete for helm] *************** 2026-02-16 21:07:35.706259 | controller | Monday 16 February 2026 21:07:35 +0000 (0:00:00.477) 0:00:06.396 ******* 2026-02-16 21:07:36.084543 | controller | changed: [controller] 2026-02-16 21:07:36.084706 | controller | 2026-02-16 21:07:36.084834 | controller | TASK [vexxhost.kubernetes.helm : Get Helm plugins dir] ************************* 2026-02-16 21:07:36.084953 | controller | Monday 16 February 2026 21:07:36 +0000 (0:00:00.379) 0:00:06.775 ******* 2026-02-16 21:07:36.566829 | controller | ok: [controller] 2026-02-16 21:07:36.566984 | controller | 2026-02-16 21:07:36.567112 | controller | TASK [vexxhost.kubernetes.helm : Create Helm plugins directory if it does not exist] *** 2026-02-16 21:07:36.567228 | controller | Monday 16 February 2026 21:07:36 +0000 (0:00:00.482) 0:00:07.258 ******* 2026-02-16 21:07:36.844717 | controller | changed: [controller] 2026-02-16 21:07:36.844859 | controller | 2026-02-16 21:07:36.844990 | controller | TASK [vexxhost.kubernetes.helm : Remove Helm diff plugin installed by kubernetes.core.helm_plugin] *** 2026-02-16 21:07:36.845105 | controller | Monday 16 February 2026 21:07:36 +0000 (0:00:00.277) 0:00:07.536 ******* 2026-02-16 21:07:37.118968 | controller | ok: [controller] 2026-02-16 21:07:37.121152 | controller | 2026-02-16 21:07:37.121163 | controller | TASK [Install plugin] ********************************************************** 2026-02-16 21:07:37.121167 | controller | Monday 16 February 2026 21:07:37 +0000 (0:00:00.274) 0:00:07.810 ******* 2026-02-16 21:07:37.177755 | controller | included: vexxhost.containers.download_artifact for controller 2026-02-16 21:07:37.179835 | controller | 2026-02-16 21:07:37.179846 | controller | TASK [vexxhost.containers.download_artifact : Starting download of file] ******* 2026-02-16 21:07:37.179851 | controller | Monday 16 February 2026 21:07:37 +0000 (0:00:00.058) 0:00:07.869 ******* 2026-02-16 21:07:37.228833 | controller | ok: [controller] => { 2026-02-16 21:07:37.231995 | controller | "msg": "https://github.com/databus23/helm-diff/releases/download/v3.8.1/helm-diff-linux-amd64.tgz" 2026-02-16 21:07:37.232007 | controller | } 2026-02-16 21:07:37.232012 | controller | 2026-02-16 21:07:37.232016 | controller | TASK [vexxhost.containers.download_artifact : Download item] ******************* 2026-02-16 21:07:37.232020 | controller | Monday 16 February 2026 21:07:37 +0000 (0:00:00.050) 0:00:07.919 ******* 2026-02-16 21:07:37.971537 | controller | changed: [controller] 2026-02-16 21:07:37.971882 | controller | 2026-02-16 21:07:37.972161 | controller | TASK [vexxhost.containers.download_artifact : Extract archive] ***************** 2026-02-16 21:07:37.972421 | controller | Monday 16 February 2026 21:07:37 +0000 (0:00:00.743) 0:00:08.663 ******* 2026-02-16 21:07:40.033725 | controller | changed: [controller] 2026-02-16 21:07:40.033900 | controller | 2026-02-16 21:07:40.034053 | controller | PLAY RECAP ********************************************************************* 2026-02-16 21:07:40.034216 | controller | controller : ok=16 changed=7 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-02-16 21:07:40.034355 | controller | 2026-02-16 21:07:40.034488 | controller | 2026-02-16 21:07:40.034634 | controller | TASKS RECAP ******************************************************************** 2026-02-16 21:07:40.034784 | controller | Monday 16 February 2026 21:07:40 +0000 (0:00:02.062) 0:00:10.725 ******* 2026-02-16 21:07:40.034926 | controller | =============================================================================== 2026-02-16 21:07:40.035074 | controller | vexxhost.containers.download_artifact : Extract archive ----------------- 2.06s 2026-02-16 21:07:40.035223 | controller | vexxhost.containers.download_artifact : Extract archive ----------------- 2.04s 2026-02-16 21:07:40.035390 | controller | vexxhost.containers.package : Update state for tar ---------------------- 1.13s 2026-02-16 21:07:40.035607 | controller | Gathering Facts --------------------------------------------------------- 1.00s 2026-02-16 21:07:40.035759 | controller | vexxhost.containers.download_artifact : Download item ------------------- 0.80s 2026-02-16 21:07:40.035953 | controller | vexxhost.containers.download_artifact : Download item ------------------- 0.74s 2026-02-16 21:07:40.036135 | controller | vexxhost.kubernetes.helm : Get Helm plugins dir ------------------------- 0.48s 2026-02-16 21:07:40.036314 | controller | vexxhost.kubernetes.helm : Remove Helm repository ----------------------- 0.48s 2026-02-16 21:07:40.036511 | controller | vexxhost.containers.forget_package : Forget package --------------------- 0.45s 2026-02-16 21:07:40.036683 | controller | vexxhost.containers.directory : Create directory (/var/lib/downloads) --- 0.42s 2026-02-16 21:07:40.036849 | controller | vexxhost.kubernetes.helm : Add bash autocomplete for helm --------------- 0.38s 2026-02-16 21:07:40.037008 | controller | vexxhost.kubernetes.helm : Create Helm plugins directory if it does not exist --- 0.28s 2026-02-16 21:07:40.037197 | controller | vexxhost.kubernetes.helm : Remove Helm diff plugin installed by kubernetes.core.helm_plugin --- 0.27s 2026-02-16 21:07:40.037349 | controller | Install plugin ---------------------------------------------------------- 0.06s 2026-02-16 21:07:40.037500 | controller | vexxhost.containers.download_artifact : Starting download of file ------- 0.06s 2026-02-16 21:07:40.037649 | controller | vexxhost.containers.download_artifact : Starting download of file ------- 0.05s 2026-02-16 21:07:40.118091 | controller | INFO [helm > converge] Executed: Successful 2026-02-16 21:07:40.127186 | controller | INFO [helm > idempotence] Executing 2026-02-16 21:07:40.923872 | controller | 2026-02-16 21:07:40.924208 | controller | PLAY [Converge] **************************************************************** 2026-02-16 21:07:40.924447 | controller | 2026-02-16 21:07:40.924699 | controller | TASK [Gathering Facts] ********************************************************* 2026-02-16 21:07:40.924956 | controller | Monday 16 February 2026 21:07:40 +0000 (0:00:00.013) 0:00:00.013 ******* 2026-02-16 21:07:41.954613 | controller | [WARNING]: Host 'controller' is using the discovered Python interpreter at '/usr/bin/python3.13', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.20/reference_appendices/interpreter_discovery.html for more information. 2026-02-16 21:07:41.960853 | controller | ok: [controller] 2026-02-16 21:07:41.960879 | controller | 2026-02-16 21:07:41.960891 | controller | TASK [vexxhost.containers.forget_package : Forget package] ********************* 2026-02-16 21:07:41.960903 | controller | Monday 16 February 2026 21:07:41 +0000 (0:00:01.036) 0:00:01.050 ******* 2026-02-16 21:07:42.342385 | controller | ok: [controller] 2026-02-16 21:07:42.342656 | controller | 2026-02-16 21:07:42.342953 | controller | TASK [vexxhost.containers.package : Update state for tar] ********************** 2026-02-16 21:07:42.343219 | controller | Monday 16 February 2026 21:07:42 +0000 (0:00:00.382) 0:00:01.432 ******* 2026-02-16 21:07:43.233290 | controller | ok: [controller] 2026-02-16 21:07:43.233610 | controller | 2026-02-16 21:07:43.234032 | controller | TASK [vexxhost.containers.directory : Create directory (/var/lib/downloads)] *** 2026-02-16 21:07:43.234339 | controller | Monday 16 February 2026 21:07:43 +0000 (0:00:00.890) 0:00:02.322 ******* 2026-02-16 21:07:43.651087 | controller | ok: [controller] 2026-02-16 21:07:43.651109 | controller | 2026-02-16 21:07:43.651113 | controller | TASK [vexxhost.containers.download_artifact : Starting download of file] ******* 2026-02-16 21:07:43.651117 | controller | Monday 16 February 2026 21:07:43 +0000 (0:00:00.416) 0:00:02.739 ******* 2026-02-16 21:07:43.692626 | controller | ok: [controller] => { 2026-02-16 21:07:43.692642 | controller | "msg": "https://get.helm.sh/helm-v3.11.2-linux-amd64.tar.gz" 2026-02-16 21:07:43.692647 | controller | } 2026-02-16 21:07:43.692653 | controller | 2026-02-16 21:07:43.692658 | controller | TASK [vexxhost.containers.download_artifact : Download item] ******************* 2026-02-16 21:07:43.692662 | controller | Monday 16 February 2026 21:07:43 +0000 (0:00:00.043) 0:00:02.782 ******* 2026-02-16 21:07:44.195705 | controller | ok: [controller] 2026-02-16 21:07:44.198180 | controller | 2026-02-16 21:07:44.198189 | controller | TASK [vexxhost.containers.download_artifact : Extract archive] ***************** 2026-02-16 21:07:44.198193 | controller | Monday 16 February 2026 21:07:44 +0000 (0:00:00.503) 0:00:03.286 ******* 2026-02-16 21:07:45.812088 | controller | ok: [controller] 2026-02-16 21:07:45.812295 | controller | 2026-02-16 21:07:45.812489 | controller | TASK [vexxhost.kubernetes.helm : Remove Helm repository] *********************** 2026-02-16 21:07:45.812675 | controller | Monday 16 February 2026 21:07:45 +0000 (0:00:01.616) 0:00:04.902 ******* 2026-02-16 21:07:46.311781 | controller | ok: [controller] 2026-02-16 21:07:46.312223 | controller | 2026-02-16 21:07:46.312555 | controller | TASK [vexxhost.kubernetes.helm : Add bash autocomplete for helm] *************** 2026-02-16 21:07:46.312857 | controller | Monday 16 February 2026 21:07:46 +0000 (0:00:00.498) 0:00:05.400 ******* 2026-02-16 21:07:46.673282 | controller | ok: [controller] 2026-02-16 21:07:46.673458 | controller | 2026-02-16 21:07:46.673627 | controller | TASK [vexxhost.kubernetes.helm : Get Helm plugins dir] ************************* 2026-02-16 21:07:46.673787 | controller | Monday 16 February 2026 21:07:46 +0000 (0:00:00.362) 0:00:05.763 ******* 2026-02-16 21:07:47.102370 | controller | ok: [controller] 2026-02-16 21:07:47.103973 | controller | 2026-02-16 21:07:47.104188 | controller | TASK [vexxhost.kubernetes.helm : Create Helm plugins directory if it does not exist] *** 2026-02-16 21:07:47.104352 | controller | Monday 16 February 2026 21:07:47 +0000 (0:00:00.429) 0:00:06.192 ******* 2026-02-16 21:07:47.367772 | controller | ok: [controller] 2026-02-16 21:07:47.367794 | controller | 2026-02-16 21:07:47.367800 | controller | TASK [vexxhost.kubernetes.helm : Remove Helm diff plugin installed by kubernetes.core.helm_plugin] *** 2026-02-16 21:07:47.367818 | controller | Monday 16 February 2026 21:07:47 +0000 (0:00:00.262) 0:00:06.454 ******* 2026-02-16 21:07:47.642713 | controller | ok: [controller] 2026-02-16 21:07:47.642889 | controller | 2026-02-16 21:07:47.643053 | controller | TASK [Install plugin] ********************************************************** 2026-02-16 21:07:47.643213 | controller | Monday 16 February 2026 21:07:47 +0000 (0:00:00.277) 0:00:06.732 ******* 2026-02-16 21:07:47.698293 | controller | included: vexxhost.containers.download_artifact for controller 2026-02-16 21:07:47.700077 | controller | 2026-02-16 21:07:47.700376 | controller | TASK [vexxhost.containers.download_artifact : Starting download of file] ******* 2026-02-16 21:07:47.700648 | controller | Monday 16 February 2026 21:07:47 +0000 (0:00:00.055) 0:00:06.788 ******* 2026-02-16 21:07:47.735458 | controller | ok: [controller] => { 2026-02-16 21:07:47.735502 | controller | "msg": "https://github.com/databus23/helm-diff/releases/download/v3.8.1/helm-diff-linux-amd64.tgz" 2026-02-16 21:07:47.735506 | controller | } 2026-02-16 21:07:47.735510 | controller | 2026-02-16 21:07:47.735514 | controller | TASK [vexxhost.containers.download_artifact : Download item] ******************* 2026-02-16 21:07:47.735518 | controller | Monday 16 February 2026 21:07:47 +0000 (0:00:00.035) 0:00:06.824 ******* 2026-02-16 21:07:48.133830 | controller | ok: [controller] 2026-02-16 21:07:48.135957 | controller | 2026-02-16 21:07:48.135970 | controller | TASK [vexxhost.containers.download_artifact : Extract archive] ***************** 2026-02-16 21:07:48.135976 | controller | Monday 16 February 2026 21:07:48 +0000 (0:00:00.399) 0:00:07.223 ******* 2026-02-16 21:07:49.674771 | controller | ok: [controller] 2026-02-16 21:07:49.674854 | controller | 2026-02-16 21:07:49.674980 | controller | PLAY RECAP ********************************************************************* 2026-02-16 21:07:49.675109 | controller | controller : ok=16 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-02-16 21:07:49.675218 | controller | 2026-02-16 21:07:49.675314 | controller | 2026-02-16 21:07:49.675440 | controller | TASKS RECAP ******************************************************************** 2026-02-16 21:07:49.677610 | controller | Monday 16 February 2026 21:07:49 +0000 (0:00:01.541) 0:00:08.765 ******* 2026-02-16 21:07:49.677636 | controller | =============================================================================== 2026-02-16 21:07:49.677641 | controller | vexxhost.containers.download_artifact : Extract archive ----------------- 1.62s 2026-02-16 21:07:49.677646 | controller | vexxhost.containers.download_artifact : Extract archive ----------------- 1.54s 2026-02-16 21:07:49.677651 | controller | Gathering Facts --------------------------------------------------------- 1.04s 2026-02-16 21:07:49.677655 | controller | vexxhost.containers.package : Update state for tar ---------------------- 0.89s 2026-02-16 21:07:49.677659 | controller | vexxhost.containers.download_artifact : Download item ------------------- 0.50s 2026-02-16 21:07:49.677664 | controller | vexxhost.kubernetes.helm : Remove Helm repository ----------------------- 0.50s 2026-02-16 21:07:49.677668 | controller | vexxhost.kubernetes.helm : Get Helm plugins dir ------------------------- 0.43s 2026-02-16 21:07:49.677672 | controller | vexxhost.containers.directory : Create directory (/var/lib/downloads) --- 0.42s 2026-02-16 21:07:49.677678 | controller | vexxhost.containers.download_artifact : Download item ------------------- 0.40s 2026-02-16 21:07:49.677682 | controller | vexxhost.containers.forget_package : Forget package --------------------- 0.38s 2026-02-16 21:07:49.677694 | controller | vexxhost.kubernetes.helm : Add bash autocomplete for helm --------------- 0.36s 2026-02-16 21:07:49.677699 | controller | vexxhost.kubernetes.helm : Remove Helm diff plugin installed by kubernetes.core.helm_plugin --- 0.28s 2026-02-16 21:07:49.677703 | controller | vexxhost.kubernetes.helm : Create Helm plugins directory if it does not exist --- 0.26s 2026-02-16 21:07:49.677708 | controller | Install plugin ---------------------------------------------------------- 0.06s 2026-02-16 21:07:49.677712 | controller | vexxhost.containers.download_artifact : Starting download of file ------- 0.04s 2026-02-16 21:07:49.677717 | controller | vexxhost.containers.download_artifact : Starting download of file ------- 0.04s 2026-02-16 21:07:49.774970 | controller | INFO [helm > idempotence] Executed: Successful 2026-02-16 21:07:49.783795 | controller | INFO [helm > side_effect] Executing 2026-02-16 21:07:49.784292 | controller | WARNING [helm > side_effect] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-02-16 21:07:49.791174 | controller | INFO [helm > verify] Executing 2026-02-16 21:07:50.559691 | controller | 2026-02-16 21:07:50.559983 | controller | PLAY [Verify] ****************************************************************** 2026-02-16 21:07:50.560205 | controller | 2026-02-16 21:07:50.560441 | controller | TASK [Gathering Facts] ********************************************************* 2026-02-16 21:07:50.560681 | controller | Monday 16 February 2026 21:07:50 +0000 (0:00:00.009) 0:00:00.009 ******* 2026-02-16 21:07:51.523376 | controller | [WARNING]: Host 'controller' is using the discovered Python interpreter at '/usr/bin/python3.13', but future installation of another Python interpreter could cause a different interpreter to be discovered. See https://docs.ansible.com/ansible-core/2.20/reference_appendices/interpreter_discovery.html for more information. 2026-02-16 21:07:51.529535 | controller | ok: [controller] 2026-02-16 21:07:51.529645 | controller | 2026-02-16 21:07:51.529770 | controller | TASK [Get the current Helm version] ******************************************** 2026-02-16 21:07:51.529896 | controller | Monday 16 February 2026 21:07:51 +0000 (0:00:00.969) 0:00:00.979 ******* 2026-02-16 21:07:51.933631 | controller | changed: [controller] 2026-02-16 21:07:51.933721 | controller | 2026-02-16 21:07:51.933840 | controller | TASK [Assert Helm version] ***************************************************** 2026-02-16 21:07:51.933960 | controller | Monday 16 February 2026 21:07:51 +0000 (0:00:00.403) 0:00:01.382 ******* 2026-02-16 21:07:51.959141 | controller | ok: [controller] => { 2026-02-16 21:07:51.959238 | controller | "changed": false, 2026-02-16 21:07:51.959327 | controller | "msg": "All assertions passed" 2026-02-16 21:07:51.959408 | controller | } 2026-02-16 21:07:51.959517 | controller | 2026-02-16 21:07:51.959609 | controller | PLAY RECAP ********************************************************************* 2026-02-16 21:07:51.959699 | controller | controller : ok=3 changed=1 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2026-02-16 21:07:51.959773 | controller | 2026-02-16 21:07:51.959844 | controller | 2026-02-16 21:07:51.959939 | controller | TASKS RECAP ******************************************************************** 2026-02-16 21:07:51.960006 | controller | Monday 16 February 2026 21:07:51 +0000 (0:00:00.026) 0:00:01.409 ******* 2026-02-16 21:07:51.960084 | controller | =============================================================================== 2026-02-16 21:07:51.960166 | controller | Gathering Facts --------------------------------------------------------- 0.97s 2026-02-16 21:07:51.960254 | controller | Get the current Helm version -------------------------------------------- 0.40s 2026-02-16 21:07:51.960335 | controller | Assert Helm version ----------------------------------------------------- 0.03s 2026-02-16 21:07:52.037579 | controller | INFO [helm > verify] Executed: Successful 2026-02-16 21:07:52.045587 | controller | INFO [helm > cleanup] Executing 2026-02-16 21:07:52.045964 | controller | WARNING [helm > cleanup] Executed: Missing playbook (Remove from test_sequence to suppress) 2026-02-16 21:07:52.052383 | controller | INFO [helm > destroy] Executing 2026-02-16 21:07:52.052438 | controller | WARNING [helm > destroy] Skipping, '--destroy=never' requested. 2026-02-16 21:07:52.052498 | controller | INFO [helm > destroy] Executed: Successful 2026-02-16 21:07:52.052731 | controller | WARNING Molecule executed 1 scenario (1 missing files) 2026-02-16 21:07:52.286286 | controller | ok: Runtime: 0:01:55.224378 2026-02-16 21:07:52.291168 | 2026-02-16 21:07:52.291235 | PLAY RECAP 2026-02-16 21:07:52.291294 | controller | ok: 3 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-02-16 21:07:52.291325 | 2026-02-16 21:07:52.400216 | RUN END RESULT_NORMAL: [untrusted : github.com/vexxhost/zuul-jobs/playbooks/molecule/run.yaml@main] 2026-02-16 21:07:52.401912 | POST-RUN START: [trusted : vexxhost.dev/zuul-config/playbooks/base/post.yaml@main] 2026-02-16 21:07:53.000808 | 2026-02-16 21:07:53.000995 | PLAY [all] 2026-02-16 21:07:53.011503 | 2026-02-16 21:07:53.011583 | TASK [fetch-output : Set log path for multiple nodes] 2026-02-16 21:07:53.056706 | controller | skipping: Conditional result was False 2026-02-16 21:07:53.066643 | 2026-02-16 21:07:53.066823 | TASK [fetch-output : Set log path for single node] 2026-02-16 21:07:53.106383 | controller | ok 2026-02-16 21:07:53.111335 | 2026-02-16 21:07:53.111424 | LOOP [fetch-output : Ensure local output dirs] 2026-02-16 21:07:53.752534 | controller -> localhost | ok: "/var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/logs" 2026-02-16 21:07:53.964889 | controller -> localhost | changed: "/var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/artifacts" 2026-02-16 21:07:54.180384 | controller -> localhost | changed: "/var/lib/zuul/builds/0dd7ea616cfa4c7bb936cefbf4b93562/work/docs" 2026-02-16 21:07:54.203658 | 2026-02-16 21:07:54.203855 | LOOP [fetch-output : Collect logs, artifacts and docs] 2026-02-16 21:07:54.848137 | controller | changed: .d..t...... ./ 2026-02-16 21:07:54.848388 | controller | changed: All items complete 2026-02-16 21:07:54.848420 | 2026-02-16 21:07:55.320063 | controller | changed: .d..t...... ./ 2026-02-16 21:07:55.794516 | controller | changed: .d..t...... ./ 2026-02-16 21:07:55.812467 | 2026-02-16 21:07:55.812629 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2026-02-16 21:07:56.255884 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.008919 2026-02-16 21:07:56.515985 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007690 2026-02-16 21:07:56.539441 | 2026-02-16 21:07:56.539646 | PLAY [all] 2026-02-16 21:07:56.547408 | 2026-02-16 21:07:56.547503 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2026-02-16 21:07:57.006404 | controller | changed 2026-02-16 21:07:57.012368 | 2026-02-16 21:07:57.012438 | PLAY RECAP 2026-02-16 21:07:57.012501 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2026-02-16 21:07:57.012533 | 2026-02-16 21:07:57.147968 | POST-RUN END RESULT_NORMAL: [trusted : vexxhost.dev/zuul-config/playbooks/base/post.yaml@main] 2026-02-16 21:07:57.149499 | POST-RUN START: [trusted : vexxhost.dev/zuul-config/playbooks/base/post-logs.yaml@main] 2026-02-16 21:07:57.748404 | 2026-02-16 21:07:57.748551 | PLAY [localhost] 2026-02-16 21:07:57.758460 | 2026-02-16 21:07:57.758533 | TASK [Generate Zuul manifest] 2026-02-16 21:07:57.779321 | localhost | ok 2026-02-16 21:07:57.795597 | 2026-02-16 21:07:57.795675 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2026-02-16 21:07:58.131690 | localhost | changed 2026-02-16 21:07:58.149469 | 2026-02-16 21:07:58.149579 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2026-02-16 21:07:58.181785 | localhost | ok 2026-02-16 21:07:58.189055 | 2026-02-16 21:07:58.189119 | TASK [Upload logs] 2026-02-16 21:07:58.221470 | localhost | ok 2026-02-16 21:07:58.280566 | 2026-02-16 21:07:58.280704 | TASK [Set zuul-log-path fact] 2026-02-16 21:07:58.301427 | localhost | ok 2026-02-16 21:07:58.318139 | 2026-02-16 21:07:58.318240 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-02-16 21:07:58.348830 | localhost | ok 2026-02-16 21:07:58.359645 | 2026-02-16 21:07:58.359735 | TASK [upload-logs : Create log directories] 2026-02-16 21:07:58.778112 | localhost | changed 2026-02-16 21:07:58.787313 | 2026-02-16 21:07:58.787440 | TASK [upload-logs : Ensure logs are readable before uploading] 2026-02-16 21:07:59.225406 | localhost -> localhost | ok: Runtime: 0:00:00.005964 2026-02-16 21:07:59.231511 | 2026-02-16 21:07:59.231574 | TASK [upload-logs : Upload logs to log server] 2026-02-16 21:07:59.697754 | localhost | Output suppressed because no_log was given 2026-02-16 21:07:59.705250 | 2026-02-16 21:07:59.705420 | LOOP [upload-logs : Compress console log and json output] 2026-02-16 21:07:59.745383 | localhost | skipping: Conditional result was False 2026-02-16 21:07:59.751439 | localhost | skipping: Conditional result was False 2026-02-16 21:07:59.761464 | 2026-02-16 21:07:59.761615 | LOOP [upload-logs : Upload compressed console log and json output] 2026-02-16 21:07:59.797131 | localhost | skipping: Conditional result was False 2026-02-16 21:07:59.797533 | 2026-02-16 21:07:59.800404 | localhost | skipping: Conditional result was False 2026-02-16 21:07:59.815550 | 2026-02-16 21:07:59.815736 | LOOP [upload-logs : Upload console log and json output]