Bug 1441721 - ERROR in the log when authentication session expires while catching RHV events
Summary: ERROR in the log when authentication session expires while catching RHV events
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Providers
Version: 5.7.0
Hardware: All
OS: All
medium
low
Target Milestone: GA
: 5.9.0
Assignee: Juan Hernández
QA Contact: Radim Hrazdil
URL:
Whiteboard: appliance:database
Depends On: 1490091
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-04-12 14:32 UTC by Ryan Spagnola
Modified: 2020-09-10 10:28 UTC (History)
12 users (show)

Fixed In Version: 5.9.0.1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-03-01 13:11:36 UTC
Category: ---
Cloudforms Team: RHEVM
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
current evm.log (8.03 MB, text/plain)
2017-04-12 14:32 UTC, Ryan Spagnola
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2018:0380 0 normal SHIPPED_LIVE Moderate: Red Hat CloudForms security, bug fix, and enhancement update 2018-03-01 18:37:12 UTC

Description Ryan Spagnola 2017-04-12 14:32:56 UTC
Created attachment 1271170 [details]
current evm.log

Description of problem:
After correcting the /api path in the database events are not working

[----] E, [2017-04-10T08:47:54.203500 #16372:1661088] ERROR -- : <RHEVM> Ovirt::Service#parse_error_response Return from URL: <https://itb-pt-virt-rhevm-1.beta.pt-virt.uspto.gov/ovirt-engine/api/events?from=27586> Data:<html><head><title>Error</title></head><body>Unauthorized</body></html>


Version-Release number of selected component (if applicable):
RHV 4.0
CF 4.2

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 2 Dave Johnson 2017-07-14 02:50:17 UTC
Please assess the impact of this issue and update the severity accordingly.  Please refer to https://bugzilla.redhat.com/page.cgi?id=fields.html#bug_severity for a reminder on each severity's definition.

If it's something like a tracker bug where it doesn't matter, please set it to Low/Low.

Comment 3 Dave Johnson 2017-07-26 00:28:03 UTC
Please assess the impact of this issue and update the severity accordingly.  Please refer to https://bugzilla.redhat.com/page.cgi?id=fields.html#bug_severity for a reminder on each severity's definition.

If it's something like a tracker bug where it doesn't matter, please set it to Low/Low.

Comment 4 Dave Johnson 2017-08-01 06:09:20 UTC
Please assess the impact of this issue and update the severity accordingly.  Please refer to https://bugzilla.redhat.com/page.cgi?id=fields.html#bug_severity for a reminder on each severity's definition.

If it's something like a tracker bug where it doesn't matter, please set it to Low/Low.

Comment 5 Tasos Papaioannou 2017-08-11 18:28:47 UTC
The attach evm.log shows that these errors occur every 30 minutes. I see this as well on CFME 5.8 with both RHEV 3.6 and RHV 4.0. /var/www/miq/vmdb/log/rhevm.log shows that it successfully connects to the RHEV manager before and after these errors:

****
[----] I, [2017-08-11T13:29:32.170800 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122669>
[----] I, [2017-08-11T13:29:32.323222 #7809:16ffcec]  INFO -- : Ovirt::Service#parse_normal_response: Return from URL: <https://rhevm.example.com/api/events?from=3122669> Data length:66
[----] I, [2017-08-11T13:29:47.324365 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122669>
[----] E, [2017-08-11T13:29:47.479863 #7809:16ffcec] ERROR -- : Ovirt::Service#parse_error_response Return from URL: <https://rhevm.example.com/api/events?from=3122669> Data:<html><head>
<title>JBWEB000065: HTTP Status 401 - </title><style><!--H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}HR {color : #525D76;}--></style> </head><body><h1>JBWEB000065: HTTP Status 401 - </h1><HR size="1" noshade="noshade"><p><b>JBWEB000309: type</b> JBWEB000067: Status report</p><p><b>JBWEB000068: message</b> <u></u></p><p><b>
JBWEB000069: description</b> <u>JBWEB000121: This request requires HTTP authentication.</u></p><HR size="1" noshade="noshade"></body></html>
[----] I, [2017-08-11T13:29:47.480300 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122669>
[----] I, [2017-08-11T13:29:47.722632 #7809:16ffcec]  INFO -- : Ovirt::Service#parse_normal_response: Return from URL: <https://rhevm.example.com/api/events?from=3122669> Data length:531
[----] I, [2017-08-11T13:30:02.725482 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122670>
[----] I, [2017-08-11T13:30:02.879546 #7809:16ffcec]  INFO -- : Ovirt::Service#parse_normal_response: Return from URL: <https://rhevm.example.com/api/events?from=3122670> Data length:66

[snip]

[----] I, [2017-08-11T14:00:38.207610 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122676>
[----] I, [2017-08-11T14:00:38.361387 #7809:16ffcec]  INFO -- : Ovirt::Service#parse_normal_response: Return from URL: <https://rhevm.example.com/api/events?from=3122676> Data length:66
[----] I, [2017-08-11T14:00:53.362658 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122676>
[----] E, [2017-08-11T14:00:53.756589 #7809:16ffcec] ERROR -- : Ovirt::Service#parse_error_response Return from URL: <https://rhevm.example.com/api/events?from=3122676> Data:<html><head>
<title>JBWEB000065: HTTP Status 401 - </title><style><!--H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}HR {color : #525D76;}--></style> </head><body><h1>JBWEB000065: HTTP Status 401 - </h1><HR size="1" noshade="noshade"><p><b>JBWEB000309: type</b> JBWEB000067: Status report</p><p><b>JBWEB000068: message</b> <u></u></p><p><b>JBWEB000069: description</b> <u>JBWEB000121: This request requires HTTP authentication.</u></p><HR size="1" noshade="noshade"></body></html>
[----] I, [2017-08-11T14:00:53.757458 #7809:16ffcec]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://rhevm.example.com/api/events?from=3122676>
****

The default session timeout on the RHEV manager is 30 minutes:

# engine-config -a | grep -i session
UserSessionTimeOutInterval: 30 version: general

So, every 30 minutes the appliance gets a 401 Unauthorized return code because the session has expired, and successfully re-authenticates. If it re-authenticates successfully, it should probably suppress these errors from the logs.

Comment 10 Dave Johnson 2017-08-30 14:24:22 UTC
Tasos, so the original write up is events are not making their way into CF and thus, CF is out of date to the reality on the provider, is that the case.  

How large of a window are we not able to receive events because the session has timed out as this sounds serious and I would say is a 5.8.2 blocker if event support is broken for portions of any given hour.

Comment 11 Tasos Papaioannou 2017-08-30 16:25:57 UTC
In my testing, there is no sign of missed events when these Unauthorized errors occur.

rhevm.log shows that the next successful api call, which completes less than 1 second after the error, uses the same value in "/api/events?from=<value>", so it doesn't lose track of what the last event was. 

****
[----] I, [2017-08-30T11:41:32.670308 #2610:1a0912c]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://server.example.com
/ovirt-engine/api/events?from=66454>
[----] E, [2017-08-30T11:41:33.469816 #2610:1a0912c] ERROR -- : Ovirt::Service#parse_error_response Return from URL: <https://server.example.com/ovirt-engine/api/events?from=66454> Data:<html><head><title>Error</title></head><body>Unauthorized</body></html>
[----] I, [2017-08-30T11:41:33.470336 #2610:1a0912c]  INFO -- : Ovirt::Service#resource_get: Sending URL: <https://server.example.com
/ovirt-engine/api/events?from=66454>
[----] I, [2017-08-30T11:41:34.344591 #2610:1a0912c]  INFO -- : Ovirt::Service#parse_normal_response: Return from URL: <https://server.example.com/ovirt-engine/api/events?from=66454> Data length:66
****

There's no rhevm.log or other info from the original reporter to indicate that events are not getting stored in CF. Based on the fact that the Unauthorized errors only appear once every 30 minutes in the attached evm.log, it looks like the same issue I described above.

Comment 14 Juan Hernández 2017-09-07 18:58:56 UTC
This ERROR in the log is expected and doesn't have any negative impact, other than the annoying/worrying message.

The error message only appears when using version 3 of the RHV API via the 'ovirt' gem. In the near future it will be possible to use version 4 of the RHV API, via the 'ovirt-engine-sdk' gem, which doesn't have this behaviour. It will be a matter of changing a setting:

  :ems:
    :ems_redhat:
      :use_ovirt_engine_sdk: false

Currently the default value is 'false' and we don't support changing it to 'true', but we will support changing it very soon. Once we support that the user will be able to change this setting and the problem will be solved.

Oved, is there a bug tracking the support for using the SDK by default? I think we can either close this bug as a duplicate or that bug, or else target this bug for the same version. Anyhow, this bug doesn't need any additinal change in the software.

Comment 15 Oved Ourfali 2017-09-10 06:21:00 UTC
It will be fixed in 5.9.0 when working with RHV v4 and above.

Comment 18 Radim Hrazdil 2017-11-27 16:34:11 UTC
Verified ovirt_engine_sdk is set to be used by default. Verified in evm.log OvirtSDK4 is used.
5.9.0.10

Comment 21 errata-xmlrpc 2018-03-01 13:11:36 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/RHSA-2018:0380


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