Bug 890165 - ovirt-engine-backend: server.log is flooded by apache messages :'[org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-6) Cookies: Invalid cookie. Value not a token or quoted value'
ovirt-engine-backend: server.log is flooded by apache messages :'[org.apache....
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
x86_64 Linux
medium Severity high
: ---
: 3.2.0
Assigned To: Juan Hernández
Pavel Stehlik
infra
:
Depends On:
Blocks: 915537
  Show dependency treegraph
 
Reported: 2012-12-25 07:43 EST by Omri Hochman
Modified: 2016-02-10 14:34 EST (History)
11 users (show)

See Also:
Fixed In Version: sf4
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
server.log (175.79 KB, application/octet-stream)
2012-12-25 07:43 EST, Omri Hochman
no flags Details
tcpdump (51.43 KB, application/octet-stream)
2013-01-01 05:32 EST, Omri Hochman
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 10877 None None None Never

  None (edit)
Description Omri Hochman 2012-12-25 07:43:09 EST
Created attachment 668900 [details]
server.log

ovirt-engine-backend: server.log is flooded by apache messages :'[org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-6) Cookies: Invalid cookie. Value not a token or quoted value'


server.log:
***********
2012-12-25 09:15:13,304 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-3) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,374 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-13) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,375 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-6) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,385 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-1) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,409 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-10) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,409 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-4) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,410 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-3) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:13,410 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-11) Cookies: Invalid cookie. Value not a token or quoted value
2012-12-25 09:15:14,729 INFO  [org.apache.tomcat.util.http.Cookies] (ajp-/127.0.0.1:8702-9) Cookies: Invalid cookie. Value not a token or quoted value
Comment 3 Juan Hernández 2012-12-25 09:21:29 EST
Yaniv Dary found this same issue some time ago with the reports application. He solved it adding the following to /etc/sysconfig/ovirt-engine as part of the reports setup:

ENGINE_PROPERTIES=-Dorg.apache.tomcat.util.http.ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0=true

Omri, do you have the reports application deployed in that environment? Does /etc/sysconfig/ovirt-engine contain this property? If it doesn't, can you add this manually and see if you still get the messages?

If that solves the problem then we could add this property in the engine start script by default. However I would like to understand which cookie is malformed. Omri, would it be possible to get a dump of the traffic going to the 8702 port of the engine when this is happening?
Comment 4 Yaniv Dary 2012-12-26 08:03:28 EST
Jasper just offered a possible cause to this issue on the reports side:
" The problem may be caused by incorrect JBoss configuration and JRS gets freaked out by forward slashes. JBoss 7 sets the session cookie path wrapped in quotes, Firefox treats the quotes as part of the path itself so it never sends session cookie info in requests which causes a new session to created on each request.

Can you please tell me what values do these configuration properties have in your JBoss?
org.apache.tomcat.util.http.ServerCookie.FWD_SLASH_IS_SEPARATOR
org.apache.catalina.STRICT_SERVLET_COMPLIANCE"
Comment 5 Yaniv Dary 2012-12-26 08:18:28 EST
I looked and saw "STRICT_SERVLET_COMPLIANC" was changed to true by default due to:
http://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2007-5333



Yaniv
Comment 6 Yaniv Dary 2012-12-26 08:20:17 EST
Also see thread:
https://community.jboss.org/thread/205264



Yaniv
Comment 7 Omri Hochman 2013-01-01 05:30:47 EST
(In reply to comment #3)
> Yaniv Dary found this same issue some time ago with the reports application.
> He solved it adding the following to /etc/sysconfig/ovirt-engine as part of
> the reports setup:
> 
> ENGINE_PROPERTIES=-Dorg.apache.tomcat.util.http.ServerCookie.
> ALLOW_HTTP_SEPARATORS_IN_V0=true
> 
> Omri, do you have the reports application deployed in that environment?
No reports installed, I saw it happens on both RHEVM 3.1 Build SI25.2 And RHEVM 3.2 Build SF2.1. 
 
> Does /etc/sysconfig/ovirt-engine contain this property? 
It's Not there by default.

> If it doesn't, can you add this manually and see if you still get the messages?
After adding the property - it stopped the flood of messages in server.log  

> If that solves the problem then we could add this property in the engine
> start script by default. However I would like to understand which cookie is
> malformed. Omri, would it be possible to get a dump of the traffic going to
> the 8702 port of the engine when this is happening?
attached  tcpdump
Comment 8 Omri Hochman 2013-01-01 05:32:00 EST
Created attachment 670936 [details]
tcpdump
Comment 9 Juan Hernández 2013-01-09 12:12:48 EST
Looking at the dump I see some requests where the cookie header is like this (package number 66 in the dump):

  JSESSIONID=LXih-by6n9nT7zTAPFu3kEqH; s_vi=[CS]v1|265EC9D5851D2BB2-6000010C800014AA[CE]; ...

(There are many other cookies in the request, but I omitted them)

The JSESSIONID cookie is expected and normal, and doesn't contain any problematic character. But the s_vi cookie is not expected, and it does contain characters that JBoss doesn't allow by default in cookies, in particular the square brackets, thus the message in the log.

Why is your browser sending those cookies to the engine? It looks like those cookies are used by a product from Adobe called "Omniture SiteCatalyst", so I guess that in the past you used the same browser to connect to a server with the same host name or IP address and with that product installed, thus the browser is sending the cookies back.

I would suggest to double check this connecting to the engine after cleaning the cookies in the browser. If the warning goes away then I think that it is safe to leave things as they are, without modifying anything in the engine.
Comment 10 Yaniv Dary 2013-01-09 16:58:12 EST
Also got a reply from jasper on this:
"I believe I have found the problem cookie.

According to RFC 6265, which defines the cookie standard, there are certain special characters not allowed in the cookie value. They are white-space characters, double quote, comma, semicolon and backslash.

In the cookies.txt file you attached to the case there are three cookies coming from JRS:

dbotzer-installation.qa.lab.tlv.redhat.com	FALSE	/rhevm-reports/	FALSE	1355997920	userLocale	en_US
dbotzer-installation.qa.lab.tlv.redhat.com	FALSE	/rhevm-reports/	FALSE	1355997920	userTimezone	Asia/Jerusalem
dbotzer-installation.qa.lab.tlv.redhat.com	FALSE	/rhevm-reports	TRUE	0	JSESSIONID	Qwxn8GXRZi9RiCVUr3qoxOLZ

and the cookie values are all within the specs. 

There are 18 other cookies coming from either www.redhat.com or .redhat.com. I'm not sure why these cookies are in your environment but they do not exist in our VM, which is why we don't see the INFO messages. The following cookie has invalid white-space characters, %20, which is hex for 'space.'

.redhat.com	TRUE	/	FALSE	0	s_ria	flash%2011%7Csilverlight%20not%20detected

The value translates to, "flash 11|silverlight not, detected," which has three invalid white-space characters. I'm quite certain that this is the one causing the messages to be generated."


What do you think?
Comment 11 Yaniv Dary 2013-01-09 17:12:54 EST
I must also add that also got "s_vi	[CS]v1|276478C8851D3686-40000142E012B9DF[CE]" in the cookies. This doesn't recreate on the jasper side on a vm with rhev and reports.
Comment 12 Juan Hernández 2013-01-10 04:10:30 EST
I think that the jasper team analysis is correct, and probably the s_ria cookie is generated by the same software than the s_vi cookie.

We can handle this in three different ways:

1. Do nothing, expecting that users will not be sending this cookies to their RHEV-M installations.

2. Add the ALLOW_HTTP_SEPARATORS_IN_V0 option by default (see comment #3) so that the cookies will be accepted without sending messages to the log.

3. Configure the logging subsystem so that it will suppress the log messages from the org.apache.tomcat.util.http.Cookies class.
Comment 13 Yaniv Dary 2013-01-10 04:18:47 EST
BTW this cookie types are sent by by Adobe SiteCatalyst to anonymously track visitor activity in the red hat domain.
Comment 14 Juan Hernández 2013-01-10 11:02:08 EST
This is how to reproduce the issue (including the blank line and the line with only a dot):

openssl s_client -connect f17.example.com:443 <<'.'
GET / HTTP/1.1
Host: f17.example.com
Connection: close
Cookie: broken=[whatever]

.


Replace f17.example.com with the address of your engine.
Comment 15 Juan Hernández 2013-01-10 11:12:48 EST
The following patch changes the logging configuration so that the message informing about the problem with the cookies is discarded:

http://gerrit.ovirt.org/10877
Comment 16 Yair Zaslavsky 2013-01-21 06:02:19 EST
Setting to MODIFIED as was merged upstream prior to last rebase
Comment 18 Itamar Heim 2013-06-11 05:10:11 EDT
3.2 has been released
Comment 19 Itamar Heim 2013-06-11 05:10:18 EDT
3.2 has been released
Comment 20 Itamar Heim 2013-06-11 05:37:55 EDT
3.2 has been released

Note You need to log in before you can comment on or make changes to this bug.