c-api should not log ERROR tracebacks for 400/409 cases

[Matt Riedemann]

Look at any CI run we have an c-api has a bunch of error traces for 400/409 conditions:

http://logs.openstack.org/78/346278/5/check/gate-tempest-dsvm-neutron-multinode-full/71882bb/logs/screen-c-api.txt.gz?level=TRACE#_2016-08-16_15_23_06_315

e.g.:

2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api Traceback (most recent call last):
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api result = task.execute(**arguments)
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 594, in execute
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api size=size)
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/quota_utils.py", line 280, in process_reserve_over_quota
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api quota=quotas[over])
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api VolumeSizeExceedsAvailableQuota: Requested volume or snapshot exceeds allowed gigabytes quota. Requested 1G, quota is 1G and 1G has been consumed.
2016-08-16 15:22:48.532 25816 ERROR cinder.volume.api

2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api Traceback (most recent call last):
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api result = task.execute(**arguments)
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 594, in execute
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api size=size)
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/quota_utils.py", line 291, in process_reserve_over_quota
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api name=over)
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api VolumeLimitExceeded: Maximum number of volumes allowed (1) exceeded for quota 'volumes'.
2016-08-16 15:22:50.309 25816 ERROR cinder.volume.api

2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api Traceback (most recent call last):
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api result = task.execute(**arguments)
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 392, in execute
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api size = self._extract_size(size, source_volume, snapshot)
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 191, in _extract_size
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api func(size)
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 154, in validate_snap_size
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api raise exception.InvalidInput(reason=msg)
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api InvalidInput: Invalid input received: Volume size '1'GB cannot be smaller than the snapshot size 2GB. They must be >= original snapshot size.
2016-08-16 15:40:24.897 25817 ERROR cinder.volume.api

These shouldn't be logged as errors or tracing, they are user operations that are wrong, hence the 400 or 409 response. Tracing an ERROR should mean something went totally wrong and an operator should be paged.

[Matt Riedemann (mriedem)]

Looks like these are coming from tasks in cinder run via taskflow, and there isn't a way (that we're aware of) to specify expected exceptions so that taskflow doesn't log them as exceptions.

[Matt Riedemann (mriedem)]

Actually, looks like cinder has it's own logger for flow failures, so we should see why this isn't working:

https://github.com/openstack/cinder/blob/master/cinder/flow_utils.py#L60

[Ivan Kolodyazhny (e0ne)]

Matt, thank you for investigation! Unfortunately, Cinder's DynamicLogListener [1] uses private taskflow API which is dropped in the current release, so that code is not executed at all:(. I'm going to continue investigation on this issue.

[1] https://github.com/openstack/cinder/blob/master/cinder/flow_utils.py#L60

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ivan Kolodyazhny (<email address hidden>) on branch: master
Review: https://review.openstack.org/364887
Reason: I9bb4a690759974206bbd95ae53339ab302b1db5a has a better fix

[Sean McGinnis (sean-mcginnis)]

Addressed by https://review.openstack.org/#/c/412819/