empiricaly / empirica

Open source project to tackle the problem of long development cycles required to produce software to conduct multi-participant and real-time human experiments online.
https://empirica.ly/
Apache License 2.0
44 stars 8 forks source link

New `Invalid WebSocket frame` error in `1.8.10` #461

Closed aliciamchen closed 5 months ago

aliciamchen commented 9 months ago

Is there an existing issue for this?

What happened?

I get a fatal error that crashes my experiment, that I haven't seen before with previous versions. This error is more frequent (i.e. every time I've deployed the experiment, within the first 10 minutes) and prevents me from essentially collecting any data at all. Like with previous errors, I am not able to redeploy my experiment until after I get rid of the tajriba.json file.

Steps To Reproduce

No response

Empirica Version

Version: v1.8.10
SHA:     ea74918
Build:   151
Branch:  main
Time:    2023-12-10T08:41:25Z

What OS are you seeing the problem on?

macOS

What browser are you seeing the problem on?

Does not apply

Relevant log output

Error: Unhandled error. (Invalid WebSocket frame: invalid status code 1006)
    at Bue.Ot.emit (/tmp/69b85f8d2d33cc16/node_modules/@empirica/tajriba/src/events.js:146:14)
    at error (/tmp/69b85f8d2d33cc16/node_modules/@empirica/tajriba/src/tajriba.ts:332:9)
    at Object.emit (/tmp/69b85f8d2d33cc16/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ge.de.onerror (/tmp/69b85f8d2d33cc16/node_modules/graphql-ws/lib/client.mjs:162:47)
    at kf (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:290:14)
    at Ge.n (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:230:9)
    at Ge.emit (node:events:513:28)
    at k9.Wz (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/websocket.js:1183:13)
    at k9.emit (node:events:525:35)
    at emitErrorNT (node:internal/streams/destroy:157:8) {
  context: M1 {
    [Symbol(kTarget)]: <ref *2> Ge {
      _events: [Object: null prototype] {
        error: [Function: n] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: n] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: n] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: n] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        }
      },
      _eventsCount: 4,
      _maxListeners: undefined,
      _binaryType: 'nodebuffer',
      _closeCode: 1006,
      _closeFrameReceived: false,
      _closeFrameSent: false,
      _closeMessage: Buffer(0) [Uint8Array] [],
      _closeTimer: null,
      _extensions: {
        'permessage-deflate': <ref *1> g9 {
          _maxPayload: 104857600,
          _options: {},
          _threshold: 1024,
          _isServer: false,
          _deflate: DeflateRaw {
            _writeState: [Uint32Array],
            _readableState: [ReadableState],
            _events: [Object: null prototype],
            _eventsCount: 2,
            _maxListeners: undefined,
            _writableState: [WritableState],
            allowHalfOpen: true,
            bytesWritten: 7083398,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 6136,
            _chunkSize: 16384,
            _defaultFlushFlag: 0,
            _finishFlushFlag: 4,
            _defaultFullFlushFlag: 3,
            _info: undefined,
            _maxOutputLength: 4294967296,
            _level: -1,
            _strategy: 0,
            [Symbol(kCapture)]: false,
            [Symbol(kCallback)]: null,
            [Symbol(kError)]: null,
            [Symbol(total-length)]: 0,
            [Symbol(buffers)]: [],
            [Symbol(callback)]: null
          },
          _inflate: InflateRaw {
            _writeState: [Uint32Array],
            _readableState: [ReadableState],
            _events: [Object: null prototype],
            _eventsCount: 3,
            _maxListeners: undefined,
            _writableState: [WritableState],
            allowHalfOpen: true,
            bytesWritten: 45480858,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 1846,
            _chunkSize: 16384,
            _defaultFlushFlag: 0,
            _finishFlushFlag: 4,
            _defaultFullFlushFlag: 3,
            _info: undefined,
            _maxOutputLength: 4294967296,
            _level: -1,
            _strategy: 0,
            [Symbol(kCapture)]: false,
            [Symbol(kCallback)]: null,
            [Symbol(kError)]: null,
            [Symbol(permessage-deflate)]: [Circular *1],
            [Symbol(total-length)]: 0,
            [Symbol(buffers)]: [],
            [Symbol(callback)]: [Function (anonymous)]
          },
          params: [Object: null prototype] {
            server_no_context_takeover: true,
            client_no_context_takeover: true
          }
        }
      },
      _paused: false,
      _protocol: 'graphql-transport-ws',
      _readyState: 2,
      _receiver: k9 {
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: true,
          ending: true,
          ended: true,
          finished: false,
          destroyed: true,
          decodeStrings: true,
          defaultEncoding: 'utf8',
          length: 0,
          writing: false,
          corked: 0,
          sync: false,
          bufferProcessing: false,
          onwrite: [Function: bound onwrite],
          writecb: null,
          writelen: 0,
          afterWriteTickInfo: null,
          buffered: [],
          bufferedIndex: 0,
          allBuffers: true,
          allNoop: true,
          pendingcb: 0,
          constructed: true,
          prefinished: false,
          errorEmitted: true,
          emitClose: true,
          autoDestroy: true,
          errored: RangeError: Invalid WebSocket frame: invalid status code 1006
              at k9.controlMessage (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:592:18)
              at k9.getData (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:466:42)
              at k9.startLoop (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:172:22)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:185:18)
              at node:internal/process/task_queues:141:7
              at AsyncResource.runInAsyncScope (node:async_hooks:203:9)
              at AsyncResource.runMicrotask (node:internal/process/task_queues:138:8)
              at processTicksAndRejections (node:internal/process/task_queues:96:5) {
            code: 'WS_ERR_INVALID_CLOSE_CODE',
            [Symbol(status-code)]: 1002
          },
          closed: true,
          closeEmitted: false,
          [Symbol(kOnFinished)]: []
        },
        _events: [Object: null prototype] {
          conclude: [Function: Vz],
          drain: [Function: Uz],
          error: [ [Function: Wz], [Function: $k] ],
          message: [Function: $z],
          ping: [Function: Gz],
          pong: [Function: zz],
          finish: [Function: $k]
        },
        _eventsCount: 7,
        _maxListeners: undefined,
        _allowMultipleEventsPerMicrotask: false,
        _binaryType: 'nodebuffer',
        _extensions: {
          'permessage-deflate': <ref *1> g9 {
            _maxPayload: 104857600,
            _options: {},
            _threshold: 1024,
            _isServer: false,
            _deflate: [DeflateRaw],
            _inflate: [InflateRaw],
            params: [Object: null prototype]
          }
        },
        _isServer: false,
        _maxPayload: 104857600,
        _skipUTF8Validation: false,
        _bufferedBytes: 0,
        _buffers: [],
        _compressed: true,
        _payloadLength: 20,
        _mask: undefined,
        _fragmented: 0,
        _masked: false,
        _fin: true,
        _opcode: 8,
        _totalPayloadLength: 0,
        _messageLength: 0,
        _fragments: [],
        _state: 4,
        _loop: false,
        [Symbol(kCapture)]: false,
        [Symbol(websocket)]: [Circular *2]
      },
      _sender: qi {
        _extensions: {
          'permessage-deflate': <ref *1> g9 {
            _maxPayload: 104857600,
            _options: {},
            _threshold: 1024,
            _isServer: false,
            _deflate: [DeflateRaw],
            _inflate: [InflateRaw],
            params: [Object: null prototype]
          }
        },
        _socket: Socket {
          connecting: false,
          _hadError: false,
          _parent: null,
          _host: 'localhost',
          _readableState: ReadableState {
            objectMode: false,
            highWaterMark: 16384,
            buffer: [BufferList],
            length: 0,
            pipes: [],
            flowing: false,
            ended: false,
            endEmitted: false,
            reading: false,
            constructed: true,
            sync: false,
            needReadable: true,
            emittedReadable: false,
            readableListening: false,
            resumeScheduled: false,
            errorEmitted: true,
            emitClose: false,
            autoDestroy: true,
            destroyed: true,
            errored: [Error],
            closed: true,
            closeEmitted: true,
            defaultEncoding: 'utf8',
            awaitDrainWriters: null,
            multiAwaitDrain: false,
            readingMore: false,
            dataEmitted: true,
            decoder: null,
            encoding: null,
            [Symbol(kPaused)]: true
          },
          _events: [Object: null prototype] {
            end: [Function: onReadableStreamEnd],
            error: [Function: NOOP]
          },
          _eventsCount: 2,
          _maxListeners: undefined,
          _writableState: WritableState {
            objectMode: false,
            highWaterMark: 16384,
            finalCalled: false,
            needDrain: false,
            ending: false,
            ended: false,
            finished: false,
            destroyed: true,
            decodeStrings: false,
            defaultEncoding: 'utf8',
            length: 0,
            writing: false,
            corked: 0,
            sync: false,
            bufferProcessing: false,
            onwrite: [Function: bound onwrite],
            writecb: null,
            writelen: 0,
            afterWriteTickInfo: null,
            buffered: [],
            bufferedIndex: 0,
            allBuffers: true,
            allNoop: true,
            pendingcb: 0,
            constructed: true,
            prefinished: false,
            errorEmitted: true,
            emitClose: false,
            autoDestroy: true,
            errored: [Error],
            closed: true,
            closeEmitted: true,
            [Symbol(kOnFinished)]: []
          },
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          parser: null,
          _httpMessage: null,
          timeout: 0,
          [Symbol(async_id_symbol)]: 27,
          [Symbol(kHandle)]: null,
          [Symbol(lastWriteQueueSize)]: 0,
          [Symbol(timeout)]: null,
          [Symbol(kBuffer)]: null,
          [Symbol(kBufferCb)]: null,
          [Symbol(kBufferGen)]: null,
          [Symbol(kCapture)]: false,
          [Symbol(kSetNoDelay)]: true,
          [Symbol(kSetKeepAlive)]: false,
          [Symbol(kSetKeepAliveInitialDelay)]: 0,
          [Symbol(kBytesRead)]: 45496281,
          [Symbol(kBytesWritten)]: 1046277,
          [Symbol(RequestTimeout)]: undefined,
          [Symbol(websocket)]: undefined
        },
        _firstFragment: true,
        _compress: false,
        _bufferedBytes: 0,
        _deflating: false,
        _queue: []
      },
      _socket: Socket {
        connecting: false,
        _hadError: false,
        _parent: null,
        _host: 'localhost',
        _readableState: ReadableState {
          objectMode: false,
          highWaterMark: 16384,
          buffer: BufferList { head: null, tail: null, length: 0 },
          length: 0,
          pipes: [],
          flowing: false,
          ended: false,
          endEmitted: false,
          reading: false,
          constructed: true,
          sync: false,
          needReadable: true,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: true,
          emitClose: false,
          autoDestroy: true,
          destroyed: true,
          errored: Error: write EPIPE
              at __node_internal_captureLargerStackTrace (node:internal/errors:477:5)
              at __node_internal_errnoException (node:internal/errors:607:12)
              at afterWriteDispatched (node:internal/stream_base_commons:160:15)
              at writevGeneric (node:internal/stream_base_commons:143:3)
              at Socket._writeGeneric (node:net:872:11)
              at Socket._writev (node:net:881:8)
              at doWrite (node:internal/streams/writable:408:12)
              at clearBuffer (node:internal/streams/writable:563:5)
              at Socket.Writable.uncork (node:internal/streams/writable:350:7)
              at qi.sendFrame (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:470:20)
              at qi.dispatch (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:399:12)
              at qi.send (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:355:14)
              at Ge.send (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/websocket.js:475:18)
              at Ge.de.onmessage (/tmp/69b85f8d2d33cc16/node_modules/graphql-ws/lib/client.mjs:208:36)
              at kf (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:290:14)
              at Ge.n (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:209:9)
              at Ge.emit (node:events:513:28)
              at k9.$z (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/websocket.js:1203:20)
              at k9.emit (node:events:513:28)
              at k9.dataMessage (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:565:14)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:516:23)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/permessage-deflate.js:309:9)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/permessage-deflate.js:392:7)
              at afterWrite (node:internal/streams/writable:499:5)
              at onwrite (node:internal/streams/writable:479:7)
              at Zlib.cb (node:internal/streams/transform:221:7)
              at Zlib.processCallback (node:zlib:613:8) {
            errno: -32,
            code: 'EPIPE',
            syscall: 'write'
          },
          closed: true,
          closeEmitted: true,
          defaultEncoding: 'utf8',
          awaitDrainWriters: null,
          multiAwaitDrain: false,
          readingMore: false,
          dataEmitted: true,
          decoder: null,
          encoding: null,
          [Symbol(kPaused)]: true
        },
        _events: [Object: null prototype] {
          end: [Function: onReadableStreamEnd],
          error: [Function: NOOP]
        },
        _eventsCount: 2,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: false,
          ending: false,
          ended: false,
          finished: false,
          destroyed: true,
          decodeStrings: false,
          defaultEncoding: 'utf8',
          length: 0,
          writing: false,
          corked: 0,
          sync: false,
          bufferProcessing: false,
          onwrite: [Function: bound onwrite],
          writecb: null,
          writelen: 0,
          afterWriteTickInfo: null,
          buffered: [],
          bufferedIndex: 0,
          allBuffers: true,
          allNoop: true,
          pendingcb: 0,
          constructed: true,
          prefinished: false,
          errorEmitted: true,
          emitClose: false,
          autoDestroy: true,
          errored: Error: write EPIPE
              at __node_internal_captureLargerStackTrace (node:internal/errors:477:5)
              at __node_internal_errnoException (node:internal/errors:607:12)
              at afterWriteDispatched (node:internal/stream_base_commons:160:15)
              at writevGeneric (node:internal/stream_base_commons:143:3)
              at Socket._writeGeneric (node:net:872:11)
              at Socket._writev (node:net:881:8)
              at doWrite (node:internal/streams/writable:408:12)
              at clearBuffer (node:internal/streams/writable:563:5)
              at Socket.Writable.uncork (node:internal/streams/writable:350:7)
              at qi.sendFrame (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:470:20)
              at qi.dispatch (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:399:12)
              at qi.send (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/sender.js:355:14)
              at Ge.send (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/websocket.js:475:18)
              at Ge.de.onmessage (/tmp/69b85f8d2d33cc16/node_modules/graphql-ws/lib/client.mjs:208:36)
              at kf (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:290:14)
              at Ge.n (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/event-target.js:209:9)
              at Ge.emit (node:events:513:28)
              at k9.$z (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/websocket.js:1203:20)
              at k9.emit (node:events:513:28)
              at k9.dataMessage (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:565:14)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:516:23)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/permessage-deflate.js:309:9)
              at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/permessage-deflate.js:392:7)
              at afterWrite (node:internal/streams/writable:499:5)
              at onwrite (node:internal/streams/writable:479:7)
              at Zlib.cb (node:internal/streams/transform:221:7)
              at Zlib.processCallback (node:zlib:613:8) {
            errno: -32,
            code: 'EPIPE',
            syscall: 'write'
          },
          closed: true,
          closeEmitted: true,
          [Symbol(kOnFinished)]: []
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        parser: null,
        _httpMessage: null,
        timeout: 0,
        [Symbol(async_id_symbol)]: 27,
        [Symbol(kHandle)]: null,
        [Symbol(lastWriteQueueSize)]: 0,
        [Symbol(timeout)]: null,
        [Symbol(kBuffer)]: null,
        [Symbol(kBufferCb)]: null,
        [Symbol(kBufferGen)]: null,
        [Symbol(kCapture)]: false,
        [Symbol(kSetNoDelay)]: true,
        [Symbol(kSetKeepAlive)]: false,
        [Symbol(kSetKeepAliveInitialDelay)]: 0,
        [Symbol(kBytesRead)]: 45496281,
        [Symbol(kBytesWritten)]: 1046277,
        [Symbol(RequestTimeout)]: undefined,
        [Symbol(websocket)]: undefined
      },
      _bufferedAmount: 0,
      _isServer: false,
      _redirects: 0,
      _url: 'ws://localhost:3000/query',
      _req: null,
      [Symbol(kCapture)]: false
    },
    [Symbol(kType)]: 'error',
    [Symbol(kError)]: RangeError: Invalid WebSocket frame: invalid status code 1006
        at k9.controlMessage (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:592:18)
        at k9.getData (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:466:42)
        at k9.startLoop (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:172:22)
        at <anonymous> (/tmp/69b85f8d2d33cc16/node_modules/ws/lib/receiver.js:185:18)
        at node:internal/process/task_queues:141:7
        at AsyncResource.runInAsyncScope (node:async_hooks:203:9)
        at AsyncResource.runMicrotask (node:internal/process/task_queues:138:8)
        at processTicksAndRejections (node:internal/process/task_queues:96:5) {
      code: 'WS_ERR_INVALID_CLOSE_CODE',
      [Symbol(status-code)]: 1002
    },
    [Symbol(kMessage)]: 'Invalid WebSocket frame: invalid status code 1006'
  }
}
20:22:25.791 FTL empirica: failed to start error="npm run --silent serve -- --token PFHdSUXYnatSDCzi --url http://localhost:3000/query --sessionTokenPath /root/.empirica/local/callBackSessionToken: exit status 1"
20:22:25.794 ERR serve: failed server command error="exit status 1"

Anything else?

No response

Code of Conduct

npaton commented 5 months ago

I have not heard about this issue in a while. The reconnection has been improved as well. So I think this might be good, closing for now, please reopen if you're still seeing this.