Red Hat Bugzilla – Bug 1441721
ERROR in the log when authentication session expires while catching RHV events
Last modified: 2018-03-01 08:11:36 EST
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:
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.
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.
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.
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.
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.
It will be fixed in 5.9.0 when working with RHV v4 and above.
Verified ovirt_engine_sdk is set to be used by default. Verified in evm.log OvirtSDK4 is used. 5.9.0.10
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