process-reboot-cause.service: Main process exited, code=exited, status=1/FAILURE (due to empty history file)

[gechiang]

Observe the following syslog reoccurring every 30 seconds after a device rebooted:

Description

May  7 19:36:19.211682 SONIC INFO systemd[1]: process-reboot-cause.service: Scheduled restart job, restart counter is at 297.
May  7 19:36:19.211971 SONIC INFO systemd[1]: Stopped Retrieve the reboot cause from the history files and save them to StateDB.
May  7 19:36:19.215606 SONIC INFO systemd[1]: Starting Retrieve the reboot cause from the history files and save them to StateDB...
May  7 19:36:19.226020 SONIC INFO systemctl[87860]: active
May  7 19:36:19.243741 SONIC INFO systemctl[87861]: active
May  7 19:36:19.245039 SONIC INFO systemd[1]: Started Retrieve the reboot cause from the history files and save them to StateDB.
May  7 19:36:19.373106 SONIC INFO process-reboot-cause: Starting up...
May  7 19:36:19.373250 SONIC INFO process-reboot-cause: Previous reboot cause: User issued 'reboot' command [User: v-arkare, Time: Tue 07 May 2024 05:05:14 PM UTC]
May  7 19:36:19.377003 SONIC INFO process-reboot-cause[87862]: Traceback (most recent call last):
May  7 19:36:19.377111 SONIC INFO process-reboot-cause[87862]:   File "/usr/local/bin/process-reboot-cause", line 100, in <module>
May  7 19:36:19.377193 SONIC INFO process-reboot-cause[87862]:     main()
May  7 19:36:19.377250 SONIC INFO process-reboot-cause[87862]:   File "/usr/local/bin/process-reboot-cause", line 96, in main
May  7 19:36:19.377335 SONIC INFO process-reboot-cause[87862]:     read_reboot_cause_files_and_save_state_db()
May  7 19:36:19.377391 SONIC INFO process-reboot-cause[87862]:   File "/usr/local/bin/process-reboot-cause", line 55, in read_reboot_cause_files_and_save_state_db
May  7 19:36:19.377461 SONIC INFO process-reboot-cause[87862]:     data = json.load(cause_file)
May  7 19:36:19.377516 SONIC INFO process-reboot-cause[87862]:   File "/usr/lib/python3.9/json/__init__.py", line 293, in load
May  7 19:36:19.378030 SONIC INFO process-reboot-cause[87862]:     return loads(fp.read(),
May  7 19:36:19.378111 SONIC INFO process-reboot-cause[87862]:   File "/usr/lib/python3.9/json/__init__.py", line 346, in loads
May  7 19:36:19.378186 SONIC INFO process-reboot-cause[87862]:     return _default_decoder.decode(s)
May  7 19:36:19.378242 SONIC INFO process-reboot-cause[87862]:   File "/usr/lib/python3.9/json/decoder.py", line 337, in decode
May  7 19:36:19.378323 SONIC INFO process-reboot-cause[87862]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
May  7 19:36:19.378380 SONIC INFO process-reboot-cause[87862]:   File "/usr/lib/python3.9/json/decoder.py", line 355, in raw_decode
May  7 19:36:19.378811 SONIC INFO process-reboot-cause[87862]:     raise JSONDecodeError("Expecting value", s, err.value) from None
May  7 19:36:19.378901 SONIC INFO process-reboot-cause[87862]: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
May  7 19:36:19.392072 SONIC NOTICE systemd[1]: process-reboot-cause.service: Main process exited, code=exited, status=1/FAILURE
May  7 19:36:19.392220 SONIC WARNING systemd[1]: process-reboot-cause.service: Failed with result 'exit-code'.
...
May  7 19:35:48.961950 SONIC INFO systemd[1]: process-reboot-cause.service: Scheduled restart job, restart counter is at 296.
May  7 19:35:48.962338 SONIC INFO systemd[1]: Stopped Retrieve the reboot cause from the history files and save them to StateDB.
May  7 19:35:48.966427 SONIC INFO systemd[1]: Starting Retrieve the reboot cause from the history files and save them to StateDB...
May  7 19:35:48.979400 SONIC INFO systemctl[87731]: active
May  7 19:35:48.995147 SONIC INFO systemctl[87732]: active
May  7 19:35:48.996982 SONIC INFO systemd[1]: Started Retrieve the reboot cause from the history files and save them to StateDB.
May  7 19:35:49.121490 SONIC INFO process-reboot-cause: Starting up...
May  7 19:35:49.122218 SONIC INFO process-reboot-cause: Previous reboot cause: User issued 'reboot' command [User: v-arkare, Time: Tue 07 May 2024 05:05:14 PM UTC]
May  7 19:35:49.130597 SONIC INFO process-reboot-cause[87733]: Traceback (most recent call last):
May  7 19:35:49.130714 SONIC INFO process-reboot-cause[87733]:   File "/usr/local/bin/process-reboot-cause", line 100, in <module>
May  7 19:35:49.130798 SONIC INFO process-reboot-cause[87733]:     main()
May  7 19:35:49.130856 SONIC INFO process-reboot-cause[87733]:   File "/usr/local/bin/process-reboot-cause", line 96, in main
May  7 19:35:49.130929 SONIC INFO process-reboot-cause[87733]:     read_reboot_cause_files_and_save_state_db()
May  7 19:35:49.130985 SONIC INFO process-reboot-cause[87733]:   File "/usr/local/bin/process-reboot-cause", line 55, in read_reboot_cause_files_and_save_state_db
May  7 19:35:49.131069 SONIC INFO process-reboot-cause[87733]:     data = json.load(cause_file)
May  7 19:35:49.131126 SONIC INFO process-reboot-cause[87733]:   File "/usr/lib/python3.9/json/__init__.py", line 293, in load
May  7 19:35:49.131674 SONIC INFO process-reboot-cause[87733]:     return loads(fp.read(),
May  7 19:35:49.131758 SONIC INFO process-reboot-cause[87733]:   File "/usr/lib/python3.9/json/__init__.py", line 346, in loads
May  7 19:35:49.131812 SONIC INFO process-reboot-cause[87733]:     return _default_decoder.decode(s)
May  7 19:35:49.131864 SONIC INFO process-reboot-cause[87733]:   File "/usr/lib/python3.9/json/decoder.py", line 337, in decode
May  7 19:35:49.132193 SONIC INFO process-reboot-cause[87733]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
May  7 19:35:49.132272 SONIC INFO process-reboot-cause[87733]:   File "/usr/lib/python3.9/json/decoder.py", line 355, in raw_decode
May  7 19:35:49.132390 SONIC INFO process-reboot-cause[87733]:     raise JSONDecodeError("Expecting value", s, err.value) from None
May  7 19:35:49.132459 SONIC INFO process-reboot-cause[87733]: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
May  7 19:35:49.145751 SONIC NOTICE systemd[1]: process-reboot-cause.service: Main process exited, code=exited, status=1/FAILURE
May  7 19:35:49.145897 SONIC WARNING systemd[1]: process-reboot-cause.service: Failed with result 'exit-code'.

Steps to reproduce the issue:

This is what I observed onthe history directory:

/host/reboot-cause/history$ ls -l
total 20
-rw-r--r-- 1 root root 136 Jan 16 22:37 reboot-cause-2024_01_16_22_37_29.json
-rw-r--r-- 1 root root   0 May  6 23:35 reboot-cause-2024_05_06_23_35_28.json
-rw-r--r-- 1 root root 103 May  6 23:37 reboot-cause-2024_05_06_23_37_14.json
-rw-r--r-- 1 root root 191 May  7 02:28 reboot-cause-2024_05_07_02_28_16.json
-rw-r--r-- 1 root root 139 May  7 03:39 reboot-cause-2024_05_07_03_39_45.json
-rw-r--r-- 1 root root 135 May  7 17:06 reboot-cause-2024_05_07_17_06_25.json

Noticed that there was an empty file.
If I were to remove this empty file, then the process-reboot-cause.service stop crashing and everything is fine.

This was found on a device running from 202305 based image which I believe should be a common problem even in master and all other branches as well.

[neethajohn]

@prgeor , can you please take a look at why there is an empty file created

[prgeor]

This is now fixed