Some logs from Openstack services are not collected by Syslog

[Pavel Vaylov]

Environment:
Fuel 4.0 HA 5 nodes (3 controller nodes 2 compute nodes). CentOS with Neutron+VLAN segmentation.
But anyway I think this bug also affect many configurations.

Steps to reproduce:
- Deploy environment with default settings.
- Check that everything is working well. (Launch instance etc)
- Restart nova-compute service on compute node.
- Check log files on masternode. /var/log/remote/node-9.domain.tld/nova-*

Expected result:

Strings like following will appear in log files:

2014-02-25 21:31:42.479 27508 INFO nova.openstack.common.periodic_task [-] Skipping periodic task _periodic_update_dns because its interval is negative
2014-02-25 21:31:42.541 27508 INFO nova.virt.driver [-] Loading compute driver 'libvirt.LibvirtDriver'
2014-02-25 21:31:42.602 27508 INFO nova.openstack.common.rpc.common [req-a28ada32-cad8-4d7d-b5e4-89bf533b38d1 None None] Connected to AMQP server on 192.168.0.2:5672
2014-02-25 21:31:42.623 27508 INFO nova.openstack.common.rpc.common [req-a28ada32-cad8-4d7d-b5e4-89bf533b38d1 None None] Connected to AMQP server on 192.168.0.2:5672
2014-02-25 21:31:42.653 27508 AUDIT nova.service [-] Starting compute node (version 2013.2.1.fuel4.0-mira15)

Actual result:

Strings like following will never appear in log files.

Workaround:

- Edit /etc/nova/nova.conf on compute node.
Disable syslog logging.
use_syslog=false
Comment following strings:
#log_config=logging.conf
#syslog_log_facility=LOCAL6

- Restart nova-compute service.

- Check local nova log /var/log/nova/compute.log

Strings like following will appear in log files:

2014-02-25 21:31:42.479 27508 INFO nova.openstack.common.periodic_task [-] Skipping periodic task _periodic_update_dns because its interval is negative
2014-02-25 21:31:42.541 27508 INFO nova.virt.driver [-] Loading compute driver 'libvirt.LibvirtDriver'
2014-02-25 21:31:42.602 27508 INFO nova.openstack.common.rpc.common [req-a28ada32-cad8-4d7d-b5e4-89bf533b38d1 None None] Connected to AMQP server on 192.168.0.2:5672
2014-02-25 21:31:42.623 27508 INFO nova.openstack.common.rpc.common [req-a28ada32-cad8-4d7d-b5e4-89bf533b38d1 None None] Connected to AMQP server on 192.168.0.2:5672
2014-02-25 21:31:42.653 27508 AUDIT nova.service [-] Starting compute node (version 2013.2.1.fuel4.0-mira15)

Impact:

- Some useful information has been lost.
- Not sure what information will be lost during instance provisioning tasks and so on.

[Pavel Vaylov (pvaylov)]

Attaching compute.log.
This file from compute node appeared after I disabled Syslog.

[Andrew Woodward (xarses)]

More importantly, critical to catch logs like stack traces are lost when syslog is enabled.

I've seen this occurring in multiple services including glance, nova, and cinder. Others may be impacted too.

[Pavel Vaylov (pvaylov)]

Andrew, I thought that we can fill in a bug report for every log issue but this way also possible.
I'm afraid of overloading this bug report with information about different services.

[Bogdan Dobrelya (bogdando)]

TRACE and DEBUG levels are lower then INFO level, by default Fuel configures verbose mode for Openstack, so TRACEs and DEBUGs will not be captured

[Pavel Vaylov (pvaylov)]

We do not need private status. No private information in log files.
Also I can provide full diagnostic snapshot from my lab (75Mb) if you really need it.

[Bogdan Dobrelya (bogdando)]

Reproduced with #211 (4.1).
- The issue is related to the deprecated log_config usage in Havana, see https://bugs.launchpad.net/fuel/+bug/1263660.
- There is also refactoring logging BP https://blueprints.launchpad.net/fuel/+spec/refactor-logging-puppet-openstack-services exists according to which we will fix this issue automatically by removing python logging configs from OS puppet modules as well (see option2, targeted for 5.0)

[Pavel Vaylov (pvaylov)]

Not sure if I understand correctly.

Any workaround for installed environments ?
And for new releases ?

[Bogdan Dobrelya (bogdando)]

The one option for existing envs is to use debug = true. Debug case uses another method of capturing local Openstack logs to syslog and ensures no messages will be skipped because of the python logging configs (note: UDP protocol does not provides reliable delivery for logging messages, though)

Another option is for every 'foo-bar' Openstack service, use log_config_append instead of log_config and correct
log_format=%(asctime)s.%(msecs)06d+00:00 foo-bar %(levelname)s: %(name)s: %(message)s
and log_date_format=%Y-%m-%dT%H:%M:%S
For example, patch for nova config could be http://pastebin.com/akN4J2EN. That would make all nova subservices to log locally as is, and remotely to /var/log/remote/node-baz.qux/nova.log

For new releases, we will just put use_syslog_rfc_format=True option in the OS configs to resolve this issue.

[Bogdan Dobrelya (bogdando)]

notes:
1)You can use as well logging_context_format_string and logging_default_format_string instead of log_format
2)debug=true is referenced as a deployment option in UI or in astute.yaml, not the same one in OS configs...

[Andrey Danin (gcon-monolake)]

Bogdan, can we somehow enable local logs storing in addition to send them to the master node? I mean any workaround for 4.0 and 4.1.

[Pavel Vaylov (pvaylov)]

Folks, still can not understand if we can use syslog but put *ALL* compute logs to one remote file instead of many remote files ?

[Bogdan Dobrelya (bogdando)]

>>> Bogdan, can we somehow enable local logs storing in addition to send them to the master node? I mean any workaround for 4.0 and 4.1.

But we do have it now. Local Openstack logs are stored as /var/log/<service>-all.log for default deployment mode, and as /var/log/<service>/<subservice>.log for debug (and for syslog=false) case.

>>> Folks, still can not understand if we can use syslog but put *ALL* compute logs to one remote file instead of many remote files ?

Current design provides remote logs are being divided by the syslog message TAG/APP-NAME(with some known issues, see https://bugs.launchpad.net/oslo/+bug/904307).
Yes, it is possible to make Fuel to configure OS to log each service into its own remote file.

[Pavel Vaylov (pvaylov)]

Bogdan, it is empty "/var/log/<service>-all.log"

I think we should put all log from one service to one file by default since we can't fix issue with proper log dividing.

[Bogdan Dobrelya (bogdando)]

Please provide all /var/log/*-all.log* and /var/log/nova/*.log* files from the compute node you're experiencing issues with.

[Bogdan Dobrelya (bogdando)]

And please make sure you've enabled syslog back and restarted nova-compue, before to collect the logs

[Pavel Vaylov (pvaylov)]

Bogdan, I was wrong in "/var/log/nova-all.log" we can see same content as "/var/log/remote/node-xx/nova-*" but in one file.

You can see it on my Lab:
172.16.73.36 - masternode
172.16.73.41 - compute with disabled syslog
172.16.73.42 - compute with default Fuel configuration

Credentials are standard. Environment will be available for a few hours.

[Bogdan Dobrelya (bogdando)]

Currently syslog logs are collected using log_config configuration option, which has some issues with disable existing python loggers, hence, some of the log messages could be skipped in syslog remotely and locally (/var/log/*-all.log files).

This is not a critical issue (all ERRORS should present anyway). To w/a this for pre-5.1 releases (see my comment above, 2014-02-26), user should redeploy or reapply puppet using debug= true in astute.yaml or patch OS configuration files appropriately.

In 5.0 release we will drop log_config usage and apply Oslo patch to configure rfc5424 compliant logging to syslog. That should resolve missing messages issues as well.

[Bogdan Dobrelya (bogdando)]

>>> "/var/log/nova-all.log" we can see same content as "/var/log/remote/node-xx/nova-*" but in one file

As designed, so I will put this ticket to appropriate state for now...

[Dmitry Borodaenko (angdraug)]

I've created a separate bug to track the problem of not having stack traces logged by default:
https://bugs.launchpad.net/fuel/+bug/1289659

[Pavel Vaylov (pvaylov)]

I've tested logging behavior one more time per Mike's request:

Nova services (api, scheduler) to quit without "debug" logging level.
Even when we launch an instance only a few strings added to log files.

So looks like we not loosing to much logs from api and scheduler.

[Bogdan Dobrelya (bogdando)]

No more invalid due to changing design in order to collect logs with new use_syslog_rfc_format option.

[Bogdan Dobrelya (bogdando)]

fix in review https://review.openstack.org/#/c/90980/

[Dennis Dmitriev (ddmitriev)]

{"build_id": "2014-09-17_21-40-34", "ostf_sha": "64cb59c681658a7a55cc2c09d079072a41beb346", "build_number": "11", "auth_required": true, "api": "1.0", "nailgun_sha": "eb8f2b358ea4bb7eb0b2a0075e7ad3d3a905db0d", "production": "docker", "fuelmain_sha": "8ef433e939425eabd1034c0b70e90bdf888b69fd", "astute_sha": "f5fbd89d1e0e1f22ef9ab2af26da5ffbfbf24b13", "feature_groups": ["mirantis"], "release": "5.1", "release_versions": {"2014.1.1-5.1": {"VERSION": {"build_id": "2014-09-17_21-40-34", "ostf_sha": "64cb59c681658a7a55cc2c09d079072a41beb346", "build_number": "11", "api": "1.0", "nailgun_sha": "eb8f2b358ea4bb7eb0b2a0075e7ad3d3a905db0d", "production": "docker", "fuelmain_sha": "8ef433e939425eabd1034c0b70e90bdf888b69fd", "astute_sha": "f5fbd89d1e0e1f22ef9ab2af26da5ffbfbf24b13", "feature_groups": ["mirantis"], "release": "5.1", "fuellib_sha": "d9b16846e54f76c8ebe7764d2b5b8231d6b25079"}}}, "fuellib_sha": "d9b16846e54f76c8ebe7764d2b5b8231d6b25079"}