{"action":"created","issue":{"url":"https://api.github.com/repos/openbmc/skeleton/issues/127","repository_url":"https://api.github.com/repos/openbmc/skeleton","labels_url":"https://api.github.com/repos/openbmc/skeleton/issues/127/labels{/name}","comments_url":"https://api.github.com/repos/openbmc/skeleton/issues/127/comments","events_url":"https://api.github.com/repos/openbmc/skeleton/issues/127/events","html_url":"https://github.com/openbmc/skeleton/issues/127","id":167824202,"number":127,"title":"Host watchdog timeout when RMC communicates with BMC continually","user":{"login":"johnhcwang","id":17872929,"avatar_url":"https://avatars.githubusercontent.com/u/17872929?v=3","gravatar_id":"","url":"https://api.github.com/users/johnhcwang","html_url":"https://github.com/johnhcwang","followers_url":"https://api.github.com/users/johnhcwang/followers","following_url":"https://api.github.com/users/johnhcwang/following{/other_user}","gists_url":"https://api.github.com/users/johnhcwang/gists{/gist_id}","starred_url":"https://api.github.com/users/johnhcwang/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/johnhcwang/subscriptions","organizations_url":"https://api.github.com/users/johnhcwang/orgs","repos_url":"https://api.github.com/users/johnhcwang/repos","events_url":"https://api.github.com/users/johnhcwang/events{/privacy}","received_events_url":"https://api.github.com/users/johnhcwang/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":{"login":"anoo1","id":9052527,"avatar_url":"https://avatars.githubusercontent.com/u/9052527?v=3","gravatar_id":"","url":"https://api.github.com/users/anoo1","html_url":"https://github.com/anoo1","followers_url":"https://api.github.com/users/anoo1/followers","following_url":"https://api.github.com/users/anoo1/following{/other_user}","gists_url":"https://api.github.com/users/anoo1/gists{/gist_id}","starred_url":"https://api.github.com/users/anoo1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/anoo1/subscriptions","organizations_url":"https://api.github.com/users/anoo1/orgs","repos_url":"https://api.github.com/users/anoo1/repos","events_url":"https://api.github.com/users/anoo1/events{/privacy}","received_events_url":"https://api.github.com/users/anoo1/received_events","type":"User","site_admin":false},"assignees":[{"login":"anoo1","id":9052527,"avatar_url":"https://avatars.githubusercontent.com/u/9052527?v=3","gravatar_id":"","url":"https://api.github.com/users/anoo1","html_url":"https://github.com/anoo1","followers_url":"https://api.github.com/users/anoo1/followers","following_url":"https://api.github.com/users/anoo1/following{/other_user}","gists_url":"https://api.github.com/users/anoo1/gists{/gist_id}","starred_url":"https://api.github.com/users/anoo1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/anoo1/subscriptions","organizations_url":"https://api.github.com/users/anoo1/orgs","repos_url":"https://api.github.com/users/anoo1/repos","events_url":"https://api.github.com/users/anoo1/events{/privacy}","received_events_url":"https://api.github.com/users/anoo1/received_events","type":"User","site_admin":false}],"milestone":null,"comments":1,"created_at":"2016-07-27T10:41:50Z","updated_at":"2016-08-04T14:32:10Z","closed_at":null,"body":"Sometimes BMC needs more than 30s to finish the jobs when RMC communicates with BMC continually.\r\nPer OpenPower Host IPMI Spec [(here)](https://github.com/openbmc/skeleton/blob/master/pychassisctl/chassis_control.py#L146), it specify the timer should be 30s.\r\nWe need to improve the performance or change the spec to extend the poll interval.\r\nAny advice?\r\n\r\nStep 1: Login to BMC by curl command\r\n````\r\n$ curl -c cjar -b cjar -k -X POST -H \"Content-Type: application/json\" -d '{\"data\": [ \"root\", \"0penBmc\" ] }' https://10.32.9.38/login\r\n{\r\n  \"data\": \"User 'root' logged in\", \r\n  \"message\": \"200 OK\", \r\n  \"status\": \"ok\"\r\n}\r\n$ curl -c cjar -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/bmc\r\n{\r\n  \"data\": {\r\n    \"fault\": \"False\", \r\n    \"fru_type\": \"BMC\", \r\n    \"is_fru\": 0, \r\n    \"manufacturer\": \"ASPEED\", \r\n    \"present\": \"False\", \r\n    \"version\": \"v1.0.3-dirty\"\r\n  }, \r\n  \"message\": \"200 OK\", \r\n  \"status\": \"ok\"\r\n````\r\n**Step 2: Create 5 sessions to get inventory continually and make sure that all of them can get the information correctly**\r\n````\r\n$for x in `seq 1 100`;do curl -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/enumerate ;done &\r\n$for x in `seq 1 100`;do curl -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/enumerate ;done &\r\n$for x in `seq 1 100`;do curl -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/enumerate ;done &\r\n$for x in `seq 1 100`;do curl -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/enumerate ;done &\r\n$for x in `seq 1 100`;do curl -b cjar -k https://10.32.9.38/org/openbmc/inventory/system/chassis/motherboard/enumerate ;done &\r\n````\r\nStep 3: Power on the system and then watchdog timeout sometimes\r\n````\r\nJul 21 00:51:31 barreleye system_manager.py[982]: Turn on power and boot\r\nJul 21 00:51:31 barreleye system_manager.py[982]: Running System State: HOST_POWERING_ON\r\nJul 21 00:51:31 barreleye system_manager.py[982]: Setting watchdog poll interval to: 30000\r\nJul 21 00:51:31 barreleye system_manager.py[982]: Starting watchdog with poll interval: 30000\r\n = None\r\nftgmac100: NCSI interface down\r\nJul 21 00:51:33 barreleye kernel: ftgmac100: NCSI interface down\r\nJul 21 00:51:33 barreleye kernel[972]: ftgmac100: NCSI interface down\r\nJul 21 00:51:33 barreleye system_manager.py[982]: Running System State: HOST_POWERED_ON\r\nJul 21 00:51:33 barreleye system_manager.py[982]: Starting process: /usr/sbin/goto_system_state.py INVENTORY_UPLOADED inventory_upload.py: inventory_upload\r\nftgmac100: NCSI interface up\r\nJul 21 00:51:34 barreleye kernel: ftgmac100: NCSI interface up\r\nJul 21 00:51:34 barreleye kernel[972]: ftgmac100: NCSI interface up\r\n^[\r\nJul 21 00:51:55 barreleye system_manager.py[982]: ERROR (name_properties): \"name\" property in /bmc/inventory/hdd_backplane is incorrect (\"BARRELEYE Exander\" instead of base node name)\r\nJul 21 00:51:55 barreleye system_manager.py[982]: ERROR (name_properties): \"name\" property in /bmc/inventory/sas_expander is incorrect (\"BARRELEYE BPx15\" instead of base node name)\r\nJul 21 00:51:55 barreleye system_manager.py[982]: ERROR (name_properties): \"name\" property in /bmc/inventory/misc is incorrect (\"BARRELEYE MB\" instead of base node name)\r\nJul 21 00:51:55 barreleye system_manager.py[982]: ERROR: Input tree has errors, aborting (use -f to force output)\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Partition 'BMC_INV' not found !\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Uploading inventory to PNOR in dtb format...\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Running System State: INVENTORY_UPLOADED\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Starting process: /usr/sbin/pcie_slot_present.exe: pcie_present\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Setting fans to max\r\nJul 21 00:51:56 barreleye system_manager.py[982]: Booting host\r\nJul 21 00:51:57 barreleye system_manager.py[982]: Checking Presence: SLOT0_RISER_PRESENT\r\nJul 21 00:51:57 barreleye system_manager.py[982]: GPIO Lookup:  SLOT0_RISER_PRESENT = 424,in\r\nJul 21 00:51:57 barreleye system_manager.py[982]: Checking Presence: SLOT1_RISER_PRESENT\r\nJul 21 00:51:57 barreleye system_manager.py[982]: GPIO Lookup:  SLOT1_RISER_PRESENT = 425,in\r\nJul 21 00:51:57 barreleye system_manager.py[982]: Checking Presence: SLOT2_RISER_PRESENT\r\nJul 21 00:51:57 barreleye system_manager.py[982]: GPIO Lookup:  SLOT2_RISER_PRESENT = 426,in\r\nJul 21 00:51:58 barreleye system_manager.py[982]: Checking Presence: SLOT0_PRESENT\r\nJul 21 00:51:58 barreleye system_manager.py[982]: GPIO Lookup:  SLOT0_PRESENT = 427,in\r\nJul 21 00:51:58 barreleye system_manager.py[982]: Using primary side of the bios flash\r\nJul 21 00:51:58 barreleye system_manager.py[982]: Checking Presence: SLOT1_PRESENT\r\nJul 21 00:51:58 barreleye system_manager.py[982]: GPIO Lookup:  SLOT1_PRESENT = 428,in\r\nJul 21 00:51:58 barreleye system_manager.py[982]: Checking Presence: SLOT2_PRESENT\r\nJul 21 00:51:58 barreleye system_manager.py[982]: Running System State: HOST_BOOTING\r\nJul 21 00:51:59 barreleye system_manager.py[982]: GPIO Lookup:  SLOT2_PRESENT = 429,in\r\nJul 21 00:51:59 barreleye system_manager.py[982]: Checking Presence: MEZZ0_PRESENT\r\nJul 21 00:51:59 barreleye system_manager.py[982]: GPIO Lookup:  MEZZ0_PRESENT = 432,in\r\nJul 21 00:51:59 barreleye system_manager.py[982]: Checking Presence: MEZZ1_PRESENT\r\nJul 21 00:51:59 barreleye system_manager.py[982]: GPIO Lookup:  MEZZ1_PRESENT = 433,in\r\nJul 21 00:52:01 barreleye system_manager.py[982]: Polling watchdog: 0\r\nJul 21 00:52:01 barreleye system_manager.py[982]: Watchdog Error, Hard Rebooting\r\nJul 21 00:52:01 barreleye system_manager.py[982]: Turn off power\r\nJul 21 00:52:01 barreleye system_manager.py[982]: Stopping watchdog\r\nJul 21 00:52:01 barreleye system_manager.py[982]: Running System State: HOST_POWERING_OFF\r\nftgmac100: NCSI interface up\r\nJul 21 00:52:03 barreleye kernel: ftgmac100: NCSI interface up\r\nJul 21 00:52:03 barreleye kernel[972]: ftgmac100: NCSI interface up\r\nJul 21 00:52:03 barreleye system_manager.py[982]: Running System State: HOST_POWERED_OFF\r\nJul 21 00:52:03 barreleye system_manager.py[982]: Deleting OCC device\r\nJul 21 00:52:03 barreleye system_manager.py[982]: Turn on power and boot\r\nJul 21 00:52:03 barreleye system_manager.py[982]: Deleting OCC device\r\nJul 21 00:52:03 barreleye system_manager.py[982]: Running System State: HOST_POWERING_ON\r\n````\r\nStep 4: Extend the watchdog timer to 300 seconds for debugging. We can see that BMC takes more than 30s to finish the jobs.\r\n````\r\nJul 21 01:29:44 barreleye system_manager.py[918]: Turn on power and boot\r\nJul 21 01:29:44 barreleye system_manager.py[918]: Running System State: HOST_POWERING_ON\r\nJul 21 01:29:44 barreleye system_manager.py[918]: Setting watchdog poll interval to: 300000\r\n = None\r\nJul 21 01:29:44 barreleye system_manager.py[918]: Starting watchdog with poll interval: 300000\r\nJul 21 01:29:46 barreleye system_manager.py[918]: Running System State: HOST_POWERED_ON\r\nftgmac100: NCSI interface down\r\nJul 21 01:29:46 barreleye system_manager.py[918]: Starting process: /usr/sbin/goto_system_state.py INVENTORY_UPLOADED inventory_upload.py: inventory_upload\r\nJul 21 01:29:46 barreleye kernel: ftgmac100: NCSI interface down\r\nJul 21 01:29:46 barreleye kernel[923]: ftgmac100: NCSI interface down\r\nftgmac100: NCSI interface up\r\nJul 21 01:29:48 barreleye kernel: ftgmac100: NCSI interface up\r\nJul 21 01:29:48 barreleye kernel[923]: ftgmac100: NCSI interface up\r\nJul 21 01:30:08 barreleye system_manager.py[918]: ERROR (name_properties): \"name\" property in /bmc/inventory/hdd_backplane is incorrect (\"BARRELEYE Exander\" instead of base node name)\r\nJul 21 01:30:08 barreleye system_manager.py[918]: ERROR (name_properties): \"name\" property in /bmc/inventory/sas_expander is incorrect (\"BARRELEYE BPx15\" instead of base node name)\r\nJul 21 01:30:08 barreleye system_manager.py[918]: ERROR (name_properties): \"name\" property in /bmc/inventory/misc is incorrect (\"BARRELEYE MB\" instead of base node name)\r\nJul 21 01:30:08 barreleye system_manager.py[918]: ERROR: Input tree has errors, aborting (use -f to force output)\r\nJul 21 01:30:09 barreleye system_manager.py[918]: Partition 'BMC_INV' not found !\r\nJul 21 01:30:09 barreleye system_manager.py[918]: Uploading inventory to PNOR in dtb format...\r\nJul 21 01:30:09 barreleye system_manager.py[918]: Running System State: INVENTORY_UPLOADED\r\nJul 21 01:30:09 barreleye system_manager.py[918]: Starting process: /usr/sbin/pcie_slot_present.exe: pcie_present\r\nJul 21 01:30:09 barreleye system_manager.py[918]: Setting fans to max\r\nJul 21 01:30:10 barreleye system_manager.py[918]: Booting host\r\nJul 21 01:30:10 barreleye system_manager.py[918]: Checking Presence: SLOT0_RISER_PRESENT\r\nJul 21 01:30:11 barreleye system_manager.py[918]: GPIO Lookup:  SLOT0_RISER_PRESENT = 424,in\r\nJul 21 01:30:11 barreleye system_manager.py[918]: Checking Presence: SLOT1_RISER_PRESENT\r\nJul 21 01:30:11 barreleye system_manager.py[918]: GPIO Lookup:  SLOT1_RISER_PRESENT = 425,in\r\nJul 21 01:30:11 barreleye system_manager.py[918]: Checking Presence: SLOT2_RISER_PRESENT\r\nJul 21 01:30:12 barreleye system_manager.py[918]: GPIO Lookup:  SLOT2_RISER_PRESENT = 426,in\r\nJul 21 01:30:12 barreleye system_manager.py[918]: Using primary side of the bios flash\r\nJul 21 01:30:12 barreleye system_manager.py[918]: Checking Presence: SLOT0_PRESENT\r\nJul 21 01:30:13 barreleye system_manager.py[918]: GPIO Lookup:  SLOT0_PRESENT = 427,in\r\nJul 21 01:30:13 barreleye system_manager.py[918]: Running System State: HOST_BOOTING\r\nJul 21 01:30:13 barreleye system_manager.py[918]: Checking Presence: SLOT1_PRESENT\r\nJul 21 01:30:13 barreleye system_manager.py[918]: GPIO Lookup:  SLOT1_PRESENT = 428,in\r\nJul 21 01:30:14 barreleye system_manager.py[918]: Checking Presence: SLOT2_PRESENT\r\nJul 21 01:30:14 barreleye system_manager.py[918]: GPIO Lookup:  SLOT2_PRESENT = 429,in\r\nJul 21 01:30:14 barreleye system_manager.py[918]: Checking Presence: MEZZ0_PRESENT\r\nJul 21 01:30:14 barreleye system_manager.py[918]: GPIO Lookup:  MEZZ0_PRESENT = 432,in\r\nJul 21 01:30:14 barreleye system_manager.py[918]: Checking Presence: MEZZ1_PRESENT\r\nJul 21 01:30:14 barreleye system_manager.py[918]: GPIO Lookup:  MEZZ1_PRESENT = 433,in\r\nJul 21 01:30:18 barreleye system_manager.py[918]: Setting watchdog poll interval to: 120000\r\nJul 21 01:30:18 barreleye system_manager.py[918]: Stopping watchdog\r\nJul 21 01:30:18 barreleye system_manager.py[918]: Starting watchdog with poll interval: 120000\r\n````"},"comment":{"url":"https://api.github.com/repos/openbmc/skeleton/issues/comments/237571202","html_url":"https://github.com/openbmc/skeleton/issues/127#issuecomment-237571202","issue_url":"https://api.github.com/repos/openbmc/skeleton/issues/127","id":237571202,"user":{"login":"anoo1","id":9052527,"avatar_url":"https://avatars.githubusercontent.com/u/9052527?v=3","gravatar_id":"","url":"https://api.github.com/users/anoo1","html_url":"https://github.com/anoo1","followers_url":"https://api.github.com/users/anoo1/followers","following_url":"https://api.github.com/users/anoo1/following{/other_user}","gists_url":"https://api.github.com/users/anoo1/gists{/gist_id}","starred_url":"https://api.github.com/users/anoo1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/anoo1/subscriptions","organizations_url":"https://api.github.com/users/anoo1/orgs","repos_url":"https://api.github.com/users/anoo1/repos","events_url":"https://api.github.com/users/anoo1/events{/privacy}","received_events_url":"https://api.github.com/users/anoo1/received_events","type":"User","site_admin":false},"created_at":"2016-08-04T14:32:10Z","updated_at":"2016-08-04T14:32:10Z","body":"From the log, the 'inventory upload' process is taking ~15 seconds to execute, so we'll move the host watchdog to start after the 'inventory upload', right before the host is initialized."}}
{"actor":{"display_login":"anoo1"}}