+++ This bug was initially created as a clone of Bug #1468965 +++

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

--- Additional comment from Michael Burman on 2017-07-10 02:09 EDT ---



--- Additional comment from Michael Burman on 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

--- Additional comment from Michael Burman on 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.

--- Additional comment from Oved Ourfali on 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.

--- Additional comment from Michael Burman on 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).

--- Additional comment from Juan Hernández on 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.

--- Additional comment from Michael Burman on 2017-07-10 04:29:35 EDT ---

Hi Juan,

10.35.17.178 is the CFME -

For example from the last minutes -

10.35.17.178 - - [10/Jul/2017:11:24:30 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:24:45 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:25:00 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 

10.35.17.178 - - [10/Jul/2017:11:25:30 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:25:45 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:26:01 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:26:16 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86

10.35.17.178 - - [10/Jul/2017:11:26:31 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:26:46 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86
10.35.17.178 - - [10/Jul/2017:11:27:01 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86

10.35.17.178 - - [10/Jul/2017:11:27:16 +0300] "GET /ovirt-engine/api/events?from=34041 HTTP/1.1" 200 86

--- Additional comment from Michael Burman on 2017-07-10 04:30 EDT ---



--- Additional comment from Martin Perina on 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?

--- Additional comment from Juan Hernández on 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.)

--- Additional comment from Martin Perina on 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

--- Additional comment from Pavel Novotny on 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.

--- Additional comment from Pavel Novotny on 2017-10-30 11:44 EDT ---