Percy intermittently hangs indefinitely when trying to establish logger websocket connection

[ozyx]

The problem

We are running a suite of Percy visual tests using Playwright. As we added more tests, we started noticing tests were intermittently timing out. We traced the issue back to the Percy process hanging indefinitely while trying to establish a websocket connection to a remote logger.

We have tested with and seen the same issue with Percy/cli versions 1.2.1, 1.6.4, 1.7.2, 1.10.0 and 1.10.2. We did notice that we started seeing a marked increase in timeouts as we added more visual tests and snapshots to our suites.

Environment

• Node version: v16.17.0
• @percy/cli version: 1.10.2
• percy-playwright version: 1.0.4
• Version of Percy SDK you’re using:
• If needed, a build or snapshot ID:
• OS version:
• Type of shell command-line [interface]:

Details

Debug logs

Below is the stacktrace after aborting a test hanging indefinitely (note that I ran this with the --debug flag):

     20 …› faultManagement.visual.spec.js:71:5 › The Fault Management Plugin Visual Test › ability to acknowledge or shelve
[percy:core:snapshot] --------- (6788ms)
[percy:core:snapshot] Handling snapshot: Selected faults highlight the ability to Acknowledge or Shelve above the fault list (theme: 'espresso') (0ms)
[percy:core:snapshot] - url: http://localhost:8080/#/browse/faults.taxonomy:faultManagement.view?tc.mode=fixed&tc.startBound=1663016803410&tc.endBound=1663018603410&tc.timeSystem=utc&view=faultManagement.view (0ms)
[percy:core:snapshot] - widths: 1024px, 2000px (0ms)
[percy:core:snapshot] - minHeight: 1440px (0ms)
[percy:core:snapshot] - discovery.allowedHostnames: localhost (1ms)
[percy:core:snapshot] - clientInfo: @percy/playwright/1.0.4 (0ms)
[percy:core:snapshot] - environmentInfo: @percy/playwright/1.0.4 (0ms)
[percy:core:snapshot] - domSnapshot: true (0ms)
[percy:core:page] Page created (16ms)
[percy:core:page] Resize page to 1024x1440 @1x (108ms)
[percy:core:page] Navigate to: http://localhost:8080/#/browse/faults.taxonomy:faultManagement.view?tc.mode=fixed&tc.startBound=1663016803410&tc.endBound=1663018603410&tc.timeSystem=utc&view=faultManagement.view (2ms)
[percy:core:discovery] Handling request: http://localhost:8080/ (13ms)
[percy:core:discovery] - Serving root resource (0ms)
[percy:core:discovery] Handling request: http://localhost:8080/dist/espressoTheme.css (89ms)
[percy:core:discovery] - Resource cache hit (1ms)
[percy:core:page] Page navigated (88ms)
[percy:core:network] Wait for 100ms idle (0ms)
[percy:core:page] Resize page to 2000x1440 @1x (100ms)
[percy:core:discovery] Handling request: http://localhost:8080/dist/images/logo-openmct.svg (102ms)
[percy:core:discovery] - Resource cache hit (0ms)
[percy:core:discovery] Handling request: http://localhost:8080/dist/fonts/Open-MCT-Symbols-16px.woff (1ms)
[percy:core:discovery] - Resource cache hit (0ms)
[percy:core:network] Wait for 100ms idle (80ms)
[percy:core] Snapshot taken: Selected faults highlight the ability to Acknowledge or Shelve above the fault list (theme: 'espresso') (111ms)
  ✓  20 …ltManagement.visual.spec.js:71:5 › The Fault Management Plugin Visual Test › ability to acknowledge or shelve (8s)
     21 …Clock.visual.spec.js:42:5 › Visual - Controlled Clock @localStorage › Overlay Plot Loading Indicator @localStorage
^C[percy:core] Stopping percy... (3082623ms)
[percy:core:browser] Closing browser (6ms)
[percy:utils] Unable to connect to remote logger
  ✘  21 [chrome] › controlledClock.visual.spec.js:42:5 › Visual - Controlled Clock @localStorage › Overlay Plot Loading Indicator @localStorage (51m)
    at WebSocket.ws.onclose (/work/node_modules/@percy/sdk-utils/dist/logger.js:136:16)
    at WebSocket.onClose (/work/node_modules/ws/lib/event-target.js:210:18)
    at WebSocket.emit (node:events:513:28)
    at WebSocket.emitClose (/work/node_modules/ws/lib/websocket.js:258:10)
    at Socket.socketOnClose (/work/node_modules/ws/lib/websocket.js:1258:15)
    at Socket.emit (node:events:513:28)
    at TCP.<anonymous> (node:net:757:14)
[percy:playwright] Could not take DOM snapshot "SineWaveInOverlayPlot (theme: 'espresso')"
[percy:playwright] Error: connect ECONNREFUSED 127.0.0.1:5338
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1247:16)
[percy:core:browser] Browser closed (338ms)
[percy:core] Build not created (1ms)

Code to reproduce issue

1. git clone https://github.com/nasa/openmct.git
2. git checkout percy-cli-timeout
3. cd openmct
4. Run docker container simulating our testing environment:

docker run --cpus=2 --rm --network host -v $(pwd):/work/ -w /work/ -it mcr.microsoft.com/playwright:v1.25.2-focal /bin/bash

5. npm install
6. npm run test:e2e:visual:debug

Observe that the test run eventually hangs indefinitely.

[Robdel12]

Hey @ozyx! Thanks for the report. We're currently working on removing the remote logger -- which should totally eliminate this issue.