{"action":"created","issue":{"url":"https://api.github.com/repos/openbmc/openbmc/issues/2847","repository_url":"https://api.github.com/repos/openbmc/openbmc","labels_url":"https://api.github.com/repos/openbmc/openbmc/issues/2847/labels{/name}","comments_url":"https://api.github.com/repos/openbmc/openbmc/issues/2847/comments","events_url":"https://api.github.com/repos/openbmc/openbmc/issues/2847/events","html_url":"https://github.com/openbmc/openbmc/issues/2847","id":292547181,"number":2847,"title":"phosphor-watchdog writing a lot of data to the journal - watchdog: update time remaining","user":{"login":"geissonator","id":1612261,"avatar_url":"https://avatars2.githubusercontent.com/u/1612261?v=4","gravatar_id":"","url":"https://api.github.com/users/geissonator","html_url":"https://github.com/geissonator","followers_url":"https://api.github.com/users/geissonator/followers","following_url":"https://api.github.com/users/geissonator/following{/other_user}","gists_url":"https://api.github.com/users/geissonator/gists{/gist_id}","starred_url":"https://api.github.com/users/geissonator/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/geissonator/subscriptions","organizations_url":"https://api.github.com/users/geissonator/orgs","repos_url":"https://api.github.com/users/geissonator/repos","events_url":"https://api.github.com/users/geissonator/events{/privacy}","received_events_url":"https://api.github.com/users/geissonator/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":{"login":"wak-google","id":22405326,"avatar_url":"https://avatars2.githubusercontent.com/u/22405326?v=4","gravatar_id":"","url":"https://api.github.com/users/wak-google","html_url":"https://github.com/wak-google","followers_url":"https://api.github.com/users/wak-google/followers","following_url":"https://api.github.com/users/wak-google/following{/other_user}","gists_url":"https://api.github.com/users/wak-google/gists{/gist_id}","starred_url":"https://api.github.com/users/wak-google/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wak-google/subscriptions","organizations_url":"https://api.github.com/users/wak-google/orgs","repos_url":"https://api.github.com/users/wak-google/repos","events_url":"https://api.github.com/users/wak-google/events{/privacy}","received_events_url":"https://api.github.com/users/wak-google/received_events","type":"User","site_admin":false},"assignees":[{"login":"wak-google","id":22405326,"avatar_url":"https://avatars2.githubusercontent.com/u/22405326?v=4","gravatar_id":"","url":"https://api.github.com/users/wak-google","html_url":"https://github.com/wak-google","followers_url":"https://api.github.com/users/wak-google/followers","following_url":"https://api.github.com/users/wak-google/following{/other_user}","gists_url":"https://api.github.com/users/wak-google/gists{/gist_id}","starred_url":"https://api.github.com/users/wak-google/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wak-google/subscriptions","organizations_url":"https://api.github.com/users/wak-google/orgs","repos_url":"https://api.github.com/users/wak-google/repos","events_url":"https://api.github.com/users/wak-google/events{/privacy}","received_events_url":"https://api.github.com/users/wak-google/received_events","type":"User","site_admin":false}],"milestone":null,"comments":6,"created_at":"2018-01-29T20:22:30Z","updated_at":"2018-02-01T02:33:48Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"I noticed when https://gerrit.openbmc-project.xyz/#/c/8712/ came through CI, it picked up https://gerrit.openbmc-project.xyz/#/c/8605/ which added some additional debug to the watchdog.\r\n\r\nOn our witherspoon, the debug output really filled up our logs during boot a lot.  Especially later in the boot when the host is nearing the end of it's boot.\r\n\r\n```\r\nJan 29 20:14:58 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:58 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:58 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:58 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:58 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:59 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:59 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:14:59 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:14:59 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:14:59 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:00 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:00 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:00 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:00 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:00 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:01 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:02 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:02 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:03 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:03 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:03 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:03 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:03 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:04 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:04 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:04 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:05 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:06 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:07 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:08 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:08 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:08 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:08 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: No Registered handlers for NetFn:[0x32],Cmd:[0xFF]\r\nJan 29 20:15:08 witherspoon ipmid[1272]: ERROR:[0xC1] handling NetFn:[0x32], Cmd:[0xF0]\r\nJan 29 20:15:08 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:09 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:11 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:12 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:13 witherspoon power_control.exe[1274]: BootProgress: xyz.openbmc_project.State.Boot.Progress.ProgressStages.OSStart\r\nJan 29 20:15:13 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:13 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:13 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:16 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:16 witherspoon ipmid[1272]: Bus: :1.23, Path: /xyz/openbmc_project/control/host0/TPMEnable, Interface: xyz.openbmc_project.Control.TPM.Policy\r\nJan 29 20:15:23 witherspoon ipmid[1272]: ERROR:[0x80] handling NetFn:[0x2C], Cmd:[0x3]\r\nJan 29 20:15:23 witherspoon ipmid[1272]: Bus: :1.72, Path: /org/open_power/control/occ1, Interface: org.open_power.OCC.Status\r\nJan 29 20:15:25 witherspoon systemd[1]: Started Phosphor Hwmon Poller.\r\nJan 29 20:15:27 witherspoon systemd[1]: Started Phosphor Hwmon Poller.\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: Failed to invoke DBus method.\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: The operation failed internally.\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: Property not used, unless PropertyChanged signal received\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: Failed to invoke DBus method.\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: The operation failed internally.\r\nJan 29 20:15:28 witherspoon phosphor-fan-control[4170]: Property not used, unless PropertyChanged signal received\r\nJan 29 20:15:29 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:29 witherspoon phosphor-fan-control[4170]: Failed to invoke DBus method.\r\nJan 29 20:15:29 witherspoon phosphor-fan-control[4170]: The operation failed internally.\r\nJan 29 20:15:30 witherspoon phosphor-fan-control[4170]: Property not used, unless PropertyChanged signal received\r\nJan 29 20:15:31 witherspoon phosphor-fan-control[4170]: Failed to invoke DBus method.\r\nJan 29 20:15:31 witherspoon phosphor-fan-control[4170]: The operation failed internally.\r\nJan 29 20:15:31 witherspoon phosphor-fan-control[4170]: Property not used, unless PropertyChanged signal received\r\nJan 29 20:15:31 witherspoon phosphor-watchdog[3706]: watchdog: update time remaining\r\nJan 29 20:15:32 witherspoon phosphor-fan-control[4170]: Failed to invoke DBus method.\r\nJan 29 20:15:32 witherspoon phosphor-fan-control[4170]: The operation failed internally.\r\nJan 29 20:15:32 witherspoon phosphor-fan-control[4170]: Property not used, unless PropertyChanged signal received\r\nJan 29 20:15:32 witherspoon phosphor-watchdog[3706]: watchdog: disabled\r\n\r\n```\r\n\r\nWe could just disable \"debug\" but I know there's some other useful logs in debug right now that would need to probably be moved."},"comment":{"url":"https://api.github.com/repos/openbmc/openbmc/issues/comments/362139314","html_url":"https://github.com/openbmc/openbmc/issues/2847#issuecomment-362139314","issue_url":"https://api.github.com/repos/openbmc/openbmc/issues/2847","id":362139314,"user":{"login":"geissonator","id":1612261,"avatar_url":"https://avatars2.githubusercontent.com/u/1612261?v=4","gravatar_id":"","url":"https://api.github.com/users/geissonator","html_url":"https://github.com/geissonator","followers_url":"https://api.github.com/users/geissonator/followers","following_url":"https://api.github.com/users/geissonator/following{/other_user}","gists_url":"https://api.github.com/users/geissonator/gists{/gist_id}","starred_url":"https://api.github.com/users/geissonator/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/geissonator/subscriptions","organizations_url":"https://api.github.com/users/geissonator/orgs","repos_url":"https://api.github.com/users/geissonator/repos","events_url":"https://api.github.com/users/geissonator/events{/privacy}","received_events_url":"https://api.github.com/users/geissonator/received_events","type":"User","site_admin":false},"created_at":"2018-02-01T02:33:48Z","updated_at":"2018-02-01T02:33:48Z","author_association":"CONTRIBUTOR","body":"Yeah, I agree, lets just revert for now.  I know our host code design is to reset the watchdog on every \"istep\" in the boot, some of which happen very quickly."}}
{"actor":{"display_login":"geissonator"}}