Bug 1650885

Summary: remote logs not displayed correctly when times do not match
Product: Red Hat Enterprise Linux 8 Reporter: Scott Poore <spoore>
Component: cockpit-session-recordingAssignee: Kirill Gliebov <kgliebov>
Status: CLOSED CURRENTRELEASE QA Contact: Scott Poore <spoore>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.0CC: dpal, nkinder
Target Milestone: rcKeywords: TestBlocker
Target Release: 8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-06-14 01:20:13 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Scott Poore 2018-11-17 04:17:27 UTC 
Description of problem:

When viewing remote journal recorded sessions, some sessions do not perform proper log correlation if times or timezones do not match.

Version-Release number of selected component (if applicable):
cockpit-session-recording-1-23.el8

How reproducible:
Unknown.  believed to be reproducible.

Steps to Reproduce:
On Server:
1. Setup cockpit and cockpit-session-recording
2. Setup systemd-journal-remote
On Client1:
3. Setup systemd-journal-upload to send to Server
4. Install tlog and add a user with /usr/bin/tlog-rec-session as shell
On Server:
5. ssh localuser1@client1 and run some commands
Open Browser in a different timezone to:
6. https://server:9090 and login as user with admin privs
7. go to Session Recording from left hand menu
8. select the session to play 

Actual results:
I do not see the correlateed logs from the session.

Expected results:
when playing back session, I expected to see the correlated log entries from the host where the session was recorded.  

Additional info:
Comment 2 Scott Poore 2018-12-12 17:21:55 UTC 
Verified with the same test as https://bugzilla.redhat.com/show_bug.cgi?id=1650883

Should be noted that browser is run on a host in CST, rhel8-3 journal-remote host is PST, and rhel8-6 journal-upload host is MST.  So 3 different timezones.

Version ::

cockpit-session-recording-1-29.el8.noarch

Results ::

rhel8-3 is setup with systemd-journal-remote

[root@rhel8-3 ~]# systemctl status systemd-journal-remote
● systemd-journal-remote.service - Journal Remote Sink Service
   Loaded: loaded (/usr/lib/systemd/system/systemd-journal-remote.service; indirect; vendor preset: di>
   Active: active (running) since Wed 2018-12-12 08:52:49 PST; 22min ago
     Docs: man:systemd-journal-remote(8)
           man:journal-remote.conf(5)
 Main PID: 1455 (systemd-journal)
   Status: "Processing requests..."
    Tasks: 1 (limit: 17972)
   Memory: 32.7M
   CGroup: /system.slice/systemd-journal-remote.service
           └─1455 /usr/lib/systemd/systemd-journal-remote --listen-https=-3 --output=/var/log/journal/>

Dec 12 08:52:49 rhel8-3.example.com systemd[1]: Started Journal Remote Sink Service.

rhel8-6 is setup with systemd-journal-upload

[root@rhel8-6 ~]# systemctl status systemd-journal-upload
● systemd-journal-upload.service - Journal Remote Upload Service
   Loaded: loaded (/usr/lib/systemd/system/systemd-journal-upload.service; disabled; vendor preset: di>
   Active: active (running) since Wed 2018-12-12 09:53:10 MST; 22min ago
     Docs: man:systemd-journal-upload(8)
 Main PID: 1417 (systemd-journal)
   Status: "Processing input..."
    Tasks: 1 (limit: 17972)
   Memory: 4.0M
   CGroup: /system.slice/systemd-journal-upload.service
           └─1417 /usr/lib/systemd/systemd-journal-upload --save-state

Dec 12 09:53:10 rhel8-6.example.com systemd[1]: Started Journal Remote Upload Service.

And is pointing to rhel8-3:

[root@rhel8-6 ~]# cat /etc/systemd/journal-upload.conf 
[Upload]
URL=https://rhel8-3.example.com:19532
ServerKeyFile=/etc/ssl/private/journal-upload.pem
ServerCertificateFile=/etc/ssl/certs/journal-upload.pem
TrustedCertificateFile=/etc/ssl/ca/trusted.pem

Recorded session made on rhel8-6 by ssh'ing as localuser1 to localhost.

Can see the session here:

[root@rhel8-6 ~]# journalctl _EXE=/usr/bin/tlog-rec-session --since 06:00
-- Logs begin at Fri 2018-11-16 16:08:46 MST, end at Wed 2018-12-12 10:06:36 MST. --
Dec 12 09:55:07 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:19 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:20 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:20 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:23 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:23 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:25 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:26 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:30 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:32 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:32 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:35 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:35 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:41 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 09:55:44 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">

Then I can also check remote recordings on rhel8-3:

[root@rhel8-3 ~]# journalctl -m _EXE=/usr/bin/tlog-rec-session --since 06:00
-- Logs begin at Fri 2018-11-09 12:42:11 PST, end at Wed 2018-12-12 09:18:01 PST. --
Dec 12 08:55:07 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:19 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:20 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:20 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:23 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:23 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:25 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:26 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:29 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:30 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:32 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:32 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:35 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:35 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:41 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">
Dec 12 08:55:44 rhel8-6.example.com -tlog-rec-session[1442]: {"ver":"2.2","host":"rhel8-6.example.com">

And when I login to https://rhel8-3.example.com:9090 from a browser and go to "Session Recordings" I can see and playback this recording.

It should be noted that the time displayed for this recording in the browser is 10:55 CST as expected.