Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1625599

Summary: Usage of webob library produces excessive logging into journal
Product: Red Hat OpenStack Reporter: Marian Krcmarik <mkrcmari>
Component: python-wsmeAssignee: Cyril Roelandt <cyril>
Status: CLOSED ERRATA QA Contact: Mike Abrams <mabrams>
Severity: high Docs Contact:
Priority: high    
Version: 14.0 (Rocky)CC: akekane, ccopello, cschwede, cyril, dbecker, eglynn, ekuvaja, mabrams, mburns, michele, michele, mkrcmari, morazi, pgrist, scohen, slinaber, tshefi
Target Milestone: z3Keywords: Triaged, ZStream
Target Release: 14.0 (Rocky)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: python-wsme-0.9.4-0.20190508170502.bff9624.el7ost Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-07-02 20:09:55 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1700503    
Bug Blocks:    

Description Marian Krcmarik 2018-09-05 10:34:31 UTC
Description of problem:
There is excessive logging in journal on controller nodes produced by usage of webob library. The following msgs are repeatedly logged:
Sep  2 03:47:02 controller-0 journal: /usr/lib/python2.7/site-packages/webob/acceptparse.py:1297: DeprecationWarning: The behavior of .best_match for the Accept classes is currently being maintained for backward compatibility, but the method will be deprecated in the future, as its behavior is not specified in (and currently does not conform to) RFC 7231.
Sep  2 03:47:02 controller-0 journal:  DeprecationWarning,

Some example stats from a controller node:
# egrep "DeprecationWarning|RFC 7231" /var/log/messages* | wc -l
938731

# grep "messages lost" /var/log/messages
Sep  2 14:43:43 controller-0 rsyslogd: imjournal: 3413247 messages lost due to rate-limiting
Sep  2 16:35:13 controller-0 rsyslogd: imjournal: 3375525 messages lost due to rate-limiting
Sep  2 17:02:47 controller-0 rsyslogd: imjournal: 3414885 messages lost due to rate-limiting
Sep  2 19:39:17 controller-0 rsyslogd: imjournal: 3342066 messages lost due to rate-limiting
Sep  2 20:04:27 controller-0 rsyslogd: imjournal: 3376243 messages lost due to rate-limiting
Sep  2 23:58:30 controller-0 rsyslogd: imjournal: 3402944 messages lost due to rate-limiting
Sep  3 00:29:44 controller-0 rsyslogd: imjournal: 3437032 messages lost due to rate-limiting
Sep  3 01:19:31 controller-0 rsyslogd: imjournal: 3398808 messages lost due to rate-limiting
Sep  3 02:26:22 controller-0 rsyslogd: imjournal: 3393892 messages lost due to rate-limiting
Sep  3 03:28:10 controller-0 rsyslogd: imjournal: 3401810 messages lost due to rate-limiting
Sep  3 11:44:06 controller-0 rsyslogd: imjournal: 3336303 messages lost due to rate-limiting
Sep  3 14:14:53 controller-0 rsyslogd: imjournal: 3485740 messages lost due to rate-limiting
Sep  3 15:06:27 controller-0 rsyslogd: imjournal: 3522480 messages lost due to rate-limiting
Sep  3 16:31:58 controller-0 rsyslogd: imjournal: 3577710 messages lost due to rate-limiting
Sep  3 17:07:16 controller-0 rsyslogd: imjournal: 3609689 messages lost due to rate-limiting
Sep  3 18:16:17 controller-0 rsyslogd: imjournal: 3667087 messages lost due to rate-limiting
Sep  3 21:08:44 controller-0 rsyslogd: imjournal: 3683133 messages lost due to rate-limiting
Sep  4 00:10:05 controller-0 rsyslogd: imjournal: 3661936 messages lost due to rate-limiting
Sep  4 11:21:28 controller-0 rsyslogd: imjournal: 3678981 messages lost due to rate-limiting
Sep  4 12:25:46 controller-0 rsyslogd: imjournal: 3707254 messages lost due to rate-limiting
Sep  4 13:30:42 controller-0 rsyslogd: imjournal: 3649744 messages lost due to rate-limiting
Sep  4 20:37:54 controller-0 rsyslogd: imjournal: 3773164 messages lost due to rate-limiting
Sep  4 21:29:23 controller-0 rsyslogd: imjournal: 3692669 messages lost due to rate-limiting
Sep  4 23:07:22 controller-0 rsyslogd: imjournal: 3829729 messages lost due to rate-limiting

Version-Release number of selected component (if applicable):
OSP14
python2-webob-1.8.1-1.el7ost.noarch

How reproducible:
Always

Steps to Reproduce:
1. Just install OSP14 and check the logs for msgs mentioned above
2.
3.

Actual results:
Hundred of thousands msgs in a day

Expected results:


Additional info:
I am not sure about the right component, investigation is ongoing, it could be more component involved or not.

Comment 1 Michele Baldessari 2018-09-05 10:47:38 UTC
So far we've observed this only on glance_api docker logs (most of the messages) and some in cinder-api logs in /var/log/containers/httpd/cinder-api/*wsgi*error*log

Comment 3 Christian Schwede (cschwede) 2018-09-05 13:53:26 UTC
There is some related work done upstream: https://bugs.launchpad.net/openstack-requirements/+bug/1765748

Comment 4 Cyril Roelandt 2018-09-05 21:21:14 UTC
So basically, https://review.openstack.org/#/c/564883/ fixes the issue, right? It will be part of one of the next OSP14 builds, so this issue should disappear.

Comment 5 Marian Krcmarik 2018-09-05 21:26:39 UTC
(In reply to Cyril Roelandt from comment #4)
> So basically, https://review.openstack.org/#/c/564883/ fixes the issue,
> right? It will be part of one of the next OSP14 builds, so this issue should
> disappear.

I believe so, at least for the glance which seems to be the main producer of the msgs.

Comment 6 Michele Baldessari 2018-09-06 05:43:31 UTC
(In reply to Cyril Roelandt from comment #4)
> So basically, https://review.openstack.org/#/c/564883/ fixes the issue,
> right? It will be part of one of the next OSP14 builds, so this issue should
> disappear.

I thought that code is already there:
()[glance@controller-0 /]$ python
Python 2.7.5 (default, May 31 2018, 09:41:32) 
[GCC 4.8.5 20150623 (Red Hat 4.8.5-28)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> try:
...     from webob.acceptparse import AcceptLanguageValidHeader  # noqa
...     USING_WEBOB_1_8 = True
... except ImportError:
...     USING_WEBOB_1_8 = False
... 
>>> print USING_WEBOB_1_8
True
>>> 

So we are taking the def _best_match_language_1_8() branch of https://review.openstack.org/#/c/564883/1/glance/common/wsgi.py, but we are still logging a truckload of messages. Or am I looking at thing incorrectly?

Comment 7 Marian Krcmarik 2018-09-06 10:34:39 UTC
(In reply to Michele Baldessari from comment #6)
> (In reply to Cyril Roelandt from comment #4)
> > So basically, https://review.openstack.org/#/c/564883/ fixes the issue,
> > right? It will be part of one of the next OSP14 builds, so this issue should
> > disappear.
> 
> I thought that code is already there:
> ()[glance@controller-0 /]$ python
> Python 2.7.5 (default, May 31 2018, 09:41:32) 
> [GCC 4.8.5 20150623 (Red Hat 4.8.5-28)] on linux2
> Type "help", "copyright", "credits" or "license" for more information.
> >>> try:
> ...     from webob.acceptparse import AcceptLanguageValidHeader  # noqa
> ...     USING_WEBOB_1_8 = True
> ... except ImportError:
> ...     USING_WEBOB_1_8 = False
> ... 
> >>> print USING_WEBOB_1_8
> True
> >>> 
> 
> So we are taking the def _best_match_language_1_8() branch of
> https://review.openstack.org/#/c/564883/1/glance/common/wsgi.py, but we are
> still logging a truckload of messages. Or am I looking at thing incorrectly?

Michele is completely right about that, The code is already in downstream. It seem that there is one more usage of "old" best_match() method in:
    def best_match_content_type(self):
        """Determine the requested response content-type."""
        supported = ('application/json',)
        bm = self.accept.best_match(supported)
        return bm or 'application/json'
?

Comment 11 Cyril Roelandt 2018-09-18 18:41:19 UTC
I just sent a patch upstream, let's see how this goes.

Comment 12 Christian Schwede (cschwede) 2018-10-30 09:19:20 UTC
Upstream patch merged on master, proposed backport to Rocky.

Comment 22 Cyril Roelandt 2019-02-26 16:34:20 UTC
Hey Mike,

I asked Steve on IRC, and it should be in z1 (2019-02-22.2).

Comment 23 Tzach Shefi 2019-02-26 19:44:46 UTC
I suspect no luck,
Just finished installing a "latest" which produced the z1 build date/puddle:

$ cat /etc/yum.repos.d/latest-installed 
14   -p 2019-02-22.2

However the resulting version is still below fixed-in
openstack-glance-17.0.1-0.20180924181829.afc0ceb.el7ost.noarch

Comment 25 Tzach Shefi 2019-02-27 13:12:39 UTC
Mike has lunched another "latest" deployment today (Fed 27),
resulting in same puddle as #24 above -> 14 -p 2019-02-22.2

openstack-glance-17.0.1-0.20180924181829.afc0ceb.el7ost.noarch < fixed-in

Still can't verify, waiting for newer puddle to recheck.

Comment 31 Cyril Roelandt 2019-03-07 15:05:11 UTC
@Mike: can I ssh the machine?

Comment 38 Cyril Roelandt 2019-03-12 19:19:10 UTC
@Mike: I managed to get to the Docker container this morning, but now I seem to be running into a network issue:

[root@titan34 ~]# ssh stack@undercloud-0
$ source overcloudrc
(overcloud) [stack@undercloud-0 ~]$ ssh -t heat-admin.24.13
ssh: connect to host 192.168.24.13 port 22: No route to host
$

Is there something wrong with the machine?

Thanks.

Comment 41 Cyril Roelandt 2019-03-21 20:52:38 UTC
So, looking at the places where best_match is used:

> ()[glance@controller-0 /usr/lib/python2.7/site-packages]$ grep -rl "\.best_match("
> pkg_resources.py
> glance/common/wsgi.py
> wsme/protocol.py
> wsme/rest/protocol.py
> wsme/root.py
> jsonschema/tests/test_exceptions.py
> oslo_middleware/healthcheck/__init__.py
> webob/acceptparse.py


pkg_resources.py                            -> Unrelated
glance/common/wsgi.py                       -> fixed by a Glance patch
wsme/protocol.py                            -> Patch under review upstream
wsme/rest/protocol.py                       -> Same as above
wsme/root.py                                -> Same as above
jsonschema/tests/test_exceptions.py         -> Tests, should not be called
oslo_middleware/healthcheck/__init__.py     -> Patch under review upstream
webob/acceptparse.py                        -> Webob itself, we don't mind

We need to merge a bunch of patches upstream, backport them and get new puddles that include the fixes.

Comment 42 Cyril Roelandt 2019-06-05 18:47:22 UTC
python-wsme python-wsme-0.9.4-0.20190508170502.bff9624.el7ost should contain the python-wsme fix.

Comment 47 errata-xmlrpc 2019-07-02 20:09:55 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:1671