nailgun-api log is too verbose

[Mike Scherbakov]

See similar issue from nailgun-agent side: https://bugs.launchpad.net/fuel/+bug/1393115

api.log became almost 1Mb in 1.5h, which is way too much. Being archived into diag snapshot then, it makes snapshot too large and not very useful for support team.
Analysis of log file shows that it is mostly polluted by data from nailgun-agent, like:
2014-11-16 00:53:17.716 DEBUG [7fb4b2b95740] (logger) Request PUT /api/nodes/agent/ from 172.17.42.1:39247 {"manufacturer":"QEMU","os_platform":"centos","mac":"64:10:F4:76:B1:6E","is_agent":true,"agent_checksum":"fdcb2f84cfef53e8e7a97479b3e10cc4c6835292","platform_name":"Standard PC (i440FX + PIIX, 1996)","meta":{"disks":[{"model":null,"disk":"disk/by-path/pci-0000:00:0a.0-virtio-pci-virtio7","removable":"0","size":53687091200,"extra":[],"name":"vdc"},{"model":null,"disk":"disk/by-path/pci-0000:00:09.0-virtio-pci-virtio6","removable":"0","size":53687091200,"extra":[],"name":"vdb"},{"model":null,"disk":"disk/by-path/pci-0000:00:08.0-virtio-pci-virtio5","removable":"0","size":53687091200,"extra":[],"name":"vda"}],"memory":{"devices":[{"type":"RAM","size":2147483648}],"maximum_capacity":2147483648,"slots":1,"total":2147483648},"cpu":{"total":1,"real":1,"spec":[{"model":"Intel Xeon E312xx (Sandy Bridge)","frequency":3500}]},"system":{"manufacturer":"QEMU","version":"pc-i440fx-trusty","fqdn":"node-3.test.domain.local","product":"Standard PC (i440FX + PIIX, 1996)"},"interfaces":[{"mac":"64:7B:AA:D8:9F:E2","state":"up","current_speed":null,"name":"eth4"},{"mac":"64:DF:C3:24:6A:A4","state":"up","current_speed":null,"name":"eth3"},{"mac":"64:13:7C:70:EB:73","state":"up","current_speed":null,"name":"eth2"},{"mac":"64:59:E3:6F:3A:F9","state":"up","current_speed":null,"name":"eth1"},{"mac":"64:10:F4:76:B1:6E","netmask":"255.255.255.0","state":"up","current_speed":null,"name":"eth0","ip":"10.108.0.4"}]},"ip":"10.108.0.4"}

If we already log this data on nailgun-agent side, I propose to remove this verbosity and not to log data structure which comes from agent.
Instead, we have a tricky code which works on Nailgun side, and which updates internal data structure only if it changed. I propose to log only that moment: changed data, not everything.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/137053

[Łukasz Oleś (loles)]

This data are not logged on nailgun-agent side. If you remove it from api we will not see what agent is sending.
Yesterday I was helping support team and I used this data to solve the problem. Without this logs I couldn't solve it.

I see three ways to fix this problem:

1) fix it in shotgun. Do not download all logs. We usually just need data from last week
2) fix agent to not send so many data. Do wee need it all?
3) log this data on nodes (this lead to hacks on api side)

[OpenStack Infra (hudson-openstack)]

Change abandoned by Dmitry Pyzhov (<email address hidden>) on branch: master
Review: https://review.openstack.org/137053
Reason: No activity for more than a month

[Ihor Kalnytskyi (ikalnytskyi)]

I don't think it's really important for 7.0. Let's move it to 8.0, because we can remove something important by accident here.

Moreover, we shouldn't remove API input. We definitely should log it.

[Mike Scherbakov (mihgen)]

Just hit this one again. 20 nodes deployment, and default configuration of logrotate for nailgun api.log lasts for a ===few hours=== with 4 archived copies of log file, each 14Mb in size.
For production installation configuration, I'd expect to see nailgun log for at least a few months.

Without this log, I spent a few hours trying to debug an issue, and was essentially unable to do so. As this severely affects operations and any troubleshooting, I raised priority to High.

[Mike Scherbakov (mihgen)]

Added customer-found tag as well.

[Roman Rufanov (rrufanov)]

customer found on 8.0, adding milestone

[Rodion Tikunov (rtikunov)]

Reopened for 9.0 as it was closed as won't fix by Fuel Devops McRobotson.

[JohnsonYi (yichengli)]

The nailgun api log size increased two fast in fuel 8.0.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/392528

[Anton Chevychalov (achevychalov)]

I prepared commit to stable/mitaka based on the following idea.

Problem:

1. api.log rotate to fast due to messages with node information.
2. we can't disable massage storing because it is useful information.

Solution:

1. Create separate log for storing nodes information from nailgun-agent (see commit above).
2. Create logrotate config for new log.
3. Change snapshot generation logic to restrict amount of information from new log to something like 5k lines.

[Vitaly Sedelnik (vsedelnik)]

Retargeted to 9.3 as more time is needed to get the patch reviewed and merged.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/425239

[Denis Meltsaykin (dmeltsaykin)]

Setting as Won't Fix since it would take a lot of effort and doesn't fit the maintenance policy. Moreover, Nailgun has extensive log rotation in the fuel's logrotate settings.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Andreas Jaeger (<email address hidden>) on branch: master
Review: https://review.opendev.org/425239
Reason: This repo is retired now, no further work will get merged.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Andreas Jaeger (<email address hidden>) on branch: stable/mitaka
Review: https://review.opendev.org/392528
Reason: This repo is retired now, no further work will get merged.