Bug 1526708 - uprecords display bug - negative uptime
Summary: uprecords display bug - negative uptime
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora EPEL
Classification: Fedora
Component: uptimed
Version: epel7
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Tomasz Torcz
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-12-16 14:55 UTC by Johan Andersson
Modified: 2018-12-05 20:22 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-12-05 20:22:39 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
/var/spool/uptimed/records (152 bytes, text/plain)
2017-12-16 16:25 UTC, Johan Andersson
no flags Details

Description Johan Andersson 2017-12-16 14:55:53 UTC
uprecords show negative uptime, after running it for a 'while', and then reboots. It can, and will, show you a negative uptime. 
Output at the bottom of the report.

Name        : uptimed
Arch        : x86_64
Version     : 0.4.0
Release     : 6.el7

It's reproducible, but I believe it will require more uptime then just a few minutes.

Steps to Reproduce:
1. Install uptimed.
2. Run 'uprecords' binary, to create initial uptime db.
3. I would let the server at least have 1 day uptime, then reboot it.
4. Run 'uprecords' again. This time it will report a negative 'down' time, and therefor give you and uptime over 100% - which is impossible.

Here's my output from 'uprecords':

     #               Uptime | System                                     Boot up
----------------------------+---------------------------------------------------
     1    62 days, 04:57:20 | Linux 3.10.0-693.2.2.el7  Sat Sep 30 10:45:46 2017
     2    10 days, 21:01:42 | Linux 3.10.0-693.5.2.el7  Fri Dec  1 14:41:04 2017
->   3     4 days, 03:58:41 | Linux 3.10.0-693.11.1.el  Tue Dec 12 11:45:33 2017
     4     4 days, 03:58:11 | Linux 3.10.0-693.11.1.el  Tue Dec 12 11:42:55 2017
----------------------------+---------------------------------------------------
1up in     6 days, 17:03:02 | at                        Sat Dec 23 08:47:15 2017
no1 in    58 days, 00:58:40 | at                        Mon Feb 12 16:42:53 2018
    up    81 days, 09:55:54 | since                     Sat Sep 30 10:45:46 2017
  down  -4 days, -03:-57:-2 | since                     Sat Sep 30 10:45:46 2017
   %up              105.392 | since                     Sat Sep 30 10:45:46 2017



Expected results: Should report a positive 'down' time, (Example: down  4 days, 03:57:2) and a %uptime with a value below 100 (Example: %up     95.392%).


Additional info:
System info - CentOS 7.4.1708 (3.10.0-693.11.1.el7.x86_64)

Comment 1 Tomasz Torcz 2017-12-16 16:08:10 UTC
Could you attach you /var/spool/uptimed/records file? It doesn't contain anything security critical, only boot times and kernel versions.

Comment 2 Johan Andersson 2017-12-16 16:23:05 UTC
(In reply to Tomasz Torcz from comment #1)
> Could you attach you /var/spool/uptimed/records file? It doesn't contain
> anything security critical, only boot times and kernel versions.

Of course I can, I'll do it right away. 
Thank you for your reply.

Comment 3 Johan Andersson 2017-12-16 16:25:29 UTC
Created attachment 1368835 [details]
/var/spool/uptimed/records

Additional information about the kernel versions etc, when the records were made.

Comment 4 Tomasz Torcz 2018-12-05 20:22:39 UTC
Hi,

  I hope you have another glorious year of uptimes! I've finally analyzed the code and your database. I don't see any problems within uprecords, but I'm suspicious of your database.
  The entries are as follows (boot times and shutdown/database sync times):

5374640:1506761146:Linux 3.10.0-693.2.2.el7.x86_64
      Sat, 30 Sep 2017 08:45:46 +0000
until Fri, 01 Dec 2017 13:43:06 +0000


939702:1512135664:Linux 3.10.0-693.5.2.el7.x86_64
      Fri, 01 Dec 2017 13:41:04 +0000
until Tue, 12 Dec 2017 10:42:46 +0000 


365832:1513075375:Linux 3.10.0-693.11.1.el7.x86_64
      Tue, 12 Dec 2017 10:42:55 +0000
until Sat, 16 Dec 2017 16:20:07 +0000


 Basically 3 entries. Now observe first two:
1) computer was shut down on 1st December 2017, at 13:43:06
2) computer started at 13:41:04
--> computer started TWO MINUTES BEFORE it was shutdown.
This explains some negative time you see.


And now last two:
2) computer was shut down at 10:42:46
3) computer was started again at 10:42:55
Basically 9 seconds passed. Isn't it too fast for full shutdown, firmware initialization, boot loader and linux boot?


My guess is that you have unreliable real time clock in this computer. During boot, uptimed starts and records false boot time. Only afterwards ntp/chronyd/ntpstep corrects your system time (stepping it backwards few minutes). I see no problem in uptimed.


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