OpenStack Heat

Heat logs too big

Bug #1499330 reported by Derek Higgins on 2015-09-24

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Heat	Fix Released	High	Steve Baker	OpenStack Heat 5.0.0 "liberty"
	tripleo	Fix Released	High	Unassigned

Bug Description

On the tripleo HA jobs at the moment the undercloud tarball artifact is coming in around 26MB

From the looks of it the majority of this is comming from heat-engine.log and the journal log (which contains the same heat-engine log entries in it in a binary non zip friendly format)

We have 100's of 1000's of log entries of the format

Sep 24 07:24:21 instack.localdomain heat-engine[10240]: 2015-09-24 06:24:21.089 10240 INFO heat.engine.environment [-] Registering OS::TripleO::CephClusterConfig::SoftwareConfig -> file:///usr/share/openstack-tr

JOBLOGS ]$ ls -lh heat/heat-engine.log journal/dae72fe0cc064eb0b7797f25bfaf69df/system*
-rw-r--r--. 1 derekh derekh 65M Sep 24 07:53 heat/heat-engine.log
-rw-r-----. 1 derekh derekh 128M Sep 24 07:24 journal/dae72fe0cc064eb0b7797f25bfaf69df/system@c1bc0754cbcc4c89bee2d499e09610e0-0000000000000001-000520775d91ac90.journal
-rw-r-----. 1 derekh derekh 128M Sep 24 07:39 journal/dae72fe0cc064eb0b7797f25bfaf69df/system@c1bc0754cbcc4c89bee2d499e09610e0-0000000000023fbf-0005207847f9f68c.journal
-rw-r-----. 1 derekh derekh 120M Sep 24 07:54 journal/dae72fe0cc064eb0b7797f25bfaf69df/system.journal

JOBLOGS ]$ wc heat/heat-engine.log
302099 3328855 67386843 heat/heat-engine.log

JOBLOGS ]$ journalctl --file ./journal/dae72fe0cc064eb0b7797f25bfaf69df/system@c1bc0754cbcc4c89bee2d499e09610e0-0000000000000001-000520775d91ac90.journal --file ./journal/dae72fe0cc064eb0b7797f25bfaf69df/system@c1bc0754cbcc4c89bee2d499e09610e0-0000000000023fbf-0005207847f9f68c.journal --file journal/dae72fe0cc064eb0b7797f25bfaf69df/system.journal -u openstack-heat-engine | wc
178398 2854476 49832178

This a far too verbose and as far as I can see most of the log entries are repeating themselves, the quantity of data need to be reduced.

Tags:

Revision history for this message

Steven Hardy (shardy) wrote on 2015-09-24:

I think the issue is we should only ever dump the " Registering foo" data on create or update, only for the parent stack, but I think we're doing it for all nested stacks and/or all other API requests, hence all the duplication.

Changed in heat:
status:	New → Triaged
importance:	Undecided → High
assignee:	nobody → Steven Hardy (shardy)
milestone:	none → mitaka-1

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-09-24: Fix proposed to heat (master)

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

Changed in heat:
status:	Triaged → In Progress

Revision history for this message

Steven Hardy (shardy) wrote on 2015-09-28:

I tagged this liberty-rc-potential for Heat - it's not a release blocker, but IMO it's worth considering if we have other reasons for an rc2 - it's reduced the TripleO CI logs to 0.5% of their previous size, so should have similarly worthwhile reductions in noise for all users logging at INFO or DEBUG levels.

tags:

added: liberty-rc-potential tripleo

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-09-30: Fix merged to heat (master)

Reviewed: https://review.openstack.org/227441
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=5d6234ecf64650b0eb7bd92eb530e899ff061457
Submitter: Jenkins
Branch: master

commit 5d6234ecf64650b0eb7bd92eb530e899ff061457
Author: Steven Hardy <email address hidden>
Date: Thu Sep 24 18:41:34 2015 +0100

Reduce frequency of logging environment resources

    Currently we log all template resources every time any API call
    happens which indirectly creates an Environment object, which
    results in a lot of duplicate bloat in the heat logs (not even
    at debug level..)

    So, instead log all environment resources (e.g those from resource
    plugins and the global environment) only when we start the
    service, and log user-provided template resources only when we
    do the template validation on create/update, for only the root stack,
    because we pass a derived subset environment down to all children.

    We also switch to using the string representation of the ResourceInfo
    objects, as this contains a bit more useful info than the current
    log format.

Change-Id: I20007c1ad6bf8b1479c1d60a5c392b8b9e1c06c4
Closes-Bug: #1499330

Changed in heat:
status:	In Progress → Fix Committed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-10-06: Fix proposed to heat (stable/liberty)

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/231276

Thierry Carrez (ttx) on 2015-10-06

no longer affects:	heat/mitaka
no longer affects:	heat/liberty
Changed in heat:
status:	In Progress → Fix Committed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-10-06: Fix merged to heat (stable/liberty)

Reviewed: https://review.openstack.org/231276
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=182034904f7da306c677e77c880a6266b1b5cd50
Submitter: Jenkins
Branch: stable/liberty

commit 182034904f7da306c677e77c880a6266b1b5cd50
Author: Steven Hardy <email address hidden>
Date: Thu Sep 24 18:41:34 2015 +0100

Reduce frequency of logging environment resources

    We also switch to using the string representation of the ResourceInfo
    objects, as this contains a bit more useful info than the current
    log format.

    Change-Id: I20007c1ad6bf8b1479c1d60a5c392b8b9e1c06c4
    Closes-Bug: #1499330
    (cherry picked from commit 5d6234ecf64650b0eb7bd92eb530e899ff061457)

tags:

added: in-stable-liberty

Thierry Carrez (ttx) on 2015-10-06

Changed in heat:
status:	Fix Committed → Fix Released

Thierry Carrez (ttx) on 2015-10-15

Changed in heat:
milestone:	liberty-rc2 → 5.0.0

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-10-15: Fix proposed to heat (master)

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

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-10-16: Fix merged to heat (master)

Download full text (9.5 KiB)

Reviewed: https://review.openstack.org/235237
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=4bf298763005b4b8e0c9c8d64ad7ad0863405b50
Submitter: Jenkins
Branch: master

commit 4348b7ababd1048e17ec354ca38c903c908cd74e
Author: Steve Baker <email address hidden>
Date: Tue Oct 6 12:54:24 2015 +1300

Do no net/subnet checks during validate

    Currently validation fails if the network or the subnet are defined in
    the same template as the server because they don't exist during
    validate.

_validate_belonging_subnet_to_net is called during _build_nics so this
check still happens when the required resources actually exist.

    Also, test method validate_internal_port_subnet_not_this_network was not
    running because its name was not prefixed with test_. Fixing and
    updating this test revealed issues with the validation failed message.

Closes-Bug: #1503060
Change-Id: I2e062abf5b9fb7446b979ba6acc2e2b531d957d6

commit 7e911cec083e98f344bfcfeb7e2e843ce2330d5d
Author: Pratik Mallya <email address hidden>
Date: Mon Oct 5 00:34:12 2015 -0500

Correctly filter events on resource name

    Filtering on resource name can be accomplished by using the db
    filters instead of using a filter method. Furthermore, using a
    custom filter breaks certain assumptions made by other parts of
    the codebase, which lead to pagination being broken.
    Specifically, custom filter for resource name is applied only
    after other filtering is finished. As a result, we try to find
    result from only 1 event and this event belongs to whole
    stack and thus its resource_name is equal to the stack name.
    This returns an event not found error instead of returning
    the first event assosciated with the resource name.

    Change-Id: Ie7d28ffb88a79d6e0f516f0db385be2eed59f7f0
    Closes-Bug: #1502751
    (cherry picked from commit 6322ff6fceabdfa226e5359328bde292d189e703)

commit fecc2bacb51c7dabdb83b87313df48dea527feae
Author: Pratik Mallya <email address hidden>
Date: Thu Oct 1 17:41:09 2015 -0500

Check if os-interface extension is present before saving ports

If that extension is not present, then the code to extract and
save ports created during server create by nova will fail.

    Change-Id: I6008a0da0c16a34c40e343af4e7237520db4ae36
    Closes-Bug: #1499877
    (cherry picked from commit 46d8c276b70e7698438988faa9d997577a7e1750)

commit 6c3fa4e25d3e35adf53ad1e80d5455bf9f7a924a
Author: Peter Razumovsky <email address hidden>
Date: Mon Sep 14 17:43:49 2015 +0300

Fix translating for props with get_param value

    If some map or list type properties specified with
    json-type or commadelimitedlist parameters, error
    raised in case of wrong properties data parsing.
    Fix this case by adding check if data is GetParam
    instance, resolve it. Other function can be safely
    replaced without resolve.

    Change-Id: I0c9a6af29b56b629cbdad2acb868c3033e38b5ef
    Closes-bug: #1494364
    (cherry picked from commit aea59ecdac6ed6635125eb2064554140e3e645fc)

commit 8810a28a9016b3bfa515fc11efd5f5dfa103b380
Author: OpenStack Propos...

Reviewed:  https://review.openstack.org/235237
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=4bf298763005b4b8e0c9c8d64ad7ad0863405b50
Submitter: Jenkins
Branch:    master

commit 4348b7ababd1048e17ec354ca38c903c908cd74e
Author: Steve Baker <sbaker@redhat.com>
Date:   Tue Oct 6 12:54:24 2015 +1300

Do no net/subnet checks during validate
    
    Currently validation fails if the network or the subnet are defined in
    the same template as the server because they don't exist during
    validate.
    
    _validate_belonging_subnet_to_net is called during _build_nics so this
    check still happens when the required resources actually exist.
    
    Also, test method validate_internal_port_subnet_not_this_network was not
    running because its name was not prefixed with test_. Fixing and
    updating this test revealed issues with the validation failed message.
    
    Closes-Bug: #1503060
    Change-Id: I2e062abf5b9fb7446b979ba6acc2e2b531d957d6

commit 7e911cec083e98f344bfcfeb7e2e843ce2330d5d
Author: Pratik Mallya <pratik.mallya@gmail.com>
Date:   Mon Oct 5 00:34:12 2015 -0500

Correctly filter events on resource name
    
    Filtering on resource name can be accomplished by using the db
    filters instead of using a filter method. Furthermore, using a
    custom filter breaks certain assumptions made by other parts of
    the codebase, which lead to pagination being broken.
    Specifically, custom filter for resource name is applied only
    after other filtering is finished. As a result, we try to find
    result from only 1 event and this event belongs to whole
    stack and thus its resource_name is equal to the stack name.
    This returns an event not found error instead of returning
    the first event assosciated with the resource name.
    
    Change-Id: Ie7d28ffb88a79d6e0f516f0db385be2eed59f7f0
    Closes-Bug: #1502751
    (cherry picked from commit 6322ff6fceabdfa226e5359328bde292d189e703)

commit fecc2bacb51c7dabdb83b87313df48dea527feae
Author: Pratik Mallya <pratik.mallya@gmail.com>
Date:   Thu Oct 1 17:41:09 2015 -0500

Check if os-interface extension is present before saving ports
    
    If that extension is not present, then the code to extract and
    save ports created during server create by nova will fail.
    
    Change-Id: I6008a0da0c16a34c40e343af4e7237520db4ae36
    Closes-Bug: #1499877
    (cherry picked from commit 46d8c276b70e7698438988faa9d997577a7e1750)

commit 6c3fa4e25d3e35adf53ad1e80d5455bf9f7a924a
Author: Peter Razumovsky <prazumovsky@mirantis.com>
Date:   Mon Sep 14 17:43:49 2015 +0300

Fix translating for props with get_param value
    
    If some map or list type properties specified with
    json-type or commadelimitedlist parameters, error
    raised in case of wrong properties data parsing.
    Fix this case by adding check if data is GetParam
    instance, resolve it. Other function can be safely
    replaced without resolve.
    
    Change-Id: I0c9a6af29b56b629cbdad2acb868c3033e38b5ef
    Closes-bug: #1494364
    (cherry picked from commit aea59ecdac6ed6635125eb2064554140e3e645fc)

commit 8810a28a9016b3bfa515fc11efd5f5dfa103b380
Author: OpenStack Proposal Bot <openstack-infra@lists.openstack.org>
Date:   Tue Oct 6 06:15:24 2015 +0000

Imported Translations from Zanata
    
    For more information about this automatic import see:
    https://wiki.openstack.org/wiki/Translations/Infrastructure
    
    Change-Id: Icf79f24067aa8a9062c6b4fd1e19508d315f4bad

commit 5c11b54701a62e357e906160f13b7cd300f56889
Author: Zane Bitter <zbitter@redhat.com>
Date:   Thu Oct 1 15:28:53 2015 -0400

Include nested stacks in reset_stack_status
    
    Previously this applied only to top-level stacks.
    
    Change-Id: I958dbbbecf91c1f86c52e90320a07c4a43e54551
    Closes-Bug: #1501828
    (cherry picked from commit 847158aea4ac2e86949c3206b563cfb102e0f148)

commit 4b30adeae16a908e2415d379fbd262e7913d88da
Author: Steven Hardy <shardy@redhat.com>
Date:   Thu Oct 1 17:16:01 2015 +0100

Update preview_update_stack to align with PATCH updates
    
    Currently attempting to do a preview update call with PATCH fails,
    because we didn't align the behavior of preview update with the
    actual update in the recent additions to fix bug #1224828
    
    So, refactor to ensure both preview_update & update use the same
    code, and add a PATCH path to the update API.
    
    Change-Id: I8ce5c0ea4035a7b9563db10ea10433e7f5f99a4f
    Closes-Bug: #1501207
    (cherry picked from commit 604595a39c9345d214f9f02c2ab8d7d1d768fcbe)

commit 182034904f7da306c677e77c880a6266b1b5cd50
Author: Steven Hardy <shardy@redhat.com>
Date:   Thu Sep 24 18:41:34 2015 +0100

Reduce frequency of logging environment resources
    
    Currently we log all template resources every time any API call
    happens which indirectly creates an Environment object, which
    results in a lot of duplicate bloat in the heat logs (not even
    at debug level..)
    
    So, instead log all environment resources (e.g those from resource
    plugins and the global environment) only when we start the
    service, and log user-provided template resources only when we
    do the template validation on create/update, for only the root stack,
    because we pass a derived subset environment down to all children.
    
    We also switch to using the string representation of the ResourceInfo
    objects, as this contains a bit more useful info than the current
    log format.
    
    Change-Id: I20007c1ad6bf8b1479c1d60a5c392b8b9e1c06c4
    Closes-Bug: #1499330
    (cherry picked from commit 5d6234ecf64650b0eb7bd92eb530e899ff061457)

commit 49976fb7bea770b230539b7b23492972666077a3
Author: Rabi Mishra <ramishra@redhat.com>
Date:   Thu Sep 24 12:10:43 2015 +0530

Fix action (CREATE) in progress error for TemplateResource/RG
    
    When StackResource 'update_with_template' is called and there
    is no existing nested_stack, we call create_stack with an empty
    template(TemplateResource CREATE_FAILED->UPDATE flow). We check
    db for CREATE_COMPLETE before calling update_stack.There is a
    possibility that the create_stack green thread has not finished
    and released the stack lock. By persisting the stack state for
    COMPLETE/FAILED in the same db session as releasing the lock,
    when green thread finishes it's run, we can avoid this race
    condition.
    
    Change-Id: I1442a7bcedb4fa340ee4f0e6ebc3705544c2a9dd
    Closes-Bug: #1498495
    (cherry picked from commit e2294da861c24d538cafe1c54d038e2b5d4ba594)

commit c74721943a2c0deac34b345c0b3e6be30595146a
Author: Andreas Jaeger <aj@suse.de>
Date:   Thu Sep 24 21:21:01 2015 +0200

Cleanup of Translations
    
    In preparation for the release, do some cleanups for translations.
    
    Removes all po files that are partially translated. The translation
    team has decided to exclude files with less than 66 % of translated
    content. There is no content lost, all data is in the translation
    server, we just remove it from the repository.
    
    This change needs to be done manually since the automatic import does
    not handle some of these cases.
    
    Change-Id: Iae315c4f9e030637051722b11aefee9543b335bd

commit 3f51a1caebcc64afa06ed779054ed5bbb4e45886
Author: Oleksii Chuprykov <ochuprykov@mirantis.com>
Date:   Thu Sep 24 20:26:51 2015 +0300

Convert to int can cause different error messages
    
    Starting from python3.4.3 casting list to int, i.e. int([]) returns
    exception with another messge. Try to fix.
    
    Co-Authored-By: Pavlo Shchelokovskyy <pshchelokovskyy@mirantis.com>
    Closes-Bug: #1499470
    Change-Id: I2a312a58ed4b722b998a0ba26a8d2b8fcdc99bd6
    (cherry picked from commit 2f2a91d2bb4b84d3ebd4529c236c03c7d19192da)

commit 1879179135a61d73215f4d9caf93b63537c5cab4
Author: Rabi Mishra <ramishra@redhat.com>
Date:   Wed Sep 23 15:00:14 2015 +0530

Add value_specs property for Firewall Resource
    
    FWaaS has added extended attribute to insert routers
    to firewalls. This patch adds support for it with
    value_specs property of  OS::Neutron::Firewall.
    
    To use extended property `router_ids`:
    
    value_specs:
      router_ids:
        - {get_resource: router1}
    
    Change-Id: Ia845e6d11101caccd196a8ea49ee41e3dc7bd0b5
    Closes-Bug: #1498824
    (cherry picked from commit f6cba42301d77c4c8e859d28ee898b944dbb6263)

commit 413f5c1b4d1214901295993d835259fe9a00ad44
Author: Angus Salkeld <asalkeld@mirantis.com>
Date:   Wed Sep 23 11:52:50 2015 +1000

Make sure we can use nova-network
    
    Change-Id: I83a1338882cbba7b65b5b8965bac00a50daee603
    Closes-bug: #1498079
    (cherry picked from commit 3c6912ceaa72f3d6e8edf03a8719abd29154524f)

commit 56bdf9ab63fc91417888d6618c28abcc6d357e41
Author: Steve Baker <sbaker@redhat.com>
Date:   Thu Sep 24 16:00:33 2015 +1200

Update .gitreview for stable/liberty
    
    Change-Id: Idca495bad7aaa5d9306292b276363e9d08ce8c3d

commit 1f6c6d39395702ccfdcd6074d8ff8c49a4add65d
Author: Zane Bitter <zbitter@redhat.com>
Date:   Tue Sep 22 14:59:40 2015 -0400

Only fail Volume deletion in 'error_deleting' state
    
    The volume may have been in the 'error' status before we attempted to
    delete it, and there is no guarantee that it has moved to 'deleting' before
    we query it again. We only want to fail if there is an error *after* we
    call delete, which will put the volume into the 'error_deleting' state. We
    now check for that state explicitly.
    
    Change-Id: I7e205aef46f8dd35fd605eb768a3b05360f4d374
    Closes-Bug: #1496445
    (cherry picked from commit fa22dfb47a5795b04adc16a16950a744c657be29)

Revision history for this message

Steven Hardy (shardy) wrote on 2015-10-21:

This is fixed in heat, I think we can close the TripleO part of this now?

Revision history for this message

Derek Higgins (derekh) wrote on 2015-10-21:

#10

Yes, the issue this was opened against is now gone. thanks.

Changed in tripleo:
status:	Triaged → Fix Released

Revision history for this message

Thierry Carrez (ttx) wrote on 2015-12-03: Fix included in openstack/heat 6.0.0.0b1

#11

This issue was fixed in the openstack/heat 6.0.0.0b1 development milestone.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.