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

Continued possibility for acceptance test failure due to interaction of Cursor and Contrast settings on Windows

    XMLWordPrintable

    Details

      Description

      This interaction has been a bugbear for some years - the node 0.10.x upgrade work for GPII-94 worsened this problem and it was partially resolved with the retrying settings handler implemented in this branch. However, several possible routes to failure seem to remain.

      http://lists.gpii.net/pipermail/architecture/2014-November/002861.html

      As time passes, we understand these issues better and better. The core cause of failure seems to be related to the fact that on a Desktop Theme change, Windows will kick of an asynchronous process to rewrite the Windows Registry keys relating to the cursors defined by that theme. This causes a huge potential for differing race conditions with respect to our own asynchronous process which is usually trying to read/write exactly the same registry keys. Here is a recent failed transcript which shows a test failure due to the fact that the snapshotting done by the test fixture itself lost a race against the reset process from the previous test which was still being serviced by Windows:

      15:15:22.139:  Initializing the Express app
      15:15:22.139:  Initializing the HTTP server.
      15:15:24.311:  Initializing the socket.io.
         info  - socket.io started
      15:15:24.327:  Opening Kettle Server on port 8081
      15:15:24.389:  Kettle Server 6sp17r48-1641 is listening on port 8081
      15:15:24.389:  Registry settings handler GET returning results {
          "Magnification": 150,
          "MagnificationMode": 3
      }
      15:15:24.452:  Registry settings handler GET returning results {
          "No": "%SystemRoot%\\cursors\\aero_unavail.cur",
          "Hand": "%SystemRoot%\\cursors\\aero_link.cur",
          "Help": "%SystemRoot%\\cursors\\aero_helpsel.cur",
          "Wait": "%SystemRoot%\\cursors\\aero_busy.ani",
          "Arrow": "%SystemRoot%\\cursors\\aero_arrow.cur",
          "NWPen": "%SystemRoot%\\cursors\\aero_pen.cur",
          "SizeNS": "%SystemRoot%\\cursors\\aero_ns.cur",
          "SizeWE": "%SystemRoot%\\cursors\\aero_ew.cur",
          "SizeAll": "%SystemRoot%\\cursors\\aero_move.cur",
          "UpArrow": "%SystemRoot%\\cursors\\aero_up.cur",
          "SizeNESW": "%SystemRoot%\\cursors\\aero_nesw.cur",
          "SizeNWSE": "%SystemRoot%\\cursors\\aero_nwse.cur",
          "AppStarting": "%SystemRoot%\\cursors\\aero_working.ani"
      }
      15:15:24.499:  Sending a GET request to: /user/os_gnome/login on port 8081
      15:15:24.530:  Clearing cache for component kettle.requests.request.evented with gradeNames [
          "kettle.requests.request.evented",
          "fluid.eventedComponent",
          "fluid.littleComponent",
          "autoInit"
      ]
      15:15:24.561:  Clearing cache for component kettle.requests.request.http with gradeNames [
          "kettle.requests.request.evented",
          "fluid.eventedComponent",
          "fluid.littleComponent",
          "kettle.requests.request.http",
          "kettle.requests.request",
          "fluid.applyGradeLinkage",
          "{requests}.eventedRequestGrade",
          "autoInit"
      ]
      15:15:24.702:  gpii.request.flowManager.getPreferences called - fetching preferences
      15:15:24.796:  gpii.request.flowManager.getDevice called - fetching device info
      15:15:25.468:  Fetched device reporter data: {
          "solutions": [
              {
                  "id": "com.microsoft.windows.magnifier"
              },
              {
                  "id": "com.microsoft.windows.onscreenKeyboard"
              },
              {
                  "id": "com.microsoft.windows.highContrast"
              },
              {
                  "id": "com.microsoft.windows.mouseTrailing"
              },
              {
                  "id": "com.microsoft.windows.cursors"
              }
          ],
          "OS": {
              "id": "win32",
              "version": "6.1.7600"
          }
      }
      15:15:25.546:  Fetched raw user preferences: {
          "userToken": "os_gnome",
          "preferences": {
              "flat": {
                  "contexts": {
                      "gpii-default": {
                          "name": "Default preferences",
                          "preferences": {
                              "http://registry.gpii.net/applications/org.gnome.desktop.a11y.magnifier": {
                                  "mag-factor": 1.5,
                                  "screen-position": "full-screen"
                              },
                              "http://registry.gpii.net/applications/org.gnome.desktop.interface": {
                                  "cursor-size": 90,
                                  "text-scaling-factor": 0.75
                              },
                              "http://registry.gpii.net/applications/org.alsa-project": {
                                  "masterVolume": 50
                              }
                          }
                      }
                  }
              }
          }
      }
      15:15:25.702:  Raw preferences fetched by preferencesServer: [object Object]
      15:15:25.733:  Fetched user preferences: {
          "contexts": {
              "gpii-default": {
                  "name": "Default preferences",
                  "preferences": {
                      "http://registry.gpii.net/applications/org.gnome.desktop.a11y.magnifier": {
                          "mag-factor": 1.5,
                          "screen-position": "full-screen"
                      },
                      "http://registry.gpii.net/applications/org.gnome.desktop.interface": {
                          "cursor-size": 90,
                          "text-scaling-factor": 0.75
                      },
                      "http://registry.gpii.net/applications/org.alsa-project": {
                          "masterVolume": 50
                      }
                  }
              }
          }
      }
      15:15:26.577:  Fetched solutions registry: {
          "com.microsoft.windows.magnifier": {
              "name": "Windows Built-in Screen Magnifier",
              "contexts": {
                  "OS": [
                      {
                          "id": "win32",
                          "version": ">=5.0"
                      }
                  ]
              },
              "settingsHandlers": [
                  {
                      "type": "gpii.windows.registrySettingsHandler",
                      "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"
                          }
                      },
                      "capabili .... [output suppressed at 1024 chars - for more output, increase fluid.logObj
      ectRenderChars]
      15:15:26.686:  MatchMaker Framework: dispatching to the flat MatchMaker
      Returned from MM
      gpii.request.flowManager.runContextManager
      gpii.contextManager.evaluateMatch called
      !!!!! about to write registry key HKEY_CURRENT_USER path Software\Microsoft\ScreenMagnifier subKey Magni
      fication value 150
      !!!!! about to write registry key HKEY_CURRENT_USER path Software\Microsoft\ScreenMagnifier subKey Magni
      ficationMode value 2
      15:15:27.155:  Registry settings handler SET returning results {
          "Magnification": {
              "oldValue": 150,
              "statusCode": 200,
              "newValue": 150
          },
          "MagnificationMode": {
              "oldValue": 3,
              "statusCode": 200,
              "newValue": 2
          }
      }
      15:15:27.202:  Registry settings handler GET returning results {
          "Magnification": 150,
          "MagnificationMode": 2
      }
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey No value %SystemRo
      ot%\cursors\aero_unavail_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Hand value %System
      Root%\cursors\aero_link_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Help value %System
      Root%\cursors\aero_helpsel_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Wait value %System
      Root%\cursors\aero_busy_xl.ani
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Arrow value %Syste
      mRoot%\cursors\aero_arrow_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey NWPen value %Syste
      mRoot%\cursors\aero_pen_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNS value %Syst
      emRoot%\cursors\aero_ns_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeWE value %Syst
      emRoot%\cursors\aero_ew_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeAll value %Sys
      temRoot%\cursors\aero_move_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey UpArrow value %Sys
      temRoot%\cursors\aero_up_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNESW value %Sy
      stemRoot%\cursors\aero_nesw_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNWSE value %Sy
      stemRoot%\cursors\aero_nwse_xl.cur
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey AppStarting value
      %SystemRoot%\cursors\aero_working_xl.ani
      15:15:27.843:  Registry settings handler SET returning results {
          "No": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_unavail_xl.cur"
          },
          "Hand": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_link_xl.cur"
          },
          "Help": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_helpsel_xl.cur"
          },
          "Wait": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_busy_xl.ani"
          },
          "Arrow": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_arrow_xl.cur"
          },
          "NWPen": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_pen_xl.cur"
          },
          "SizeNS": {
              "oldValue": undefined,
              "statusCode": 200,
              "newValue": "%SystemRoot%\\cursors\\aero_ns_xl.cur"
          },
          "SizeWE": {
              "oldV .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderCha
      rs]
      15:15:28.014:  Registry settings handler GET returning results {
          "No": "%SystemRoot%\\cursors\\aero_unavail_xl.cur",
          "Hand": "%SystemRoot%\\cursors\\aero_link_xl.cur",
          "Help": "%SystemRoot%\\cursors\\aero_helpsel_xl.cur",
          "Wait": "%SystemRoot%\\cursors\\aero_busy_xl.ani",
          "Arrow": "%SystemRoot%\\cursors\\aero_arrow_xl.cur",
          "NWPen": "%SystemRoot%\\cursors\\aero_pen_xl.cur",
          "SizeNS": "%SystemRoot%\\cursors\\aero_ns_xl.cur",
          "SizeWE": "%SystemRoot%\\cursors\\aero_ew_xl.cur",
          "SizeAll": "%SystemRoot%\\cursors\\aero_move_xl.cur",
          "UpArrow": "%SystemRoot%\\cursors\\aero_up_xl.cur",
          "SizeNESW": "%SystemRoot%\\cursors\\aero_nesw_xl.cur",
          "SizeNWSE": "%SystemRoot%\\cursors\\aero_nwse_xl.cur",
          "AppStarting": "%SystemRoot%\\cursors\\aero_working_xl.ani"
      }
      15:15:28.108:  Lifecycle manager returned: true
      15:15:28.139:  Registry settings handler GET returning results {
          "Magnification": 150,
          "MagnificationMode": 2
      }
      15:15:28.327:  Registry settings handler GET returning results {
          "No": "%SystemRoot%\\cursors\\aero_unavail_xl.cur",
          "Hand": "%SystemRoot%\\cursors\\aero_link_xl.cur",
          "Help": "%SystemRoot%\\cursors\\aero_helpsel_xl.cur",
          "Wait": "%SystemRoot%\\cursors\\aero_busy_xl.ani",
          "Arrow": "%SystemRoot%\\cursors\\aero_arrow_xl.cur",
          "NWPen": "%SystemRoot%\\cursors\\aero_pen_xl.cur",
          "SizeNS": "%SystemRoot%\\cursors\\aero_ns_xl.cur",
          "SizeWE": "%SystemRoot%\\cursors\\aero_ew_xl.cur",
          "SizeAll": "%SystemRoot%\\cursors\\aero_move_xl.cur",
          "UpArrow": "%SystemRoot%\\cursors\\aero_up_xl.cur",
          "SizeNESW": "%SystemRoot%\\cursors\\aero_nesw_xl.cur",
          "SizeNWSE": "%SystemRoot%\\cursors\\aero_nwse_xl.cur",
          "AppStarting": "%SystemRoot%\\cursors\\aero_working_xl.ani"
      }
      15:15:28.421:  Executing: tasklist /fi "STATUS eq RUNNING" /FI "IMAGENAME eq Magnify.exe" | find /I "Mag
      nify.exe" /C
      15:15:29.874:  Sending a GET request to: /user/os_gnome/logout on port 8081
      !!!!! about to write registry key HKEY_CURRENT_USER path Software\Microsoft\ScreenMagnifier subKey Magni
      fication value 150
      !!!!! about to write registry key HKEY_CURRENT_USER path Software\Microsoft\ScreenMagnifier subKey Magni
      ficationMode value 3
      15:15:29.952:  Registry settings handler SET returning results {
          "Magnification": {
              "oldValue": 150,
              "statusCode": 200,
              "newValue": 150
          },
          "MagnificationMode": {
              "oldValue": 2,
              "statusCode": 200,
              "newValue": 3
          }
      }
      15:15:29.968:  Registry settings handler GET returning results {
          "Magnification": 150,
          "MagnificationMode": 3
      }
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey No value undefined
      
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Hand value undefin
      ed
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Help value undefin
      ed
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Wait value undefin
      ed
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey Arrow value undefi
      ned
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey NWPen value undefi
      ned
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNS value undef
      ined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeWE value undef
      ined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeAll value unde
      fined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey UpArrow value unde
      fined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNESW value und
      efined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey SizeNWSE value und
      efined
      !!!!! about to write registry key HKEY_CURRENT_USER path Control Panel\Cursors subKey AppStarting value
      undefined
      15:15:30.343:  Registry settings handler SET returning results {
          "No": {
              "oldValue": "%SystemRoot%\\cursors\\aero_unavail_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "Hand": {
              "oldValue": "%SystemRoot%\\cursors\\aero_link_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "Help": {
              "oldValue": "%SystemRoot%\\cursors\\aero_helpsel_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "Wait": {
              "oldValue": "%SystemRoot%\\cursors\\aero_busy_xl.ani",
              "statusCode": 200,
              "newValue": undefined
          },
          "Arrow": {
              "oldValue": "%SystemRoot%\\cursors\\aero_arrow_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "NWPen": {
              "oldValue": "%SystemRoot%\\cursors\\aero_pen_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "SizeNS": {
              "oldValue": "%SystemRoot%\\cursors\\aero_ns_xl.cur",
              "statusCode": 200,
              "newValue": undefined
          },
          "SizeWE": {
              "oldV .... [output suppressed at 1024 chars - for more output, increase fluid.logObjectRenderCha
      rs]
      15:15:30.530:  Registry settings handler GET returning results {
          "No": undefined,
          "Hand": undefined,
          "Help": undefined,
          "Wait": undefined,
          "Arrow": undefined,
          "NWPen": undefined,
          "SizeNS": undefined,
          "SizeWE": undefined,
          "SizeAll": undefined,
          "UpArrow": undefined,
          "SizeNESW": undefined,
          "SizeNWSE": undefined,
          "AppStarting": undefined
      }
      15:15:30.608:  Lifecycle manager returned: true
      15:15:30.624:  Executing: tasklist /fi "STATUS eq RUNNING" /FI "IMAGENAME eq Magnify.exe" | find /I "Mag
      nify.exe" /C
      15:15:31.693:  Registry settings handler GET returning results {
          "Magnification": 150,
          "MagnificationMode": 3
      }
      15:15:31.724:  Registry settings handler GET returning results {
          "No": undefined,
          "Hand": undefined,
          "Help": undefined,
          "Wait": undefined,
          "Arrow": undefined,
          "NWPen": undefined,
          "SizeNS": undefined,
          "SizeWE": undefined,
          "SizeAll": undefined,
          "UpArrow": undefined,
          "SizeNESW": undefined,
          "SizeNWSE": undefined,
          "AppStarting": undefined
      }
      15:15:31.803:  jq: FAIL: Module "acceptanceTests.windows.builtIn tests" Test name "Testing os_gnome usin
      g Flat matchmaker" - Message: Checking that settings are properly reset - at sequence position 14 of 16
      15:15:31.803:  jq: Expected: {
          "gpii.windows.registrySettingsHandler": {
              "some.app.id": [
                  {
                      "settings": {
                          "Magnification": 150,
                          "MagnificationMode": 3
                      }
                  },
                  {
                      "settings": {
                          "No": "%SystemRoot%\\cursors\\aero_unavail.cur",
                          "Hand": "%SystemRoot%\\cursors\\aero_link.cur",
                          "Help": "%SystemRoot%\\cursors\\aero_helpsel.cur",
                          "Wait": "%SystemRoot%\\cursors\\aero_busy.ani",
                          "Arrow": "%SystemRoot%\\cursors\\aero_arrow.cur",
                          "NWPen": "%SystemRoot%\\cursors\\aero_pen.cur",
                          "SizeNS": "%SystemRoot%\\cursors\\aero_ns.cur",
                          "SizeWE": "%SystemRoot%\\cursors\\aero_ew.cur",
                          "SizeAll": "%SystemRoot%\\cursors\\aero_move.cur",
                          "UpArrow": "%SystemRoot%\\cursors\\aero_up.cur",
                          "SizeNESW": "%SystemRoot%\\cursors\ .... [output suppressed at 1024 chars - for more
       output, increase fluid.logObjectRenderChars]
      15:15:31.896:  jq: Actual: {
          "gpii.windows.registrySettingsHandler": {
              "some.app.id": [
                  {
                      "settings": {
                          "Magnification": 150,
                          "MagnificationMode": 3
                      }
                  },
                  {
                      "settings": {
                          "No": undefined,
                          "Hand": undefined,
                          "Help": undefined,
                          "Wait": undefined,
                          "Arrow": undefined,
                          "NWPen": undefined,
                          "SizeNS": undefined,
                          "SizeWE": undefined,
                          "SizeAll": undefined,
                          "UpArrow": undefined,
                          "SizeNESW": undefined,
                          "SizeNWSE": undefined,
                          "AppStarting": undefined
                      }
                  }
              ]
          }
      }
      15:15:32.021:  jq: Source:     at Object.jsUnitCompat.assertDeepEq (C:\Source\gits\gpii\node_modules\uni
      versal\node_modules\infusion\tests\test-core\jqUnit\js\jqUnit.js:167:19)
          at gpii.test.checkRestoredConfiguration (C:\Source\gits\gpii\node_modules\universal\gpii\node_module
      s\testing\src\Testing.js:77:12)
          at Object.execute (C:\Source\gits\gpii\node_modules\universal\node_modules\infusion\tests\test-core\
      utils\js\IoCTestUtils.js:265:26)
          at Object.fluid.test.execExecutor (C:\Source\gits\gpii\node_modules\universal\node_modules\infusion\
      tests\test-core\utils\js\IoCTestUtils.js:424:18)
          at that.execute (C:\Source\gits\gpii\node_modules\universal\node_modules\infusion\tests\test-core\ut
      ils\js\IoCTestUtils.js:512:32)
          at C:\Source\gits\gpii\node_modules\universal\node_modules\infusion\tests\test-core\utils\js\IoCTest
      Utils.js:303:13
          at wrapped (C:\Source\gits\gpii\node_modules\universal\node_modules\infusion\tests\test-core\utils\j
      s\IoCTestUtils.js:314:17)
          at fireToListeners (C:\Source\gits\gpii\node_module .... [output suppressed at 1024 chars - for more
       output, increase fluid.logObjectRenderChars]
      15:15:32.068:  Stopping Kettle Server 6sp17r48-1641 on port 8081
      15:15:32.084:  Kettle Server 6sp17r48-1641 on port 8081 is stopped
      15:15:32.099:  jq: Test concluded - Module "acceptanceTests.windows.builtIn tests" Test name "Testing os
      _gnome using Flat matchmaker": 5/6 passed - FAIL
      15:15:32.131:  jq: ***************
      15:15:32.131:  jq: All tests concluded: 17/18 total passed in 37649ms - FAIL
      15:15:32.131:  jq: ***************
      

      In this case the behaviour of the actual system is correct - it is just that Windows resetting processing intervenes between the test case's snapshot and the architecture's snapshot, causing them to diverge.

      The "failed transcript" from the GPII-94 work shows a variant of this process which used to be able to cause a real failure due to the Windows reset overlapping with our own reset http://piratepad.net/failed-transcript - this kind of failure is no longer possible due to the retrying architecture.

      Earlier today I observed a yet further failure mode which triggered a hard error from windows.writeRegistryKey which was trying to write to a cursor key which had been entirely eliminated as a result of the user's theme being a default theme which had no cursors area at all. I'm unable to reproduce this now - but there is a bug in the code which handles this case - the line
      if (value === undefined && cr === 2) {
      should in fact read
      if (value === undefined && code2 === 2) {

      We can fix up our tests to guard against one more cause of failure - by using the settings handler snapshot rather than our own independent one - at the cost of coupling our tests more closely to the real architecture.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              kasper Kasper Markus
              Reporter:
              amb26 Antranig Basman
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: