Uploaded image for project: 'GPII - Global Public Inclusive Infrastructure'
  1. GPII - Global Public Inclusive Infrastructure
  2. GPII-3791

Race condition in LifecycleManager session

    XMLWordPrintable

    Details

    • Type: Improvement
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Lifecycle Manager
    • Labels:
      None

      Description

      We have a race condition in the LifecycleManager in that it will continue to process updates for a session which has been keyed out/"destroyed". This is exposed by the gpii-app's "PspTestDefs" at the following sequence point: https://github.com/GPII/gpii-app/blob/master/tests/PspTestDefs.js#L212
      The error was seen fairly regularly in testing our final reintegration of the gpii-app with the core at https://github.com/GPII/gpii-app/pull/100
      A failing test sequence looks as follows:

      08:42:16.147:  contextManager: Context changed from old context "bright" to new active context "gpii-default" for the GPII key: multi_context
      08:42:16.162:  PSPChannel's PSP-facing modelChangeListener, sources are []
      08:42:16.162:  Model change source is not PSP - candidate for update message
      08:42:17.533:  Registry settings handler SET returning results {
          "Magnification": {
              "oldValue": 150,
              "statusCode": 200,
              "newValue": 50
          }
      }
      08:42:19.521:  Registry settings handler SET returning results {
          "Magnification": {
              "oldValue": 50,
              "statusCode": 200,
              "newValue": 200
          }
      }
      08:42:20.774:  Test case listener has not responded after 5000ms - at sequence pos 19 of 24 sequence element {
          "event": "{that}.app.events.onKeyedOut",
          "listener": "gpii.tests.psp.testKeyedOut",
          "args": [
              "{that}.app.psp"
          ]
      } of fixture PSP integration tests
      08:42:21.670:  PSPChannel's PSP-facing modelChangeListener, sources are []
      08:42:21.670:  Model change source is not PSP - candidate for update message
      08:42:21.670:  contextManager: Successfully updated configuration triggered by context changes
      08:42:21.670:  PSPChannel sending unblocked full update message{
        "gpiiKey": "multi_context",
        "activeContextName": "bright",
        "settingControls": {
          "http://registry\\.gpii\\.net/common/magnification": {
            "value": 2,
            "schema": {
              "title": "Magnification",
              "description": "Level of magnification",
              "type": "number",
              "default": 1,
              "minimum": 1,
              "multipleOf": 0.1
            },
            "liveness": "liveRestart"
          },
          "http://registry\\.gpii\\.net/common/volume": {
            "value": 0,
            "schema": {
              "title": "Volume",
              "description": "General volume of the operating system",
              "type": "number",
              "minimum": 0,
              "maximum": 1
            },
            "liveness": "live"
          }
        },
        "preferences": {
          "name": "Multiple Contexts",
          "contexts": {
            "gpii-default": {
              "name": "Default preferences"
            },
            "bright": {
              "name": "bright"
            },
            "noise": {
              "name": "noise"
            },
            "brightandnoise": {
              "name": "bright and noise"
            }
          }
         .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderChars]
      08:42:22.380:  Registry settings handler SET returning results {
          "Magnification": {
              "oldValue": 200,
              "statusCode": 200,
              "newValue": undefined
          }
      }
      08:42:22.394:  gpiiConnect.qss: Merge QSS default settings
      08:42:22.395:  GpiiConnector: Updated preference set:{
          "path": [],
          "type": "ADD",
          "value": {
              "gpiiKey": "multi_context",
              "activeContextName": "bright",
              "settingControls": {
                  "http://registry\\.gpii\\.net/common/magnification": {
                      "value": 2,
                      "schema": {
                          "title": "Magnification",
                          "description": "Level of magnification",
                          "type": "number",
                          "default": 1,
                          "minimum": 1,
                          "multipleOf": 0.1
                      },
                      "liveness": "liveRestart",
                      "grouped": true
                  },
                  "http://registry\\.gpii\\.net/common/volume": {
                      "value": 0,
                      "schema": {
                          "title": "Volume",
                          "description": "General volume of the operating system",
                          "type": "number",
                          "minimum": 0,
                          "maximum": 1
                      },
                      "liveness": " .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderChars]
      08:42:22.410:  gpiiConnector.qss Controls to be sent: {
          "http://registry\\.gpii\\.net/common/DPIScale": {
              "value": 0
          },
          "http://registry\\.gpii\\.net/common/highContrastTheme": {
              "value": "regular-contrast"
          },
          "http://registry\\.gpii\\.net/common/selfVoicing/enabled": {
              "value": false
          },
          "http://registry\\.gpii\\.net/common/language": {
              "value": null
          }
      }
      08:42:22.738:  PSPChannel's PSP-facing modelChangeListener, sources are []
      08:42:22.738:  Model change source is not PSP - candidate for update message
      08:42:22.761:  FactsManager: Changed interactionsCount: 4
      08:42:22.763:  Writing journal file to path C:\Users\vagrant\AppData\Local\Temp/gpii/journal-2019-03-13T154208.592Z.json
      08:42:22.940:  PSPChannel's PSP-facing modelChangeListener, sources are [
          "SessionCleanup"
      ]
      08:42:22.940:  userLogonStateChange.logoutUser: Lifecycle manager returned: [
          {
              "runningOnLogin": {
                  "com.microsoft.windows.magnifier": true
              }
          },
          [
              [
                  {
                      "settings": {
                          "running": {
                              "type": "ADD",
                              "value": true
                          }
                      },
                      "type": "gpii.windows.enableRegisteredAT",
                      "options": {
                          "registryName": "magnifierpane",
                          "getState": [
                              {
                                  "type": "gpii.processReporter.find",
                                  "command": "Magnify.exe"
                              }
                          ]
                      }
                  }
              ],
              [
                  {
                      "settings": {
                          "Magnification": {
                              "type": "ADD",
                              "value": 200
                          }
                      },
                      "type": "gpii.windows.registrySettingsHandler",
                      "livenes .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderChars]
      08:42:22.944:  UserLogonRequest completes successfully with the payload: User with GPII key multi_context was successfully logged out.
      08:42:22.956:  User with GPII key multi_context has no active session, so ignoring update request
      08:42:22.975:  Settings for session bfio7gdu-10643 created at undefined updated to {
          "com.microsoft.windows.magnifier": {
              "name": "Windows Built-in Screen Magnifier",
              "capabilities": [
                  "http://registry\\.gpii\\.net/common/magnification/enabled"
              ],
              "settingsHandlers": {
                  "configure": {
                      "type": "gpii.windows.registrySettingsHandler",
                      "liveness": "liveRestart",
                      "options": {
                          "hKey": "HKEY_CURRENT_USER",
                          "path": "Software\\Microsoft\\ScreenMagnifier",
                          "dataTypes": {
                              "Magnification": "REG_DWORD",
                              "Invert": "REG_DWORD",
                              "FollowFocus": "REG_DWORD",
                              "FollowCaret": "REG_DWORD",
                              "FollowMouse": "REG_DWORD",
                              "MagnificationMode": "REG_DWORD",
                              "ZoomIncrement": "REG_DWORD"
                          }
                      },
                      "supportedSettings": {
                          "Inver .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderChars]
      08:42:22.977:  FATAL ERROR: Uncaught exception: Invalid time value
      RangeError: Invalid time value
          at Date.toISOString (<anonymous>)
          at Function.gpii.journal.formatTimestamp (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\journal\src\JournalIdParser.js:105:22)
          at gpii.journal.writeJournal (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\journal\src\Journal.js:204:46)
          at invokeInvoker (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidIoC.js:1742:29)
          at togo (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidIoC.js:1806:33)
          at fire (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\Fluid.js:1568:40)
          at Object.fluid.event.invokeListener (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1184:25)
          at togo (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1199:25)
          at Object.fluid.model.notifyExternal (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1066:33)
          at concludeTransaction (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1136:29)
          at Object.fire (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\Fluid.js:1568:40)
          at Object.commit (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1713:41)
          at fluid.ChangeApplier.that.fireChangeRequest (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1679:19)
          at fluid.ChangeApplier.that.change (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\DataBinding.js:1591:18)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\contextManager\src\ContextManager.js:197:31)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at \\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\lifecycleManager\src\LifecycleManager.js:1125:26
          at Object.that.then (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:33:21)
          at gpii.lifecycleManager.processActionQueue (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\lifecycleManager\src\LifecycleManager.js:1123:17)
          at fluid.componentConstructor.invokeInvoker [as processActionQueue] (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidIoC.js:1742:29)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\lifecycleManager\src\LifecycleManager.js:1130:22)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:163:26)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at \\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35
          at Object.that.then (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:33:21)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:168:23)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at \\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35
          at Object.that.then (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:33:21)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:168:23)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:163:26)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at \\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35
          at Object.that.then (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:33:21)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:168:23)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:163:26)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\gpii-universal\gpii\node_modules\lifecycleManager\src\LifecycleManager.js:657:18)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\gpii-windows\gpii\node_modules\registeredAT\registeredAT.js:160:21)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at Function.fluid.promise.resumeSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:163:26)
          at Function.fluid.promise.progressSequence (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:149:23)
          at Array.<anonymous> (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:169:35)
          at Object.that.complete (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:70:25)
          at Object.that.resolve (\\vboxsvr\vagrant\node_modules\infusion\src\framework\core\js\FluidPromises.js:52:22)
          at \\vboxsvr\vagrant\node_modules\gpii-windows\gpii\node_modules\registeredAT\registeredAT.js:121:29
          at ChildProcess.exithandler (child_process.js:294:7)
          at ChildProcess.emit (events.js:182:13)
          at maybeClose (internal/child_process.js:961:16)
          at Process.ChildProcess._handle.onexit (internal/child_process.js:248:5)
      08:42:22.979:  Current activity: 
          while invoking invoker with name writeJournal and record {
          "func": undefined,
          "funcName": "gpii.journal.writeJournal",
          "listener": undefined,
          "this": undefined,
          "method": undefined,
          "changePath": undefined,
          "value": undefined,
          "args": {
              "value": "NO_VALUE"
          },
          "componentSource": "gpii.journal"
      } from path serverEnvironment-bfio7gdu-10382,tests,configuration,server,localConfig,server,flowManager,journal holding component {
          "typeName": "gpii.journal",
          "id": "bfio7gdu-11042",
          "lifecycleStatus": "treeConstructed",
          "destroy": { Function
              
          },
          "options": {
              "gradeNames": [
                  "gpii.journal",
                  "gpii.journalLifecycleManager",
                  "fluid.component",
                  "kettle.app",
                  "gpii.journalApp"
              ],
              "invokers": {
                  "readJournals": {
                      "funcName": "gpii.journal.readJournals",
                      "args": [
                          "{that}"
                      ],
                      "componentSource": "gpii.journal"
                  },
                  "writeJournal": {
                      "funcName": "gpii.journal.writeJournal",
       .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderChars]
          while firing to listener to event named {lifecycleManager}.events.onSessionSnapshotUpdate of component {
      

      Note that there is evidence of faulty processing before the actual failure with the line

      08:42:22.975:  Settings for session bfio7gdu-10643 created at undefined updated to {
      
      • the fact that the createTime is reported as "undefined" indicates that the system is in an invalid state - it is attempting to process a settings update for a session which is not active. If we represented this condition by actually destroying the session component as we had planned in the original refactoring, this would be architecturally much clearer, and we could perform checks via fluid.isDestroyed() rather than some ad hoc mechanism.

      The test sequence has been as follows -

      i) Perform a preference set change
      ii) When receiving this, immediately key out

      Depending on the exact processing sequence, we may be partway through processing the resulting settings update messages at the key out point.

        Attachments

          Activity

            People

            Assignee:
            cli@ocad.ca Cindy Qi Li
            Reporter:
            amb26 Antranig Basman
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated: