Bug 1468965 - Event log and engine spammed with 'User admin@internal-authz logged in/out' info messages
Event log and engine spammed with 'User admin@internal-authz logged in/out' i...
Status: CLOSED CURRENTRELEASE
Product: ovirt-engine
Classification: oVirt
Component: BLL.Infra (Show other bugs)
4.2.0
x86_64 Linux
unspecified Severity medium (vote)
: ovirt-4.2.0
: 4.2.0
Assigned To: Ravi Nori
Pavel Novotny
:
Depends On:
Blocks: 1512490
  Show dependency treegraph
 
Reported: 2017-07-10 02:07 EDT by Michael Burman
Modified: 2017-12-20 06:04 EST (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: Enhancement
Doc Text:
Feature: All audit log messages around login or logout now contains not only username, but also IP address of the client which user is connecting from and ID of a session (if exists) to be able to distinguish between several connection from a single client. Reason: Result:
Story Points: ---
Clone Of:
: 1512490 (view as bug list)
Environment:
Last Closed: 2017-12-20 06:04:38 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rule-engine: ovirt‑4.2+


Attachments (Terms of Use)
engine log (76.46 KB, application/x-gzip)
2017-07-10 02:07 EDT, Michael Burman
no flags Details
screenshot (139.26 KB, image/png)
2017-07-10 02:09 EDT, Michael Burman
no flags Details
/var/log/httpd/ssl_access_log (23.02 KB, application/x-gzip)
2017-07-10 04:30 EDT, Michael Burman
no flags Details
screen: enhanced login/logout event messages (106.18 KB, image/png)
2017-10-30 11:44 EDT, Pavel Novotny
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 80669 master POST aaa: Event log and engine spammed with logout message 2017-08-16 10:51 EDT

  None (edit)
Description Michael Burman 2017-07-10 02:07:57 EDT
Created attachment 1295704 [details]
engine log

Description of problem:
Event log and engine spammed with 'User admin@internal-authz logged in/out' info messages.

The event log ui and engine log are spammed with info event messages about user admin logged in and out every 20 to 50 minutes. 
The events are followed as 3 messages about user admin logged in then 3 messages  as user admin logged out.

The messages appears when no user admin was logged in the session.
Something triggers those messages info events, not sure what.

Version-Release number of selected component (if applicable):
4.1.4-0.2.el7

How reproducible:
100% on 4.1.4-0.2.el7

Steps to Reproduce:
1. Just log in the webadmin and check the log event ui or check for engine log
Comment 1 Michael Burman 2017-07-10 02:09 EDT
Created attachment 1295705 [details]
screenshot
Comment 2 Michael Burman 2017-07-10 02:10:40 EDT
I see this behaviour on the latest master as well - 4.2.0-0.0.master.20170709165327.gitfd2334b.el7.centos
Comment 3 Michael Burman 2017-07-10 03:46:20 EDT
Thinking about it, those rhv-m engines are running in CFME(5.8.1) as 'Infrastructure Providers', so maybe it now make sense from where all of those log in and out messages event are coming, the question is this is expected? 

Is something like that is expected - 
Jul 10, 2017, 8:23:09 AM User admin@internal-authz logged out.
Jul 10, 2017, 8:23:09 AM User admin@internal-authz logged out.
Jul 10, 2017, 8:23:08 AM User admin@internal-authz logged out.

Jul 10, 2017, 8:05:52 AM User admin@internal-authz logged out.
Jul 10, 2017, 8:05:52 AM User admin@internal-authz logged out.
Jul 10, 2017, 8:05:52 AM User admin@internal-authz logged out.
Comment 4 Oved Ourfali 2017-07-10 03:51:45 EDT
As part of the provider work we do login/logout.
We do use the same session for some cases, but not for all of them.

Juan - I guess that is expected, but please take a look and let me know whether I'm wrong.
Comment 5 Michael Burman 2017-07-10 04:12:05 EDT
(In reply to Oved Ourfali from comment #4)
> As part of the provider work we do login/logout.
> We do use the same session for some cases, but not for all of them.
> 
> Juan - I guess that is expected, but please take a look and let me know
> whether I'm wrong.

I guess as well, but i don't think that the same event should be printed 3 times for log in and 3 times for log out(it's confusing).
Comment 6 Juan Hernández 2017-07-10 04:21:44 EDT
It is not the same event printed three times, but three different events. The reason is probably the CFME provider is logging in multiple times instead of reusing the authentication session.

Michael, can you please check the /var/log/httpd/ssl_access_log file corresponding to the time of those events? It should reflect the API activity, and will help us determine if those events are really triggered by CFME.
Comment 8 Michael Burman 2017-07-10 04:30 EDT
Created attachment 1295727 [details]
/var/log/httpd/ssl_access_log
Comment 9 Martin Perina 2017-07-10 04:35:56 EDT
(In reply to Michael Burman from comment #5)
> (In reply to Oved Ourfali from comment #4)
> > As part of the provider work we do login/logout.
> > We do use the same session for some cases, but not for all of them.
> > 
> > Juan - I guess that is expected, but please take a look and let me know
> > whether I'm wrong.
> 
> I guess as well, but i don't think that the same event should be printed 3
> times for log in and 3 times for log out(it's confusing).

AFAIK we don't print the same message 3 times, so most probably it's 3 different sessions for the same user.

We show client IP or database session id inside Sessions tab in webadmin, so we could probably add more info about each logged-out session (maybe some unique session ID which could be visible in both webadmin and logs). Ravi, what do you think?
Comment 10 Juan Hernández 2017-07-10 06:11:58 EDT
Looking at the logs I see that all the API access come from the same IP address, and the requests match what CFME does.

A normal installation of CFME creates three different workers to handle the integration with RHV:

* One worker that performs the inventory refresh.
* One worker that catches events.
* One worker that collects metrics.

In the CFME architecture each of these workers is a separate Ruby process.

The 'ovirt' Ruby gem that we currently use to talk to RHV stores in a global variable the authentication session id, and renews it when it expires in the RHV side. Processes don't share global variables. This means that each of the three workers will need to log-in to renew the session id when the session expires in the RHV side. That explains the three consecutive long-in events that you see.

So these events are normal, and not a regression, in my opinion.

If we want to avoid them we can devise a mechanism to share the session between the workers that need it. This could be achieved in the CFME side storing the session id in the database, or in memcached, instead of using global variables.

Alternatively we could consider a mechanism for the RHV administrator to mute events based on certain rules, for example to ignore the login/logout events coming from the CFME IP address.

(Note that when using version 4 of the API instead of version 3 the same will apply, but to the SSO token instead of to the session id.)
Comment 11 Martin Perina 2017-07-10 06:23:40 EDT
Personally I don't think it's an issue for CFME to use 3 sessions per engine, so the only issue is that having 3 same logging messages is confusing. So let's add some differentiation to the logging message so admin will know that those were 3 different sessions.

Based on above removing regression keyword and targeting to 4.2 as it should be an easy fix
Comment 12 Pavel Novotny 2017-10-30 11:42:58 EDT
Verified in
ovirt-engine-webadmin-portal-4.2.0-0.0.master.20171029154613.git19686f3.el7.centos.noarch
ovirt-engine-4.2.0-0.0.master.20171029154613.git19686f3.el7.centos.noarch

As per comment 11, the login/logout messages now contain the client IP and session ID:

  User admin@internal-authz connecting from '<IP>' using session '<SESSION_ID>' logged in.

  User admin@internal-authz connected from '<IP>' using session '<SESSION_ID>' logged out.

See attached screenshot for more details.
Comment 13 Pavel Novotny 2017-10-30 11:44 EDT
Created attachment 1345524 [details]
screen: enhanced login/logout event messages
Comment 14 Sandro Bonazzola 2017-12-20 06:04:38 EST
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017.

Since the problem described in this bug report should be
resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE.

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

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