No handlers could be found for logger "thrift.server.TServer"

[arubdesu]

I haven't jiggled the handle much on this, but while the demo foobar example returns fine, I get the TServer error when running the pam table I built.

[theopolis]

Can I see the output of:

osqueryi --verbose

Here's me testing:

[teddy@lol] /tmp » cat autoload.ext                                                           
/tmp/pam.ext
------------------------------------------------------------
[teddy@maverics] /tmp » cat pam.ext                                                                
#!/usr/bin/python
"""pam.d confs table"""
# See bottom for license

import glob
import os
import osquery


def open_andreturn():
    """send files out, receive bacon"""
    pam_files = glob.glob('/etc/pam.d/*')
    query_data = []
    for pam in pam_files:
        if not os.path.islink(pam):
            query_data.extend(process_pam(pam))
    print query_data
    return query_data


def process_pam(pam):
    """do open and processing on each pam"""
    with open(pam, 'r') as canola:
        all_lines = canola.readlines()
    all_rows = []
    path = pam
    priority = 1
    comment = all_lines.pop(0).strip()
    for line in all_lines:
        indiv_dict = {}
        indiv_strs = line.split()
        indiv_dict['priority'] = priority
        indiv_dict['path'] = path
        indiv_dict['comment'] = comment
        indiv_dict['function_class'] = indiv_strs[0].strip()
        indiv_dict['control_flag'] = indiv_strs[1].strip()
        indiv_dict['module_path'] = indiv_strs[2].strip()
        indiv_dict['args'] = ' '.join(*[indiv_strs[3:]])
        all_rows.append(indiv_dict)
        priority += 1
    return all_rows


@osquery.register_plugin
class pam(osquery.TablePlugin):
    def name(self):
        return "pam"

    def columns(self):
        return [
            osquery.TableColumn(name="priority", type=osquery.INTEGER),
            osquery.TableColumn(name="path", type=osquery.STRING),
            osquery.TableColumn(name="comment", type=osquery.STRING),
            osquery.TableColumn(name="function_class", type=osquery.STRING),
            osquery.TableColumn(name="control_flag", type=osquery.STRING),
            osquery.TableColumn(name="module_path", type=osquery.STRING),
            osquery.TableColumn(name="args", type=osquery.STRING),
        ]

    def generate(self, context):
        query_data = open_andreturn()
        return query_data

if __name__ == "__main__":
    osquery.start_extension(name="pam",
                            version="1.0.1",)

------------------------------------------------------------
[teddy@lol] /tmp » sudo osqueryi --verbose --extensions_autoload ./autoload.ext --allow_unsafe
I0831 12:54:18.757068  1662 init.cpp:318] osquery initialized [version=1.7.7]
I0831 12:54:18.757158  1662 extensions.cpp:252] Found autoloadable extension: /tmp/pam.ext
I0831 12:54:18.757381  1662 extensions.cpp:214] Could not autoload modules: Failed reading: /etc/osquery/modules.load
I0831 12:54:18.758116  1663 watcher.cpp:414] Created and monitoring extension child (1664): /tmp/pam.ext
I0831 12:54:18.758165  1666 interface.cpp:257] Extension manager service starting: /home/teddy/.osquery/shell.em
I0831 12:54:18.758213  1662 init.cpp:558] Error reading config: config file does not exist: /var/osquery/osquery.conf
osquery> I0831 12:54:18.790629  1667 interface.cpp:86] Registering extension (pam, 50556, version=1.0.1, sdk=1.8.0)
I0831 12:54:18.790885  1667 registry.cpp:325] Extension 50556 registered table plugin pam

------------------------------------------------------------
[teddy@lol] /tmp » ~/git/osquery/build/xenial/osquery/osqueryi --verbose --extensions_autoload ./autoload.ext --allow_unsafe
I0831 12:54:29.334169  1673 init.cpp:340] osquery initialized [version=1.8.2-75-g9584c1e]
I0831 12:54:29.334209  1673 extensions.cpp:278] Found autoloadable extension: /tmp/pam.ext
I0831 12:54:29.334249  1673 extensions.cpp:240] Could not autoload modules: Failed reading: /etc/osquery/modules.load
I0831 12:54:29.334326  1673 init.cpp:581] Error reading config: config file does not exist: /etc/osquery/osquery.conf
I0831 12:54:29.334481  1674 watcher.cpp:477] Created and monitoring extension child (1677): /tmp/pam.ext
I0831 12:54:29.334537  1676 interface.cpp:265] Extension manager service starting: /home/teddy/.osquery/shell.em
I0831 12:54:29.365028  1678 registry.cpp:359] Extension 50314 registered table plugin pam

[theopolis]

My guess, the host has an outdated version of the Python module:

pip install --upgrade osquery

[arubdesu]

Hmm, seeing different output when following those steps on my Sierra machine running 1.8.2 and verified module is 1.8 as well:

$ sudo osqueryi --verbose --extensions_autoload ./autoload.ext --allow_unsafe
I0831 20:43:23.572582 3884995520 init.cpp:374] osquery initialized [version=1.8.2]
I0831 20:43:23.573051 3884995520 extensions.cpp:278] Found autoloadable extension: /tmp/pam.ext
I0831 20:43:23.573173 3884995520 extensions.cpp:240] Could not autoload modules: Failed reading: /var/osquery/modules.load
I0831 20:43:23.573770 234835968 watcher.cpp:477] Created and monitoring extension child (10741): /tmp/pam.ext
I0831 20:43:23.573942 235909120 interface.cpp:265] Extension manager service starting: /Users/abanks/.osquery/shell.em
osquery - being built, with love, at Facebook
-----
Using a virtual database. Need help, type '.help'

Trying to get at least a count of results is where I hit the "thrift.server.TServer" error:

osquery> select count(*) from pam;
[{'comment': '# authorization: auth account', 'args': 'use_first_pass use_kcminit', 'function_class': 'auth', 'control_flag': 'optional', 'pri...

<lots of debug output trimmed...>

 '/etc/pam.d/sudo'}]
No handlers could be found for logger "thrift.server.TServer"
+----------+
| count(*) |
+----------+
| 0        |
+----------+

I'll try those steps on my ElCap machines tomorrow.

[theopolis]

Ok, good to know. Let me try a few more things.

[arubdesu]

Yeah, different output showing a successful Extension registered on 10.11.6, but same result - can't return results, but lots of debug showing the list of dicts:

$ sudo osqueryi --verbose --extensions_autoload ./autoload.ext --allow_unsafe
I0901 16:04:32.474895 2066591744 init.cpp:374] osquery initialized [version=1.8.2]
I0901 16:04:32.475229 2066591744 extensions.cpp:278] Found autoloadable extension: /tmp/pam.ext
I0901 16:04:32.475311 2066591744 extensions.cpp:240] Could not autoload modules: Failed reading: /var/osquery/modules.load
I0901 16:04:32.475636 528384 watcher.cpp:477] Created and monitoring extension child (5330): /tmp/pam.ext
I0901 16:04:32.475908 1601536 interface.cpp:265] Extension manager service starting: /Users/abanks/.osquery/shell.em
W0901 16:04:32.476598 2066591744 config.cpp:455] Error parsing the pack JSON: sal
osquery - being built, with love, at Facebook
------
Using a virtual database. Need help, type '.help'
osquery> I0901 16:04:32.544039 2662400 interface.cpp:94] Registering extension (pam, 33607, version=1.0.1, sdk=1.8.0)
I0901 16:04:32.544350 2662400 registry.cpp:325] Extension 33607 registered table plugin pam

osquery> select count(*) from pam;
[{'comment': '# authorization: auth account',  

<lots of debug output trimmed...>

'path': '/etc/pam.d/sudo'}]
No handlers could be found for logger "thrift.server.TServer"
+----------+
| count(*) |
+----------+
| 0        |
+----------+
osquery>

[gcmurphy]

FWIW I hit a similar problem when using a osquery.INTEGER column in my table. Adding the following to the start of my extension and running the extension in the foreground helped me figure out the problem.

import logging
logging.basicConfig()

This should get rid of the No handlers could be found for logger "thrift.server.TServer" message and give some more context about what Thrift is complaining about.

[arubdesu]

Thanks @gcmurphy ! So far I'm seeing no issues getting results on 10.12(beta) by adding those lines

[theopolis]

@arubdesu, so by including those lines your table is now returning results?

[theopolis]

Got it, seems like the Thrift transport needs string values. We should enhance the example to make the clear.

[theopolis]

It seems better to me to simply accept integers and floats. Why is that impossible?

NB: I would need to dig into the Thrift-generated code to find out exactly why.

In our thrift definition we define table results as a list<map<string, string>>. Python is letting us shoot our foots by passing non-string data as the result of the generate method.

@jedi22 and I spoke about forcing everything into a string within our Python Thrift wrappers for TablePlugin but decided a documentation update might be better as to not try to guess what caller intended.

We can be flexible here and try to handle int-like structures with a str(), or detect a not-string-like input and return a more meaningful exception earlier. I'm not strict on this, a PR with an acceptable solution will win. :)

[theopolis]

This is where we call the plugin's generate method: https://github.com/osquery/osquery-python/blob/master/osquery/table_plugin.py#L43

That's where 'helped' string coercion or excepting would need to occur.