syslog_json callback not working with ansible-core 2.12.2?

[mathieumd]

Summary

I'm trying to use syslog_json callback to push ansible-playbook and ansible runs' output to our syslog server. But it seems to be not working.

Running the simples logger --server syslog.example.com test1 or logger --server syslog.example.com --port 514 --priority user.debug test2 does work, though.

Issue Type

Bug Report

Component Name

syslog_json

Ansible Version

$ ansible --version
ansible [core 2.12.2]
  config file = /home/mathieu/dev/ansible/ansible.cfg
  configured module search path = ['/home/mathieu/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3/dist-packages/ansible
  ansible collection location = /home/mathieu/dev/ansible/.collections
  executable location = /usr/bin/ansible
  python version = 3.9.2 (default, Feb 28 2021, 17:03:44) [GCC 10.2.1 20210110]
  jinja version = 2.11.3
  libyaml = True

Community.general Version

$ ansible-galaxy collection list community.general
# /home/mathieu/dev/ansible/.collections/ansible_collections
Collection        Version
----------------- -------
community.general 4.5.0  

# /usr/lib/python3/dist-packages/ansible_collections
Collection        Version
----------------- -------
community.general 4.5.0  

Configuration

$ ansible-config dump --only-changed
ANSIBLE_NOCOWS(/home/mathieu/dev/ansible/ansible.cfg) = True
CALLBACKS_ENABLED(/home/mathieu/dev/ansible/ansible.cfg) = ['syslog_json']
COLLECTIONS_PATHS(/home/mathieu/dev/ansible/ansible.cfg) = ['/home/mathieu/dev/ansible/.collections']
DEFAULT_HOST_LIST(/home/mathieu/dev/ansible/ansible.cfg) = ['/home/mathieu/dev/ansible/inventory']
DEFAULT_ROLES_PATH(/home/mathieu/dev/ansible/ansible.cfg) = ['/home/mathieu/dev/ansible/.roles']
INVENTORY_ENABLED(/home/mathieu/dev/ansible/ansible.cfg) = ['host_list', 'script', 'auto', 'yaml', 'ini', 'toml']

$ cat ansible.cfg |grep syslog
callbacks_enabled = syslog_json
[callback_syslog_json]
syslog_server = syslog.example.com
syslog_port = 514
syslog_facility = user

OS / Environment

Debian GNU/Linux 11 (bullseye)

Steps to Reproduce

ansible -m ping test.example.com -vvv |egrep -i '(callback|syslog)'

redirecting (type: callback) ansible.builtin.syslog_json to community.general.syslog_json
Skipping callback 'default', as we already have a stdout callback.
Skipping callback 'minimal', as we already have a stdout callback.
Skipping callback 'oneline', as we already have a stdout callback.

But the remote Syslog server does not get anything.

Expected Results

Remote Syslog server should receive something.

Actual Results

Remote Syslog server get nothing.

Code of Conduct

• [X] I agree to follow the Ansible Code of Conduct

[ansibullbot]

Files identified in the description:

• plugins/callback/syslog_json.py

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

[ansibullbot]

cc @imjoseangel click here for bot help

[felixfontein]

I fixed your title since Ansible 2.12.2 does not exist, you mean ansible-core 2.12.2.

You might want to run Ansible with more verbosity and look at whether it tells you something why it doesn't work.

[mathieumd]

Thanks @felixfontein.

More verbosity doesn't seems to give any hint:

ansible -m ping test.example.com -vvvvv 2>&1 |ag -i '(callback|syslog)'
Loading callback plugin minimal of type stdout, v2.0 from /usr/lib/python3/dist-packages/ansible/plugins/callback/minimal.py
redirecting (type: callback) ansible.builtin.syslog_json to community.general.syslog_json
Attempting to use 'default' callback.
Skipping callback 'default', as we already have a stdout callback.
Attempting to use 'junit' callback.
Attempting to use 'minimal' callback.
Skipping callback 'minimal', as we already have a stdout callback.
Attempting to use 'oneline' callback.
Skipping callback 'oneline', as we already have a stdout callback.
Attempting to use 'tree' callback.
Attempting to use 'syslog_json' callback.

On the Syslog server, there is no UDP paquet being seen by iptables:

sudo iptables -L INPUT -vn |grep 'dpt:514'
   10  1637 ACCEPT     udp  --  *      *       0.0.0.0/0            0.0.0.0/0            udp dpt:514
    0     0 ACCEPT     tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            tcp dpt:514

(Therer has been a total of 10 UDP datagrams [since iptables started], and those are only the ones sent by my logger manual tests)

[lmayorga1980]

Maybe related? https://github.com/ansible/ansible/issues/78677

[mathieumd]

While testing to see if I could reproduce @lmayorga1980's issue (which I could not), logging to syslog (magically) worked! :confetti_ball:

# ansible.cfg
callbacks_enabled = syslog_json
# callbacks_whitelist does not work

[callback_syslog_json]
syslog_server = syslog.example.com
syslog_port = 514
syslog_facility = user

On the syslog server, it creates entries like this in the host pc01's syslog file:

Sep  5 09:49:28 pc01 ansible-command: task execution SKIPPED; host: srv01; message: skipped 
Sep  5 09:49:28 pc01 ansible-command: task execution OK; host: srv01; message: {"changed": false, "msg": "All assertions passed"} 
Sep  5 09:49:28 pc01 ansible-command: task execution OK; host: srv01; message: {"changed": false, "msg": "All assertions passed"} 
Sep  5 09:49:31 pc01 ansible-command: task execution OK; host: srv01; message: {"attempts": 1, "changed": false} 

Ansible info:

ansible [core 2.12.7]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/home/mathieu/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3/dist-packages/ansible
  ansible collection location = /home/mathieu/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/bin/ansible
  python version = 3.9.2 (default, Feb 28 2021, 17:03:44) [GCC 10.2.1 20210110]
  jinja version = 2.11.3
  libyaml = True

Now the question is: how to actually log something useful? I had expected that invocation command line at least would be logged!

[lmayorga1980]

I was not able to reproduce it

ansible --version

ansible [core 2.13.6]
  config file = /Users/lmayorga/repos/ansible/vagrant/ansible.cfg
  configured module search path = ['/Users/lmayorga/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/Cellar/ansible/6.6.0/libexec/lib/python3.10/site-packages/ansible
  ansible collection location = /Users/lmayorga/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/local/bin/ansible
  python version = 3.10.8 (main, Oct 13 2022, 10:17:43) [Clang 14.0.0 (clang-1400.0.29.102)]
  jinja version = 3.1.2
  libyaml = True

ansible.cfg

[defaults]
inventory = hosts.ini
#callback_whitelist=json
callbacks_enabled = syslog_json

[callback_syslog_json]
syslog_server = localhost
syslog_facility = user
syslog_port = 5514

playbook.yml

---
- name: "Ansible"
  hosts: localhost
  gather_facts: true
  connection: local
  tasks:
    - name: 1. Shell Command Ls
      shell: "ls -lrt"
      register: "output"
    - name: 2. Debug Message
      debug: var=output.stdout_lines
    - name: 3. Another Command
      shell: echo command

I am using a Vagrant box with Ubuntu and Rsyslog Server.

config.vm.network "forwarded_port", guest: 514, host: 5514, host_ip: "127.0.0.1", protocol: "tcp"
config.vm.network "forwarded_port", guest: 514, host: 5514, host_ip: "127.0.0.1", protocol: "udp"

rsyslog.conf

#  /etc/rsyslog.conf	Configuration file for rsyslog.
#
#			For more information see
#			/usr/share/doc/rsyslog-doc/html/rsyslog_conf.html
#
#  Default logging rules can be found in /etc/rsyslog.d/50-default.conf


#################
#### MODULES ####
#################

module(load="imuxsock") # provides support for local system logging
#module(load="immark")  # provides --MARK-- message capability

# provides UDP syslog reception
module(load="imudp")
input(type="imudp" port="514")

# provides TCP syslog reception
module(load="imtcp")
input(type="imtcp" port="514")

module(load="imjournal")

# provides kernel logging support and enable non-kernel klog messages
module(load="imklog" permitnonkernelfacility="on")

###########################
#### GLOBAL DIRECTIVES ####
###########################

#
# Use traditional timestamp format.
# To enable high precision timestamps, comment out the following line.
#
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

# Filter duplicated messages
$RepeatedMsgReduction on

#
# Set the default permissions for all log files.
#
$FileOwner syslog
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022
$PrivDropToUser syslog
$PrivDropToGroup syslog

#
# Where to place spool and state files
#
$WorkDirectory /var/spool/rsyslog

#
# Include all config files in /etc/rsyslog.d/
#
$IncludeConfig /etc/rsyslog.d/*.conf

$template RemoteMachineLogs, "/var/log/remotelogs/%HOSTNAME%/%PROGRAMNAME%.log"
*.* ?RemoteMachineLog

[lmayorga1980]

I tested locally on the same ubuntu box and it worked

Nov 20 16:45:32 ubuntu-bionic ansible-command: task execution OK; host: localhost; message: {#012    "changed": false,#012    "output.stdout_lines": [#012        "total 16",#012        "drwxrwxr-x 4 vagrant vagrant 4096 Nov 20 16:39 venv",#012        "-rw-rw-r-- 1 vagrant vagrant  182 Nov 20 16:44 ansible.cfg",#012        "-rw-rw-r-- 1 vagrant vagrant  295 Nov 20 16:44 playbook.yml",#012        "-rw-rw-r-- 1 vagrant vagrant   16 Nov 20 16:45 hosts.ini"#012    ]#012}
Nov 20 16:45:32 ubuntu-bionic ansible-command: task execution OK; host: localhost; message: {"changed": true, "cmd": "echo command", "delta": "0:00:00.002616", "end": "2022-11-20 16:45:32.258903", "msg": "", "rc": 0, "start": "2022-11-20 16:45:32.256287", "stderr": "", "stderr_lines": [], "stdout": "command", "stdout_lines": ["command"]}
Nov 20 16:48:02 ubuntu-bionic ansible-command: task execution OK; host: localhost; message: {"ansible_facts": {"discovered_interpreter_python": "/usr/bin/python3"}, "changed": true, "cmd": "ls -lrt", "delta": "0:00:00.005245", "end": "2022-11-20 16:48:02.438205", "msg": "", "rc": 0, "start": "2022-11-20 16:48:02.432960", "stderr": "", "stderr_lines": [], "stdout": "total 16\ndrwxrwxr-x 4 vagrant vagrant 4096 Nov 20 16:39 venv\n-rw-rw-r-- 1 vagrant vagrant  182 Nov 20 16:44 ansible.cfg\n-rw-rw-r-- 1 vagrant vagrant   16 Nov 20 16:45 hosts.ini\n-rw-rw-r-- 1 vagrant vagrant  296 Nov 20 16:47 playbook.yml", "stdout_lines": ["total 16", "drwxrwxr-x 4 vagrant vagrant 4096 Nov 20 16:39 venv", "-rw-rw-r-- 1 vagrant vagrant  182 Nov 20 16:44 ansible.cfg", "-rw-rw-r-- 1 vagrant vagrant   16 Nov 20 16:45 hosts.ini", "-rw-rw-r-- 1 vagrant vagrant  296 Nov 20 16:47 playbook.yml"]}
Nov 20 16:48:02 ubuntu-bionic ansible-command: task execution OK; host: localhost; message: {#012    "changed": false,#012    "output.stdout_lines": [#012        "total 16",#012        "drwxrwxr-x 4 vagrant vagrant 4096 Nov 20 16:39 venv",#012        "-rw-rw-r-- 1 vagrant vagrant  182 Nov 20 16:44 ansible.cfg",#012        "-rw-rw-r-- 1 vagrant vagrant   16 Nov 20 16:45 hosts.ini",#012        "-rw-rw-r-- 1 vagrant vagrant  296 Nov 20 16:47 playbook.yml"#012    ]#012}
Nov 20 16:48:02 ubuntu-bionic ansible-command: task execution OK; host: localhost; message: {"changed": true, "cmd": "echo command", "delta": "0:00:00.003147", "end": "2022-11-20 16:48:02.786472", "msg": "", "rc": 0, "start": "2022-11-20 16:48:02.783325", "stderr": "", "stderr_lines": [], "stdout": "command", "stdout_lines": ["command"]