[openstack-dev] [olso] olso incubator logging issues

Doug Hellmann doug.hellmann at dreamhost.com
Wed Jul 9 12:24:59 UTC 2014


On Wed, Jul 9, 2014 at 7:39 AM, Sean Dague <sean at dague.net> wrote:
> On 07/03/2014 01:52 PM, Doug Hellmann wrote:
>> On Mon, Jun 30, 2014 at 9:00 AM, Sean Dague <sean at dague.net> wrote:
>>> Every time I crack open a nova logs in detail, at least 2 new olso
>>> incubator log issues have been introduced.
>>>
>>> The current ones is clearly someone is over exploding arrays, as we're
>>> getting things like:
>>> 2014-06-29 13:36:41.403 19459 DEBUG nova.openstack.common.processutils
>>> [-] Running cmd (subprocess): [ ' e n v ' ,   ' L C _ A L L = C ' ,   '
>>> L A N G = C ' ,   ' q e m u - i m g ' ,   ' i n f o ' ,   ' / o p t / s
>>> t a c k / d a t a / n o v a / i n s t a n c e s / e f f 7 3 1 3 a - 1 1
>>> b 2 - 4 0 2 b - 9 c c d - 6 5 7 8 c b 8 7 9 2 d b / d i s k ' ] execute
>>> /opt/stack/new/nova/nova/openstack/common/processutils.py:160
>>>
>>> (yes all those spaces are in there, which now effectively inhibits search).
>>>
>>> Also on every wsgi request to Nova API we get something like this:
>>>
>>>
>>> 2014-06-29 13:26:43.836 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute:get will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.837 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:security_groups will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.838 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:security_groups will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.838 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:keypairs will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.838 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:hide_server_addresses will be now enforced
>>> enforce /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.838 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_volumes will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.842 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:config_drive will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.842 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:server_usage will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.842 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_status will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.843 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_server_attributes will be now enforced
>>> enforce /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.843 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_ips_mac will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.843 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_ips will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.843 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:extended_availability_zone will be now enforced
>>> enforce /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>> 2014-06-29 13:26:43.844 DEBUG nova.openstack.common.policy
>>> [req-86680d63-6d6c-4962-9274-1de7de8ca37d
>>> FixedIPsNegativeTestJson-768779075 FixedIPsNegativeTestJson-579905596]
>>> Rule compute_extension:disk_config will be now enforced enforce
>>> /opt/stack/new/nova/nova/openstack/common/policy.py:288
>>>
>>> On *every* request.
>>>
>>> oslo code, by definition, is going to be used a lot, inside of tight
>>> loops. Which means extremely verbose. Actually
>>> nova.openstack.common.policy currently represents ~40% of all bytes in
>>> nova-api logs (15 MB uncompressed content during a Tempest run).
>>>
>>> Both these are bugs that should be fixed, however, I'd like to figure
>>> out how we come up with more systematic approach to keep the quality of
>>> these things up, especially as an oslo fix is expensive in terms of
>>> labor, as we have to fix in oslo first, then sync to projects. And as
>>> more syncs have caused issues like this an oslo sync is not longer a
>>> fast approve as it used to be.
>>
>> Do you have some automation in mind, or just focusing more on logging
>> in reviews?
>
> I don't know. I'm just concerned that some really bad bugs are slipping
> through oslo incubator, which is then copy / pasted into projects before
> they get noticed (because there is no forward testing), then we have to
> run around and replicate fixes everywhere.

The best solution I've been able to come up with to that is to
graduate libraries, and we're working on that. I'm tempted to say that
in the future no more than 2 projects should adopt any given incubated
module until it graduates, but I don't like arbitrary limits like
that.

Doug

>
> Stuff like this is generating a ton of extra work on everyone that's not
> oslo.
>
>         -Sean
>
> --
> Sean Dague
> http://dague.net
>
>
> _______________________________________________
> OpenStack-dev mailing list
> OpenStack-dev at lists.openstack.org
> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
>



More information about the OpenStack-dev mailing list