ERROR in h-api log after successful tempest run

[David Kranz]

From http://logs.openstack.org/78/45578/11/check/gate-tempest-devstack-vm-full/a991819/logs/screen-h-api.txt.gz
Seems like some of these are logging an ERROR based on invalid user requests.

2013-09-23 14:23:45.242 25005 DEBUG requests.packages.urllib3.connectionpool [-] "GET /template.template HTTP/1.1" 404 1270 _make_request /usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:296
2013-09-23 14:23:45.244 25005 ERROR root [-] Returning 400 to user: The server could not comply with the request since it is either malformed or otherwise incorrect.
2013-09-23 14:23:45.246 25005 DEBUG root [-] JSON response : {"explanation": "Could not retrieve template: Failed to retrieve template: 404 Client Error: Not Found", "code": 400, "error": {"message": "Could not retrieve template: Failed to retrieve template: 404 Client Error: Not Found", "traceback": " File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 660, in __call__\n request, **action_args)\n File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 729, in dispatch\n return method(*args, **kwargs)\n File \"/opt/stack/new/heat/heat/api/openstack/v1/util.py\", line 30, in handle_stack_method\n return handler(controller, req, **kwargs)\n File \"/opt/stack/new/heat/heat/api/openstack/v1/stacks.py\", line 314, in validate_template\n data.template())\n File \"/opt/stack/new/heat/heat/api/openstack/v1/stacks.py\", line 102, in template\n raise exc.HTTPBadRequest(err_reason)\n", "type": "HTTPBadRequest"}, "title": "Bad Request"} to_json /opt/stack/new/heat/heat/common/wsgi.py:561

2013-09-23 14:26:38.803 25005 DEBUG routes.middleware [-] Matched POST /de9e04cac2c7463188029ef99749ea1b/stacks __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-09-23 14:26:38.803 25005 DEBUG routes.middleware [-] Route path: '/{tenant_id}/stacks', defaults: {'action': u'create', 'controller': <heat.common.wsgi.Resource object at 0x2d27250>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-09-23 14:26:38.803 25005 DEBUG routes.middleware [-] Match dict: {'action': u'create', 'tenant_id': u'de9e04cac2c7463188029ef99749ea1b', 'controller': <heat.common.wsgi.Resource object at 0x2d27250>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-09-23 14:26:38.807 25005 ERROR root [-] Unexpected error occurred serving API: Request limit exceeded: Template exceeds maximum allowed size.
2013-09-23 14:26:38.809 25005 DEBUG root [-] JSON response : {"explanation": "The server could not comply with the request since it is either malformed or otherwise incorrect.", "code": 400, "error": {"message": "Request limit exceeded: Template exceeds maximum allowed size.", "traceback": "Traceback (most recent call last):\n File \"/opt/stack/new/heat/heat/api/middleware/fault.py\", line 125, in process_request\n return req.get_response(self.application)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1296, in send\n application, catch_exc_info=False)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1260, in call_application\n app_iter = application(self.environ, start_response)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 130, in __call__\n resp = self.call_func(req, *args, **self.kwargs)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 195, in call_func\n return self.func(req, *args, **kwargs)\n File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 367, in __call__\n response = req.get_response(self.application)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1296, in send\n application, catch_exc_info=False)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1260, in call_application\n app_iter = application(self.environ, start_response)\n File \"/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py\", line 545, in __call__\n return self.app(env, start_response)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 130, in __call__\n resp = self.call_func(req, *args, **self.kwargs)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 195, in call_func\n return self.func(req, *args, **kwargs)\n File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 367, in __call__\n response = req.get_response(self.application)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1296, in send\n application, catch_exc_info=False)\n File \"/usr/local/lib/python2.7/dist-packages/webob/request.py\", line 1260, in call_application\n app_iter = application(self.environ, start_response)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 144, in __call__\n return resp(environ, start_response)\n File \"/usr/lib/python2.7/dist-packages/routes/middleware.py\", line 131, in __call__\n response = self.app(environ, start_response)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 144, in __call__\n return resp(environ, start_response)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 130, in __call__\n resp = self.call_func(req, *args, **self.kwargs)\n File \"/usr/local/lib/python2.7/dist-packages/webob/dec.py\", line 195, in call_func\n return self.func(req, *args, **kwargs)\n File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 684, in __call__\n raise translate_exception(err, request.best_match_language())\nRequestLimitExceeded: Request limit exceeded: Template exceeds maximum allowed size.\n", "type": "RequestLimitExceeded"}, "title": "Bad Request"} to_json /opt/stack/new/heat/heat/common/wsgi.py:561

2013-09-23 14:26:40.359 25005 ERROR root [-] Unexpected error occurred serving API: The Stack (heat791021814) could not be found.
2013-09-23 14:26:40.359 25005 DEBUG root [-] JSON response : {"explanation": "The resource could not be found.", "code": 404, "error": {"message": "The Stack (heat791021814) could not be found.", "traceback": "Traceback (most recent call last):\n\n File \"/opt/stack/new/heat/heat/openstack/common/rpc/amqp.py\", line 461, in _process_data\n **args)\n\n File \"/opt/stack/new/heat/heat/openstack/common/rpc/dispatcher.py\", line 172, in dispatch\n result = getattr(proxyobj, method)(ctxt, **kwargs)\n\n File \"/opt/stack/new/heat/heat/engine/service.py\", line 59, in wrapped\n return func(self, ctx, *args, **kwargs)\n\n File \"/opt/stack/new/heat/heat/engine/service.py\", line 400, in delete_stack\n st = self._get_stack(cnxt, stack_identity)\n\n File \"/opt/stack/new/heat/heat/engine/service.py\", line 165, in _get_stack\n raise exception.StackNotFound(stack_name=identity.stack_name)\n\nStackNotFound: The Stack (heat791021814) could not be found.\n", "type": "StackNotFound"}, "title": "Not Found"} to_json /opt/stack/new/heat/heat/common/wsgi.py:561

2013-09-23 14:26:43.109 25005 INFO heat.common.urlfetch [-] Fetching data from http://www.example.com/template.yaml
2013-09-23 14:26:43.110 25005 INFO requests.packages.urllib3.connectionpool [-] Starting new HTTP connection (1): www.example.com
2013-09-23 14:26:43.127 25005 DEBUG requests.packages.urllib3.connectionpool [-] "GET /template.yaml HTTP/1.1" 404 1270 _make_request /usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:296
2013-09-23 14:26:43.128 25005 ERROR root [-] Returning 400 to user: The server could not comply with the request since it is either malformed or otherwise incorrect.
2013-09-23 14:26:43.129 25005 DEBUG root [-] JSON response : {"explanation": "Could not retrieve template: Failed to retrieve template: 404 Client Error: Not Found", "code": 400, "error": {"message": "Could not retrieve template: Failed to retrieve template: 404 Client Error: Not Found", "traceback": " File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 660, in __call__\n request, **action_args)\n File \"/opt/stack/new/heat/heat/common/wsgi.py\", line 729, in dispatch\n return method(*args, **kwargs)\n File \"/opt/stack/new/heat/heat/api/openstack/v1/util.py\", line 30, in handle_stack_method\n return handler(controller, req, **kwargs)\n File \"/opt/stack/new/heat/heat/api/openstack/v1/stacks.py\", line 314, in validate_template\n data.template())\n File \"/opt/stack/new/heat/heat/api/openstack/v1/stacks.py\", line 102, in template\n raise exc.HTTPBadRequest(err_reason)\n", "type": "HTTPBadRequest"}, "title": "Bad Request"} to_json /opt/stack/new/heat/heat/common/wsgi.py:561

[Steve Baker (steve-stevebaker)]

Yes, we shouldn't be logging stack traces for errors such as 404s, since any user can trigger them at will.

[Pablo Andres Fuente (pablo-a-fuente)]

So, the idea is to remove the stack trace from 404 errors, but: Should still be logged as errors?

[David Kranz (david-kranz)]

No, they should be logged with DEBUG, if at all. From the standpoint of the cloud operator, this is a normal expected condition. Logs are monitored and an ERROR should be cause for operator investigation/action.

[Pablo Andres Fuente (pablo-a-fuente)]

The same criteria applies to https://bugs.launchpad.net/heat/+bug/1231135?

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/62080
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=7cca4576f09616d6dbf7cec0d5127b04daafd248
Submitter: Jenkins
Branch: master

commit 7cca4576f09616d6dbf7cec0d5127b04daafd248
Author: Pablo Andres Fuente <email address hidden>
Date: Fri Dec 13 16:51:47 2013 -0300

    wsgi.Resource exception handling to not log errors

    In order to not log some exceptions as errors, the
    wsgi.Resource.__call__() was modified.
    Instead of check if an exception is a HTTPBadRequest or a HTTPNotFound,
    now all the exceptions that are not childs of HTTPError are raised
    directly, without logging, translation or disguise.
    If the exception is a child of HeatException, then the exception is
    tranlated but not logged as an error. When this exception reaches the
    Fault Wrapper Middleware it is logged as debug.
    Some unused, or only use in test, exceptions were removed.

    Change-Id: I105eeb74a55dcabc79cd3926dd88da0e19d1e1f1
    Closes-Bug: #1231133

[David Kranz (david-kranz)]

I was going to remove these errors from the whitelist in tempest but according to logstash they are still happening.

[Pablo Andres Fuente (pablo-a-fuente)]

David, could you post here the query that you use in logstash?
I did some searches without any luck (It's the first time that I use logstash)
By the way, I pull the last changes in master and if I reproduce the errors of this bug no ERROR are logged for h-api. If you post the query I will check those logs in order to find why the ERROR are still logged.

[David Kranz (david-kranz)]

Interesting. So the incidence of this dropped by two orders of magnitude since the fix was committed, but it still happens. Here is the logstach querey, run with "All Time" selected:

message:"server could not comply with the request since it is either malformed or" AND filename:"logs/screen-h-api.txt"

[Pablo Andres Fuente (pablo-a-fuente)]

David,
Sorry for the delay (work/vacations/holidays ;) )
It's possible that the builds that still contains ERRORs in logs aren't rebased to include my fix?
I analyzed the logs and I can't figure out why that ERRORs were not be catched.

[David Kranz (david-kranz)]

Unfortunately the log checking was broken for the last few weeks. I hope it will be working soon but a ceilometer issue slipped in. We can recheck this once the log errors are reporting again.

[Pablo Andres Fuente (pablo-a-fuente)]

David,
Clicking on some random hits on logstash.openstack.org, I can see things like this:
    - build_ref: refs/zuul/stable/havana/Zd37fcb3d9ecc4b43be000bfb2917b924
    - build_name: periodic-tempest-dsvm-full-havana
This means that the test was run against havana code? If this is true, maybe this is why there are still ERRORS in h-api logs.

[David Kranz (david-kranz)]

I think you are right. When I looked only in console.html I did not see any hits. The log checker code itself is a no-op in havana so the errors are not copied to the console there.