Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-36823

On low power vagrant VMs quick and repeated updates to handlers can cause tempStore and UI to go out of sync

    XMLWordPrintable

Details

    Description

      Build: 6.5.0-4778

      While testing MB-35455 , i was pausing -> updating -> resume curl handler. Then i hit a state where i can not resumed paused handler with error

      2019-11-08T00:48:31.433-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request 

      Handler state

      http://10.143.192.102:8096/api/v1/status
       
       
      {
          "apps": [
              {
                  "composite_status": "paused",
                  "name": "curl",
                  "num_bootstrapping_nodes": 0,
                  "num_deployed_nodes": 1,
                  "deployment_status": true,
                  "processing_status": false
              }
          ],
          "num_eventing_nodes": 1
      } 

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          jeelan.poola Jeelan Poola added a comment -

          This is on a low power vagrant VM and when things are attempted at quick succession. A corresponding UI refresh may have shown that the handler is actually deployed. Will go over the logs just in case something is amiss.

          jeelan.poola Jeelan Poola added a comment - This is on a low power vagrant VM and when things are attempted at quick succession. A corresponding UI refresh may have shown that the handler is actually deployed. Will go over the logs just in case something is amiss.
          jeelan.poola Jeelan Poola added a comment - - edited

          This is very likely a case of requiring a UI refresh to reflect the correct state of the handler and hence showing correct set of buttons on the UI. As we can see from the logs below which capture the time line of various life cycle operations that have happened on the handler named curl, the errors were thrown when the app was in deployed stated which is expected. Lowering the priority of this MB and deferring to CC. Please let me know if there is a real issue here.

          2019-11-08T00:18:41.619-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl Begin undeploy process. Current state: 1
          2019-11-08T00:18:41.619-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl undeployment done
          2019-11-08T00:19:56.957-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl begin deployment process
          2019-11-08T00:22:45.018-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:23:55.799-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl Begin undeploy process. Current state: 2
          2019-11-08T00:24:15.392-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl undeployment done
          2019-11-08T00:25:08.483-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl begin deployment process
          2019-11-08T00:29:41.057-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:31:26.871-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process
          2019-11-08T00:31:26.871-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:34:39.227-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process
          2019-11-08T00:34:39.227-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:35:17.605-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process
          2019-11-08T00:35:17.605-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:40:15.422-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin pausing process
          2019-11-08T00:40:55.361-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process
          2019-11-08T00:42:23.089-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
          2019-11-08T00:44:07.875-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin pausing process
          2019-11-08T00:44:27.239-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process
          2019-11-08T00:46:55.783-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done
           
           
          2019-11-08T00:47:39.482-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request
          2019-11-08T00:48:07.663-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request
          2019-11-08T00:48:31.433-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request
          

          Also a subsequent undeploy-->deploy worked fine as well.

          There seems to be a potential possibility where lots of updates to handler in quick succession can cause tempStore to have config values which are different from the actual status of the handler in the backend. However this is more of a negative test and possibility of occurring in the field should be rare.

          jeelan.poola Jeelan Poola added a comment - - edited This is very likely a case of requiring a UI refresh to reflect the correct state of the handler and hence showing correct set of buttons on the UI. As we can see from the logs below which capture the time line of various life cycle operations that have happened on the handler named curl , the errors were thrown when the app was in deployed stated which is expected. Lowering the priority of this MB and deferring to CC. Please let me know if there is a real issue here. 2019-11-08T00:18:41.619-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl Begin undeploy process. Current state: 1 2019-11-08T00:18:41.619-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl undeployment done 2019-11-08T00:19:56.957-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl begin deployment process 2019-11-08T00:22:45.018-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:23:55.799-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl Begin undeploy process. Current state: 2 2019-11-08T00:24:15.392-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl undeployment done 2019-11-08T00:25:08.483-08:00 [Info] SuperSupervisor::SettingsChangeCallback [0] Function: curl begin deployment process 2019-11-08T00:29:41.057-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:31:26.871-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process 2019-11-08T00:31:26.871-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:34:39.227-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process 2019-11-08T00:34:39.227-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:35:17.605-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process 2019-11-08T00:35:17.605-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:40:15.422-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin pausing process 2019-11-08T00:40:55.361-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process 2019-11-08T00:42:23.089-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done 2019-11-08T00:44:07.875-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin pausing process 2019-11-08T00:44:27.239-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl begin deployment process 2019-11-08T00:46:55.783-08:00 [Info] SuperSupervisor::SettingsChangeCallback [1] Function: curl deployment done     2019-11-08T00:47:39.482-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request 2019-11-08T00:48:07.663-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request 2019-11-08T00:48:31.433-08:00 [Error] ServiceMgr::savePrimaryStore Function: curl another function with same name is already deployed, skipping save request Also a subsequent undeploy-->deploy worked fine as well. There seems to be a potential possibility where lots of updates to handler in quick succession can cause tempStore to have config values which are different from the actual status of the handler in the backend. However this is more of a negative test and possibility of occurring in the field should be rare.

          seen again on 6.5.0-4797

          vikas.chaudhary Vikas Chaudhary added a comment - seen again on 6.5.0-4797
          jeelan.poola Jeelan Poola added a comment -

          Proposing to move to CC.Next to keep the focus on Collections in CC.

          jeelan.poola Jeelan Poola added a comment - Proposing to move to CC.Next to keep the focus on Collections in CC.

          People

            suraj.naik Suraj Naik (Inactive)
            vikas.chaudhary Vikas Chaudhary
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty