Empty "META: " lines printed

[bluikko]

Summary

My complex site.yml causes "empty" META: lines being printed often together with other META: lines such as ran handlers, role_complete.
The line is:

META:

There is a space after the META: but after that there isn't any reason such as ran handlers or role_complete.

Normal/valid META: lines with a "reason" often but not always have these "empty" META: lines near them.

I cannot duplicate this issue with a simple playbook or a simple playbook + role. My site.yml uses multiple layers of include_role and so on so it is difficult to try to simplify it into test case. But perhaps it could be possible to look at how that "empty" META: line could be possible.

Issue Type

Bug Report

Component Name

ansible

Ansible Version

$ ansible --version
ansible [core 2.11.9]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/x/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /y/lib64/python3.6/site-packages/ansible
  ansible collection location = /x/.ansible/collections:/usr/share/ansible/collections
  executable location = /y/bin/ansible
  python version = 3.6.8 (default, Nov 16 2020, 16:55:22) [GCC 4.8.5 20150623 (Red Hat 4.8.5-44)]
  jinja version = 3.0.2
  libyaml = True

Configuration

$ ansible-config dump --only-changed
CACHE_PLUGIN(/etc/ansible/ansible.cfg) = community.general.yaml
CACHE_PLUGIN_CONNECTION(/etc/ansible/ansible.cfg) = /tmp/.ansible-fact.$USER
CACHE_PLUGIN_TIMEOUT(/etc/ansible/ansible.cfg) = 5184000
CALLBACKS_ENABLED(/etc/ansible/ansible.cfg) = ['ansible.posix.timer']
CONTROLLER_PYTHON_WARNING(/etc/ansible/ansible.cfg) = False
DEFAULT_FORKS(/etc/ansible/ansible.cfg) = 10
DEFAULT_LOCAL_TMP(/etc/ansible/ansible.cfg) = /tmp/.ansible.x/ansible-local-20276c69v2u7m
DEFAULT_LOG_PATH(/etc/ansible/ansible.cfg) = /var/log/ansible.log
DEFAULT_STDOUT_CALLBACK(/etc/ansible/ansible.cfg) = community.general.yaml
DEFAULT_STRATEGY(/etc/ansible/ansible.cfg) = ansible.builtin.free
DEFAULT_TIMEOUT(/etc/ansible/ansible.cfg) = 50
DEFAULT_VAULT_IDENTITY_LIST(env: ANSIBLE_VAULT_IDENTITY_LIST) = ['a@v1', 'b@v2']
DEFAULT_VAULT_ID_MATCH(/etc/ansible/ansible.cfg) = True
INJECT_FACTS_AS_VARS(/etc/ansible/ansible.cfg) = False
RETRY_FILES_SAVE_PATH(/etc/ansible/ansible.cfg) = /tmp/.ansible-retry.x

OS / Environment

EL7

Steps to Reproduce

could not reproduce with a naive test case, it is visible in my site.yml that contains total ~500 .yml files across dozens of roles

Expected Results

There should be no spurious META: lines with no further information on what it is about.

Actual Results

example 1:
2022-03-17 09:34:47,350 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,359 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,368 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,377 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,386 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,396 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,405 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,415 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,425 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,435 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,443 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,452 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,461 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,470 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,479 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:47,597 p=13119 u=user n=ansible | ok: [host.example.com]
2022-03-17 09:34:47,612 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,621 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,631 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,640 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,649 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,659 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,669 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,679 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,689 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,698 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,706 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,715 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,724 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,733 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,741 p=13119 u=user n=ansible | META:
2022-03-17 09:34:47,751 p=13119 u=user n=ansible | META: ran handlers
2022-03-17 09:34:48,056 p=13119 u=user n=ansible | META:

Code of Conduct

• I agree to follow the Ansible Code of Conduct

[ansibot]

Files identified in the description:
None

If these files are incorrect, please update the component name section of the description or use the !component bot command.

click here for bot help

[mkrizek]

Which meta tasks are being used in the playbook?

This appears to happen for when some meta tasks are being skipped because then the actual message is empty and "skip_reason" is being used instead, though we still print the header in -vv:

ansible/lib/ansible/plugins/strategy/__init__.py

Lines 1314 to 1321 in 68b5db3

	result = {'msg': msg}
	if skipped:
	result['skipped'] = True
	result['skip_reason'] = skip_reason
	else:
	result['changed'] = False
	display.vv("META: %s" % msg)

[bluikko]

There are about few dozen flush_handlers across the different roles, but I do not explicitly call any ansible.builtin.meta when those empty lines appear. They appear together or near with "legitimate" automatically printed META: lines like ran handlers and role_complete.

[bluikko]

Managed to somehow get these empty META: lines without an accompanying "proper" META: line. Just a single "empty" META: line by itself.
They seem to be in a place where usually there should be META: role_complete.
They are printed after a task that was skipped due to when: evaluating to false, a single task in a role that was include_roled from an include_tasks that was a handler. I.e. (include_tasks ->) handler that was notified -> include_tasks -> include_role -> skipped task -> role is completed -> (include_tasks is completed -> handler is completed) -> empty META: line was printed.

I don't know if that is all, will try to create a test if I find time...

Edit: and a few tasks later:

included: /x/roles/application/server/tasks/before_reboot.yml for host.example.com
ERROR! Unexpected Exception, this is probably a bug: 'IncludeRole' object has no attribute 'cached_name'

What is intriguing about this error that the included line refers to a file that should have been finished already a few tasks ago!

Edit2:
This ERROR! is a separate issue definitely.

The empty META: lines are printed even almost in the beginning of an ansible-playbook run, before any handlers are run.
Literally the 3rd task in a play causes these lines to print: 2 assert tasks followed by import_playbook.

[bcoca]

i suspect these are meta: noop we sometimes to make many tasks 'work' while not breaking the linear strategy. Mostly handlers and includes trigger these as they can conditionally affect only a subset of the hosts, but 'all hosts' need to be iterated over.

[bluikko]

Full output for my site.yml against a single host:

Fetching: https://netbox[...]

PLAYBOOK: site.yml **************************************************************************************************************************************************************
87 plays in site.yml

PLAY [all] **********************************************************************************************************************************************************************
META: ran handlers

TASK [Check variable] *****************************************************************************************************************************************
task path: /x/site.yml:6
skipping: [host.example.com] => changed=false
  skip_reason: Conditional result was False

TASK [Check other variable] **************************************************************************************************************************************
task path: /x/site.yml:10
skipping: [host.example.com] => changed=false
  skip_reason: Conditional result was False
META: ran handlers
META: ran handlers

PLAY [Run role] *****************************************************************************************************************************************************

TASK [Gathering Facts] **********************************************************************************************************************************************************
task path: /x/server.yml:2
ok: [host.example.com]
META: ran handlers
META: