Python Logger registers multiple times, sometimes fail

seva98 — Sun, 07 Jun 2020 18:50:58 GMT

This issue is related to this https://answers.splunk.com/answers/777557/how-do-you-debug-custom-search-command-error-in-sc.html

I have generatereport.py custom search commands that tends to fail on Logger registration.

I have checked log files and found in generatereport.py.log that issue is probably in logger registration as Logger setup message runs multiple times and my logger.info() that is on start of def reduce(self, records) is not logged.

Unfortunately, this is random. Sometimes I get logger registration message logged a few times and it fails with error (post img) and sometimes I get registration message a few times and then it continues with the script as it should.

Example of log is on the bottom of this post.

This is how I start logging, taken from answers.splunk.com

def setup_logging(n):
    logger = logging.getLogger(n)
    if myDebug == 'yes':
        logger.setLevel(logging.DEBUG)
    else:
        logger.setLevel(logging.ERROR)
    LOGGING_DEFAULT_CONFIG_FILE = os.path.join(SPLUNK_HOME, 'etc', 'log.cfg')
    LOGGING_LOCAL_CONFIG_FILE = os.path.join(SPLUNK_HOME, 'etc', 'log-local.cfg')
    LOGGING_STANZA_NAME = 'python'
    LOGGING_FILE_NAME = '%s.log' % myScript
    BASE_LOG_PATH = os.path.join('var', 'log', 'splunk')
    LOGGING_FORMAT = '%(asctime)s %(levelname)-s\t%(module)s:%(lineno)d - %(message)s'
    splunk_log_handler = logging.handlers.RotatingFileHandler(os.path.join(SPLUNK_HOME, BASE_LOG_PATH, LOGGING_FILE_NAME), mode='a')
    splunk_log_handler.setFormatter(logging.Formatter(LOGGING_FORMAT))
    logger.addHandler(splunk_log_handler)
    splunk.setupSplunkLogger(logger, LOGGING_DEFAULT_CONFIG_FILE, LOGGING_LOCAL_CONFIG_FILE, LOGGING_STANZA_NAME)
    return logger


# start the logger only if needed
logger = setup_logging('logger started ...')

After that I just use this to log messages.

logger.info('message')

In this log example I have run exactly Splunk search 3 times in the row and it worked only on third try.

Example log:

## First try (NOT WORKING)
2019-10-16 10:35:49,177 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:49,178 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:35:49,575 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:49,575 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:35:50,088 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:50,089 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:35:50,631 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:50,632 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:35:51,161 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:51,163 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:35:51,755 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:35:51,756 INFO    __init__:209 - Setting logger=splunk level=DEBUG

## Second try (NOT WORKING)
2019-10-16 10:50:40,921 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:40,928 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:42,482 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:42,484 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:44,338 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:44,341 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:45,828 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:45,831 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:45,846 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:45,848 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:46,973 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:46,974 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:50:47,016 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:50:47,019 INFO    __init__:209 - Setting logger=splunk level=DEBUG

## Third try (WORKING)
2019-10-16 10:51:19,644 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:19,645 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:20,151 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:20,153 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:20,650 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:20,650 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:21,203 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:21,204 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:21,726 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:21,727 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:22,325 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:22,325 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:22,821 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:22,822 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:23,335 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:23,335 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:24,048 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:24,049 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:24,174 INFO    __init__:171 - Using default logging config file: C:\Program Files\Splunk\etc\log.cfg
2019-10-16 10:51:24,174 INFO    __init__:209 - Setting logger=splunk level=DEBUG
2019-10-16 10:51:24,178 INFO    generatereport:284 - Genearting document

topic Python Logger registers multiple times, sometimes fail in Splunk Dev

Python Logger registers multiple times, sometimes fail