Floss python library disables all other loggers

[capnspacehook]

I've been working on integrating Floss with Cuckoo Sandbox, and I've come to a bit of a problem. When running Floss, the Cuckoo logs show extremely verbose logging information from Floss. When I tried to disable this behavior by using the floss.main.set_logging_level() function, it disabled Floss's logging, as by default it sets Floss's loggers to ERROR or CRITICAL levels, but it killed all of Cuckoo's logging as well.

After perusing the Floss's source, I found the problem in main.py at lines 214-217:

def set_logging_level(should_debug=False, should_verbose=False):
    # reset .basicConfig root handler
    # via: http://stackoverflow.com/a/2588054
    root = logging.getLogger()
    if root.handlers:
        for handler in root.handlers:
            root.removeHandler(handler)

    if should_debug:
        logging.basicConfig(level=logging.DEBUG)
    elif should_verbose:
        logging.basicConfig(level=logging.INFO)
    else:
        logging.basicConfig(level=logging.WARNING)

set_logging_level() removes all handlers of the root logger. So, if Floss is used as a library in an existing project with logging, there is no easy way to change Floss's logging level without killing all other logging, or by setting the level of the 10 or so loggers that are associated with Floss manually.

I would suggest that maybe set_logging_level() could be revised to take an additional argument that would determine if the root logger's handles are removed. This would allow for other projects to integrate with Floss more easily. I was going to do just that and make a pull request, but if the root logger has handlers, calling logging.basicConfig() in lines 219-224 would have no effect.

I'm not sure as of how to set Floss's logging level globally without using logging.basicConfig(), do you guys have any ideas?

[williballenthin]

Hey @capnspacehook

We're really excited to hear that you're integrating FLOSS with Cuckoo; please let us know whatever we can do to assist!

We've tried to design FLOSS in such a way that it can be used as a stand alone tool, or as a library. Therefore, your use case is perfectly valid.

Our design for floss.main is that this main module should be responsible for handling input/output and user interaction, while invoking the "FLOSS algorithms". From a purists point of view, this is the one file that is not in scope for use as a library.

I would discourage you from invoking floss.main.main(), and instead provide your own implementation of this main routine. It may even look 95% similar to what's already in FLOSS, but I think this duplication is ok. You should still be able to import and invoke helpers like floss.main.is_supported_filetype(), etc. This will allow you to configure loggers to your liking, while still using much of FLOSS's existing code.

For example, internally at FireEye, we run FLOSS against all the malware we encounter on a daily basis. We have a custom script that invokes the FLOSS library, using the helpers in main to set things up, yet configuring the input/output formats slightly differently (JSON in, JSON out). It looks something like this:

def main():
    # Handle command-line arguments
    parser = argparse.ArgumentParser(description='Use Floss to extract PE strings')
    parser.add_argument('--file','-f', help='file to inspect <STDIN> default')
    args = parser.parse_args()

    logging.basicConfig(level=logging.ERROR)

    if args.file:
        try:
            f = open(args.file, 'rb')
            bytez = f.read()
        except IOError, e:
            logging.error("%s" %(str(e)))
            sys.exit(1)
    else:
        f = sys.stdin
        bytez = f.read()
        bytez, parameters = internal.parse_input_document(bytez)

    # FLOSS currently supports PE files (32- and 64-bit), try to analyze the file as shellcode otherwise
    analyze_as_shellcode = not is_supported_file_type(bytez)

    time0 = time()
    decoded_strings, stack_strings = internal.load_floss(bytez, analyze_as_shellcode, MIN_STRING_LENGTH)
    time1 = time()
    if decoded_strings or stack_strings:
        service_output = internal.format_output(decoded_strings, stack_strings)

        all_strings = get_all_strings(service_output)
        if internal.contains_high_confidence_strings(all_strings):
            internal.add_floss_badge(service_output, len(all_strings))

        if analyze_as_shellcode:
            # this might be useful for data analysis, probably not very interesting for users
            service_output['shellcode'] = "True"

        service_output['runtime'] = "%.02f" % (time1 - time0)

        print(json.dumps(service_output))
        sys.exit(0)
    else:
        sys.exit(EMPTY)

[capnspacehook]

Thanks for the detailed answer @williballenthin. I'm really excited to have the opportunity to work on these two amazing projects!

I'm not actually importing or invoking floss.main.main(), and as I said above, floss.main.set_logging_level() is the only function that I see that will allow me to set Floss's logging level. I'm not sure how I would set Floss's logging level without using the floss.main.set_logging_level() function, which has the problems I mentioned above.

I also can't just add logging.basicConfig(level=logging.ERROR), because logging.basicConfig has no effect when logging handlers are already set, which Cuckoo does on startup.

[williballenthin]

Ah, right.

Reading your initial comment a bit closer, I see this:

or by setting the level of the 10 or so loggers that are associated with Floss manually.

I think this is the expected way to configure the loggers. Its a bit of an exercise to figure out all the available loggers (in fact, I'm not sure how you're supposed to do this for a library, except by trial and error), but does allow for the most configurability.

Grepping through the FLOSS source code, I see the following loggers:

• floss
• floss.plugins.arithmetic_plugin (might be dead?)
• floss.stackstrings

And the loggers from libraries on which FLOSS depends:

• EmulatorDriver (noisy, from viv-utils)
• Monitor (noisy, from viv-utils)
• envi/codeflow.addCodeFlow (noisy, from vivisect)
• vtrace.platforms.win32 (noisy, from vivisect)

I'd recommend either:

1. reconfiguring the above loggers to your liking, or
2. copying set_logging_level into your project and removing the offending lines

set_logging_level should only be called by FLOSS when run as a command line utility.

Do you have any ideas for how the logging might be better exposed/configured?

[williamgibb]

@williballenthin The set_logging_level function should probably be split into two functions - one function which sets the misc library loggers to a sane value, and one which nukes existing loggers, does the basic config calls and (optionally, based on verbosity settings), calls the first function to set the library loggers specifically.

This would allow @capnspacehook to set his own basisconfig, log floss components how he wants to, and have a one-shot function that he can call to set all the misc library stuff to sane values without having to manage all those loggers himself.

[capnspacehook]

I guess for now I will just set all the loggers manually. That does work, though as you said it requires a bit of trial and error discovering all of the loggers.

I was actually just going to say something like that @williamgibb. You hit the nail on the head there.

[williamgibb]

@capnspacehook A PR for doing that should be... 2 lines of code? One to define the new function header and one to call said function from within the end of set_logging_level ?

[capnspacehook]

Well @williamgibb I would like for the new function to sets ALL of Floss's loggers to the value the user provides. So it would be more than just 2 lines, but I would be happy to submit a PR for that :)

[williballenthin]

🎉