2.2: Daemon log level issue

[GuusH]

Hi,

I tried to upgrade our distributed production environment (5 monitoring hosts monitoring 1500 instances and 50.000+ services) from 2.0.3 to 2.2 and I ran into serious trouble. We ran our daemons with loglevel INFO and got into issues (I'll get to that below). As a work around we tried setting the loglevel to WARNING, but after stopping and starting the services they kept logging at INFO level. So something is not working properly there it seems.

The bigger issue is the following. As stated we have a pretty large config. The arbiter outputs a line for each host and service at INFO level and if there's something like a service has no contact (also?) a WARNING line. So for our config this generates between 75.000 and 100.000 lines of output. Which is in itself not so bad, but for some reason these lines are being sent to the broker. The broker looks at these lines, concludes that it's not a valid line for storing in Mongo and then drops it. But it takes forever to do all this and while it's doing this it's not responding to requests on its livestatus module, so Thruk is unhappy. So as a work around we tried setting the loglevel to WARNING as stated earlier, but that didn't work.

Example of entries I got in brokerd.log:

[1424865789] INFO: [broker-ops-shinken01.example.com] [LogStoreMongoDB] This line is invalid: [1424865069] INFO: [Shinken] Processing object config file '/etc/shinken/monitoring_config/manual/hosts/gsp-lt-ndb-app01.example.com/gsp-lt-ndb-app01.example.com-FILESYSTEM__.cfg'

So why is the output from the config test of the arbiter sent to the broker in the first place?

I also got exciting stuff like this, but I suspect that's because the broker is busy plowing through those lines:

[1424865789] ERROR: [broker-ops-shinken01.example.com] LiveStatusClientError: Could not send response: [Errno 32] Broken pipe

I haven't had time to look through the code to find where this is done, but you can maybe pinpoint this much quicker than I can. If you need any info from me to help debug this, please let me know!

Thanks!

Guus

[GuusH]

Forgot: we did a rollback to 2.0.3, but kept the loglevel at WARNING. It's definitely working as it should in 2.0.3, as I'm not seeing any logs at INFO anymore since that rollback.

[dkanbier]

There is definitely something weird going on with the Log object I'd say. I've added these print lines:

deamon.py:

   def do_daemon_init_and_start(self, use_pyro=True, fake=False):
        self.change_to_user_group()
        self.change_to_workdir()
        self.check_parallel_run()
        if use_pyro:
            self.setup_pyro_daemon()

        # Setting log level
        print "daemon.py using log level %s" % self.log_level
        logger.setLevel(self.log_level)

In arbiterdaemon.py:

class IForArbiter(Interface):

    doc = 'Does the daemon got a configuration (internal)'
    def have_conf(self, magic_hash):
        # Beware, we got an str in entry, not an int
        print "arbiterdaemon.py using log level %s" % logger.getEffectiveLevel()

Now setting the log_level option in shinken.cfg causes the line from daemon.py print the same level (set log_level in shinken.cfg to CRITICAL it will report "50"). However, the line from arbiterdaemon.py always prints "20" (INFO).

So the setting gets lost (is the logger object from arbiterdaemon.py the same object which is used by daemon.py?) or is not shared with other objects.

[dkanbier]

Also, this code from daemon.py is not working anymore in shinken 2.2:

    doc = 'Get the current log level in [NOTSET, DEBUG, INFO, WARNING, ERROR, CRITICAL, UNKNOWN]'
    def get_log_level(self):
        return {logging.NOTSET: 'NOTSET', logging.DEBUG:'DEBUG',
                logging.INFO: 'INFO', logging.WARNING: 'WARNING',
                logging.ERROR : 'ERROR', logging.CRITICAL : 'CRITICAL'}.get(logger._level, 'UNKNOWN')
    get_log_level.doc = doc

because the method "_level" is not present in the Log class in 2.2 (and is available in 2.0.3). This might be related?

[Seb-Solon]

Hi. The logging part was refactored. We removed some useless part to delegate everything we can to the logging lib.

The thing is, the logger is in INFO at the beginning until the configuration parameter is loaded and the level is modified.

Another thing to know : there is one global level and level for handlers. Handler does not have the same level than the logger (that how filter is done).

The issue here is that logger created by shinken are sent to the broker as Broks (like every log in Shinken) and we may consider defining 2 different logger for that. I mentionned this pont some time ago when refactoring the logging part

[olivierHa]

Any updates on this issue ?
Those logs shouldn't be sent to broker :(

2015-03-11 19:34 GMT+01:00 Sébastien Coavoux notifications@github.com:

Hi. The logging part was refactored. We removed some useless part to
delegate everything we can to the logging lib.

The thing is, the logger is in INFO at the beginning until the
configuration parameter is loaded and the level is modified.

Another thing to know : there is one global level and level for handlers.
Handler does not have the same level than the logger (that how filter is
done).

The issue here is that logger created by shinken are sent to the broker as
Broks (like every log in Shinken) and we may consider defining 2 different
logger for that. I mentionned this pont some time ago when refactoring the
logging part

—
Reply to this email directly or view it on GitHub
#1525 (comment).

[Seb-Solon]

Logs are sent to the broker by design. The issue here is that default logging is set to INFO until the config is read and set to WARNING. In 2.0.3 those log where just dumped I think (not written to file)

This is in my opinion an issue regarding the whole log system s we will have to fix that in the next release. See #1201 for details

[ser]

Shinken 2.4.3, completely ignores log_level=WARNING set up and uses INFO instead.