Exception occurred in runner inventory.audit: Traceback...

[d-a-v]

Hi,

We are trying your inventory runner, thanks for that, we are facing issues.

database is setup and working, module is functionnal,

$ salt -l debug minion1 inventory.audit force=True
[...]
[DEBUG   ] LazyLoaded nested.output
minion1:
    Success
[DEBUG   ] jid 20181221174623203872 found all minions set([u'minion1'])

We added a log line in __doQuery:

def __doQuery(cursor, query):
        """
        Helper function to execute a query on the given cursor object.
        """
        try:
                log.debug("query: %s" % query);       # <-------- here
                cursor.execute(query)
        except Exception as e:
                raise Exception("inventory.__query: %s\nquery was: %s" % (e, query))

All what we can see in logs are SELECTs (no INSERT, UPDATE...)

and salt logs show lines like that

2018-12-21 17:33:53,422 [salt.utils.event :739 ][DEBUG   ][29868] Sending event: tag = salt/run/20181221173353399703/ret; data = {u'fun_args': [u'2018-12-21T16:33:53.272762', OrderedDict([(u'server_id', 1564434732)]), False], u'jid': u'20181221173353399703', u'return': u'Exception occurred in runner inventory.audit: Traceback (most recent call last):\n  File "/usr/lib/python2.7/site-packages/salt/client/mixins.py", line 387, in _low\n    data[\'return\'] = self.functions[fun](*args, **kwargs)\n  File "/srv/salt/_runners/inventory.py", line 208, in audit\n    properties["id"],\nKeyError: \'id\'\n', u'success': False, u'_stamp': '2018-12-21T16:33:53.421964', u'user': u'Reactor', u'fun': u'runner.inventory.audit'}

Exception occurred in runner inventory.audit: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/salt/client/mixins.py", line 387, in _low
    data[\'return\'] = self.functions[fun](*args, **kwargs)
  File "/srv/salt/_runners/inventory.py", line 208, in audit

Line 208 is an access to properties[], all accesses to properties[] give this error, The error originally occurs in this line (we added our logs and debugs).

We are not at this point bearded enough to debug the properties argument in the audit python function. Can you please provide us some help ?

Also, thanks for setting this repository up !

[neilmunday]

Hi,

Thanks for adding the detailed issue report.

Can you confirm which version of Salt you are running on the Salt master and client(s)?

Just to make sure the state of the database is ok, can you delete all records (if there are any) from the minion table and then try running a force audit on a minion?

If this does not work, then it would also be useful if you could share the output of your event queue on the Salt master when a minion runs an audit. This can be done by running on the master:

salt-run state.event pretty=True

This should show the arguments and their values being passed from the minion to the reactor and finally to the runner.

Cheers,

Neil.

[d-a-v]

Salt server is

           Salt: 2018.3.3
        version: CentOS Linux 7.6.1810 Core

Salt minion is

           Salt: 2018.3.3
        version: Ubuntu 18.04 bionic

Database is empty and has never been populated so far.

mysql> select * from minion;
Empty set (0.00 sec)

Stripped logs from salt-run state.event pretty=True:

Bottom error expanded:

    "return": "Exception occurred in runner inventory.audit:
Traceback (most recent call last):
  File \"/usr/lib/python2.7/site-packages/salt/client/mixins.py\", line 387, in _low
    data['return'] = self.functions[fun](*args, **kwargs)
  File \"/srv/salt/_runners/inventory.py\", line 222, in audit
    int(properties[\"selinux_enabled\"]),\nKeyError: 'selinux_enabled'

Now the error is different, our line 222 is int(properties["selinux_enabled"]),

I removed the int(), and restarted, now it is again:

    "return": "Exception occurred in runner inventory.audit:
Traceback (most recent call last):
  File \"/usr/lib/python2.7/site-packages/salt/client/mixins.py\", line 387, in _low
    data['return'] = self.functions[fun](*args, **kwargs)
  File \"/srv/salt/_runners/inventory.py\", line 208, in audit
    properties[\"id\"],\nKeyError: 'id'

(this is the same error as the one reported above)

Our query log is still showing only SELECTs

Logs before changing line 222:

[DEBUG   ] Configuration file path: /etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] LazyLoaded state.event
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] Found minion id from generate_minion_id(): saltserver.our.domain
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event: tag = salt/run/20181221193417016134/new; data = {u'fun': u'runner.state.event', u'fun_args': [{u'pretty': True}], u'jid': u'20181221193417016134', u'user': u'root', u'_stamp': '2018-12-21T18:34:17.857890'}
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
20181221193419387601    {
    "_stamp": "2018-12-21T18:34:19.387984", 
    "minions": [
        "minion1"
    ]
}
salt/job/20181221193419387601/new   {
    "_stamp": "2018-12-21T18:34:19.388778", 
    "arg": [
        {
            "__kwarg__": true, 
            "force": true
        }
    ], 
    "fun": "inventory.audit", 
    "jid": "20181221193419387601", 
    "minions": [
        "minion1"
    ], 
    "missing": [], 
    "tgt": "minion1", 
    "tgt_type": "glob", 
    "user": "root"
}
salt/job/20181221193419387601/ret/minion1   {
    "_stamp": "2018-12-21T18:34:20.047824", 
    "cmd": "_return", 
    "fun": "inventory.audit", 
    "fun_args": [
        {
            "force": true
        }
    ], 
    "id": "minion1", 
    "jid": "20181221193419387601", 
    "retcode": 0, 
    "return": "Success", 
    "success": true
}
inventory/audit {
    "_stamp": "2018-12-21T18:34:20.090738", 
    "cmd": "_minion_event", 
    "data": {
        "properties": {
            "biosreleasedate": "05/20/2015", 
            "biosversion": "A16", 
            "cpu_model": "Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz", 
            "fqdn": "minion1.our.domain", 
            "host": "minion1", 
            "hwaddr_interfaces": {
                "eno1": "64:00:6a:68:27:e2", 
                "lo": "00:00:00:00:00:00"
            }, 
            "id": "minion1", 
            "ip4_interfaces": {
                "eno1": [
                    "987.654.0.173"
                ], 
                "lo": [
                    "127.0.0.1"
                ]
            }, 
            "kernel": "Linux", 
            "kernelrelease": "4.15.0-42-generic", 
            "mem_total": 15948, 
            "num_cpus": 8, 
            "num_gpus": 1, 
            "os": "Ubuntu", 
            "osrelease": "18.04", 
            "pkgs": {
                "aalib1": [
                    "1"
                ], 
[...........]
                "zsh-common": [
                    "5.4.2-3ubuntu3.1"
                ]
            }, 
            "saltversion": "2018.3.3", 
            "server_id": 688959869
        }, 
        "propertiesChanged": true
    }, 
    "id": "minion1", 
    "pretag": null, 
    "tag": "inventory/audit"
}
salt/run/20181221193421645864/new   {
    "_stamp": "2018-12-21T18:34:21.648684", 
    "fun": "runner.inventory.audit", 
    "fun_args": [
        "2018-12-21T18:34:20.090738", 
        {
            "biosreleasedate": "05/20/2015", 
            "biosversion": "A16", 
            "cpu_model": "Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz", 
            "fqdn": "minion1.our.domain", 
            "host": "minion1", 
            "hwaddr_interfaces": {
                "eno1": "64:00:6a:68:27:e2", 
                "lo": "00:00:00:00:00:00"
            }, 
            "id": "minion1", 
            "ip4_interfaces": {
                "eno1": [
                    "987.654.0.173"
                ], 
                "lo": [
                    "127.0.0.1"
                ]
            }, 
            "kernel": "Linux", 
            "kernelrelease": "4.15.0-42-generic", 
            "mem_total": 15948, 
            "num_cpus": 8, 
            "num_gpus": 1, 
            "os": "Ubuntu", 
            "osrelease": "18.04", 
            "pkgs": {
                "aalib1": [
                    "1"
                ], 
[...........]
                "zsh-common": [
                    "5.4.2-3ubuntu3.1"
                ]
            }, 
            "saltversion": "2018.3.3", 
            "server_id": 688959869
        }, 
        true
    ], 
    "jid": "20181221193421645864", 
    "user": "Reactor"
}
salt/run/20181221193421645864/ret   {
    "_stamp": "2018-12-21T18:34:21.897327", 
    "fun": "runner.inventory.audit", 
    "fun_args": [
        "2018-12-21T18:34:20.090738", 
        {
            "biosreleasedate": "05/20/2015", 
            "biosversion": "A16", 
            "cpu_model": "Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz", 
            "fqdn": "minion1.our.domain", 
            "host": "minion1", 
            "hwaddr_interfaces": {
                "eno1": "64:00:6a:68:27:e2", 
                "lo": "00:00:00:00:00:00"
            }, 
            "id": "minion1", 
            "ip4_interfaces": {
                "eno1": [
                    "987.654.0.173"
                ], 
                "lo": [
                    "127.0.0.1"
                ]
            }, 
            "kernel": "Linux", 
            "kernelrelease": "4.15.0-42-generic", 
            "mem_total": 15948, 
            "num_cpus": 8, 
            "num_gpus": 1, 
            "os": "Ubuntu", 
            "osrelease": "18.04", 
            "pkgs": {
                "aalib1": [
                    "1"
                ], 
[..........]
                "zsh-common": [
                    "5.4.2-3ubuntu3.1"
                ]
            }, 
            "saltversion": "2018.3.3", 
            "server_id": 688959869
        }, 
        true
    ], 
    "jid": "20181221193421645864", 
    "return": "Exception occurred in runner inventory.audit: Traceback (most recent call last):\n  File \"/usr/lib/python2.7/site-packages/salt/client/mixins.py\", line 387, in _low\n    data['return'] = self.functions[fun](*args, **kwargs)\n  File \"/srv/salt/_runners/inventory.py\", line 222, in audit\n    int(properties[\"selinux_enabled\"]),\nKeyError: 'selinux_enabled'\n", 
    "success": false, 
    "user": "Reactor"
}

[neilmunday]

Thanks for the info.

The event log info is interesting as I don't see any selinux values being passed from the minion to the master. Can you run the follow command against your minion from your master:

salt 'minion1' grain.items

This will display all of the grain info for your minion. The inventory.audit module function uses the grain values to find out details about a minion. Can you look through the output produced and see if you have a selinux section, e.g.

 selinux:
        ----------
        enabled:
            True
        enforced:
            Enforcing

Can you confirm if you are using selinux or not? E.g. check the output of sestatus

In the meantime I'll try and set-up an Ubuntu VM to see if I can repeat the issue you are seeing.

[neilmunday]

I've set-up an Ubuntu 18.04 server VM and repeated the error. It would appear that selinux is not part of a default install.

I'll update the inventory.audit module to handle this situation.

[neilmunday]

Version 1.3 released to fix this bug.

Also fixed a bug for the Python3 version of SaltStack when using this module.

Can you test this new release (only /srv/salt/_modules/inventory.py has changed)?

[d-a-v]

Thanks for working on this, and it works now ! Database is populated with minion1 data. I am not the main user and further tests will be processed after christmas / new year eve.

I don't know if that's useful to know, there is still an exception. I am now filtering debug logs with:

salt-run state.event pretty=True 2>&1 | grep "Exception occurred" | sed 's,\\n,\n,g'

it shows:

    "return": "Exception occurred in runner inventory.audit: Traceback (most recent call last):
  File \"/usr/lib/python2.7/site-packages/salt/client/mixins.py\", line 387, in _low
    data['return'] = self.functions[fun](*args, **kwargs)
  File \"/srv/salt/_runners/inventory.py\", line 159, in audit
    log.debug(\"inventory.audit: adding new host \\\"%s\\\"\" % properties[\"host\"])
KeyError: 'host'
", 

This is unrelated with force-auditing (happens without starting the following command)

salt -l debug 'minion1' inventory.audit force=True

[neilmunday]

Glad to hear the update fixed the initial issue and thanks for letting me know.

I take it from the web page you now see your minion(s) and can view their details ok?

I'm not sure why you are seeing adding new host error. Do you have any other minions or just the one?

The full output of the event queue from the Salt master would be useful to try and identify how this is being triggered.

[d-a-v]

I currently have no access to the setup for two weeks. I only checked database content from command line. We will update this issue with more inputs when we come back. Thanks for this inventory tool

[neilmunday]

No problem, have a good Christmas ;-)