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

Server error in middle of experiment #437

Closed aliciamchen closed 9 months ago

aliciamchen commented 10 months ago

Is there an existing issue for this?

What happened?

My experiment runs fine for a while (participants can log in, are paired with other participants, etc.) but then in the middle of the experiment it crashes and participants are not able to continue.

This has happened twice, once when I was running version 1.4.6 and once with version 1.8.0

Error: Unhandled error. (Invalid WebSocket frame: invalid status code 1006)
    at Dae.xt.emit (/tmp/dabb005e6df3940e/node_modules/@empirica/tajriba/src/events.js:156:9)
    at error (/tmp/dabb005e6df3940e/node_modules/@empirica/tajriba/src/tajriba.ts:305:16)
    at Object.emit (/tmp/dabb005e6df3940e/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ve.ue.onerror (/tmp/dabb005e6df3940e/node_modules/graphql-ws/lib/client.mjs:162:47)
    at Kh (/tmp/dabb005e6df3940e/node_modules/ws/lib/event-target.js:290:14)
    at Ve.r (/tmp/dabb005e6df3940e/node_modules/ws/lib/event-target.js:230:9)
    at Ve.emit (node:events:513:28)
    at Q_.j8 (/tmp/dabb005e6df3940e/node_modules/ws/lib/websocket.js:1164:13)
    at Q_.emit (node:events:525:35)
    at emitErrorNT (node:internal/streams/destroy:157:8) {
  context: qu {
    [Symbol(kTarget)]: <ref *2> Ve {
      _events: [Object: null prototype] {
        error: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: r] {
          [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> z_ {
          _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: 6107393,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 13780,
            _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: 12537007,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 9057,
            _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: Q_ {
        _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 Q_.controlMessage (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:566:18)
              at Q_.getData (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:442:42)
              at Q_.startLoop (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:158:22)
              at <anonymous> (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:495:12)
              at <anonymous> (/tmp/dabb005e6df3940e/node_modules/ws/lib/permessage-deflate.js:309:9)
              at <anonymous> (/tmp/dabb005e6df3940e/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) {
            code: 'WS_ERR_INVALID_CLOSE_CODE',
            [Symbol(status-code)]: 1002
          },
          closed: true,
          closeEmitted: false,
          [Symbol(kOnFinished)]: []
        },
        _events: [Object: null prototype] {
          conclude: [Function: L8],
          drain: [Function: M8],
          error: [ [Function: j8], [Function: WO] ],
          message: [Function: B8],
          ping: [Function: U8],
          pong: [Function: W8],
          finish: [Function: WO]
        },
        _eventsCount: 7,
        _maxListeners: undefined,
        _binaryType: 'nodebuffer',
        _extensions: {
          'permessage-deflate': <ref *1> z_ {
            _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: li {
        _extensions: {
          'permessage-deflate': <ref *1> z_ {
            _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: true,
            endEmitted: true,
            reading: false,
            constructed: true,
            sync: false,
            needReadable: false,
            emittedReadable: false,
            readableListening: false,
            resumeScheduled: false,
            errorEmitted: false,
            emitClose: false,
            autoDestroy: true,
            destroyed: true,
            errored: null,
            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: YO]
          },
          _eventsCount: 2,
          _maxListeners: undefined,
          _writableState: WritableState {
            objectMode: false,
            highWaterMark: 16384,
            finalCalled: true,
            needDrain: false,
            ending: true,
            ended: true,
            finished: true,
            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: true,
            errorEmitted: false,
            emitClose: false,
            autoDestroy: true,
            errored: null,
            closed: true,
            closeEmitted: true,
            [Symbol(kOnFinished)]: []
          },
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          parser: null,
          _httpMessage: null,
          timeout: 0,
          write: [Function: writeAfterFIN],
          [Symbol(async_id_symbol)]: 107222,
          [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)]: 12537328,
          [Symbol(kBytesWritten)]: 988846,
          [Symbol(RequestTimeout)]: undefined,
          [Symbol(websocket)]: undefined
        },
        _firstFragment: true,
        _compress: false,
        _bufferedBytes: 15,
        _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: true,
          endEmitted: true,
          reading: false,
          constructed: true,
          sync: false,
          needReadable: false,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: true,
          destroyed: true,
          errored: null,
          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: YO]
        },
        _eventsCount: 2,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: true,
          needDrain: false,
          ending: true,
          ended: true,
          finished: true,
          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: true,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: true,
          errored: null,
          closed: true,
          closeEmitted: true,
          [Symbol(kOnFinished)]: []
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        parser: null,
        _httpMessage: null,
        timeout: 0,
        write: [Function: writeAfterFIN],
        [Symbol(async_id_symbol)]: 107222,
        [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)]: 12537328,
        [Symbol(kBytesWritten)]: 988846,
        [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 Q_.controlMessage (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:566:18)
        at Q_.getData (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:442:42)
        at Q_.startLoop (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:158:22)
        at <anonymous> (/tmp/dabb005e6df3940e/node_modules/ws/lib/receiver.js:495:12)
        at <anonymous> (/tmp/dabb005e6df3940e/node_modules/ws/lib/permessage-deflate.js:309:9)
        at <anonymous> (/tmp/dabb005e6df3940e/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) {
      code: 'WS_ERR_INVALID_CLOSE_CODE',
      [Symbol(status-code)]: 1002
    },
    [Symbol(kMessage)]: 'Invalid WebSocket frame: invalid status code 1006'
  }
}
23:15:50.171 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"
23:15:50.173 ERR serve: failed server command error="exit status 1"

After I get this error, if I empirica serve my bundle file again, it gives me more errors:

23:17:59.110 INF unbundle: already installed target=/tmp/dabb005e6df3940e
23:17:59.117 INF serve: server started
Error: Unhandled error. (connect ECONNREFUSED 127.0.0.1:3000)
    at Xi.xt.emit (/tmp/dabb005e6df3940e/node_modules/@empirica/tajriba/src/events.js:156:9)
    at error (/tmp/dabb005e6df3940e/node_modules/@empirica/tajriba/src/tajriba.ts:305:16)
    at Object.emit (/tmp/dabb005e6df3940e/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ve.ue.onerror (/tmp/dabb005e6df3940e/node_modules/graphql-ws/lib/client.mjs:162:47)
    at Kh (/tmp/dabb005e6df3940e/node_modules/ws/lib/event-target.js:290:14)
    at Ve.r (/tmp/dabb005e6df3940e/node_modules/ws/lib/event-target.js:230:9)
    at Ve.emit (node:events:513:28)
    at Yh (/tmp/dabb005e6df3940e/node_modules/ws/lib/websocket.js:1008:13)
    at ClientRequest.<anonymous> (/tmp/dabb005e6df3940e/node_modules/ws/lib/websocket.js:856:5)
    at ClientRequest.emit (node:events:513:28) {
  context: qu {
    [Symbol(kTarget)]: Ve {
      _events: [Object: null prototype] {
        error: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: r] {
          [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: {},
      _paused: false,
      _protocol: '',
      _readyState: 2,
      _receiver: null,
      _sender: null,
      _socket: null,
      _bufferedAmount: 0,
      _isServer: false,
      _redirects: 0,
      _url: 'ws://localhost:3000/query',
      _req: null,
      [Symbol(kCapture)]: false
    },
    [Symbol(kType)]: 'error',
    [Symbol(kError)]: Error: connect ECONNREFUSED 127.0.0.1:3000
        at __node_internal_captureLargerStackTrace (node:internal/errors:477:5)
        at __node_internal_exceptionWithHostPort (node:internal/errors:655:12)
        at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1247:16) {
      errno: -111,
      code: 'ECONNREFUSED',
      syscall: 'connect',
      address: '127.0.0.1',
      port: 3000
    },
    [Symbol(kMessage)]: 'connect ECONNREFUSED 127.0.0.1:3000'
  }
}
23:18:00.486 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"
23:18:00.490 ERR serve: failed server command error="exit status 1"
23:18:01.233 INF tajriba: server started build={"branch":"main","sha":"297d560","tag":"v1.8.0","time":"2023-09-16T08:00:40Z","version":"v1.8.0"}
23:18:07.556 WRN changes: conn write timeout
23:18:07.657 WRN changes: conn write timeout
23:18:15.136 WRN changes: conn write timeout
23:18:15.240 WRN changes: conn write timeout
23:19:15.691 WRN changes: conn write timeout
23:21:08.654 WRN changes: conn write timeout
23:21:31.174 WRN changes: conn write timeout

The errors disappear if I delete the tajriba.json file and then redeploy the experiment.

Steps To Reproduce

No response

Empirica Version

Version: v1.8.0
SHA:     297d560
Branch:  main
Time:    2023-09-16T08:00:40Z

What OS are you seeing the problem on?

macOS

What browser are you seeing the problem on?

Does not apply

Relevant log output

No response

Anything else?

No response

Code of Conduct

aliciamchen commented 10 months ago

The error shows up most of the time but sometimes it doesn't show up. Today I ran 8 participants, and all made it to the end. Then I tried running 30 participants and the experiment crashed in the middle. But the server usage (CPU, disk, memory) looks good.

This is the error I got:

POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 175009 lock 0xc0032bc324
/go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/hooks.go:41 runtime.(*Runtime).propagateHook ??? <<<<<
/go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/hooks.go:40 runtime.(*Runtime).propagateHook ???
/go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/change.go:528 runtime.(*Runtime).SubChanges.func1 ???

Have been trying to lock it again for more than 30s
goroutine 185489 lock 0xc0032bc324
/go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/hooks.go:175 runtime.(*Runtime).SubOnEvent.func1 ??? <<<<<
/go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/hooks.go:174 runtime.(*Runtime).SubOnEvent.func1 ???

Here is what goroutine 175009 doing now
goroutine 175009 [chan send]:
github.com/empiricaly/tajriba/internal/runtime.(*Runtime).propagateHook(0xc0004d7380, {0xc0002c6cf0?, 0xc0003e4bc0?}, {0xdb59d8, 0x16}, {0xc0003e4bc0, 0x1a}, {0xee8220, 0xc0002c32d0})
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/hooks.go:43 +0x407
github.com/empiricaly/tajriba/internal/runtime.(*Runtime).SubChanges.func1()
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/change.go:529 +0x5c5
created by github.com/empiricaly/tajriba/internal/runtime.(*Runtime).SubChanges
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.4.0/internal/runtime/change.go:488 +0x1ea

root@learning-to-teach:~# Error: Unhandled error. (connect ECONNREFUSED 127.0.0.1:3000)
    at Xi.xt.emit (/tmp/c7a54ad1788110f3/node_modules/@empirica/tajriba/src/events.js:156:9)
    at error (/tmp/c7a54ad1788110f3/node_modules/@empirica/tajriba/src/tajriba.ts:323:16)
    at Object.emit (/tmp/c7a54ad1788110f3/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ve.ue.onerror (/tmp/c7a54ad1788110f3/node_modules/graphql-ws/lib/client.mjs:162:47)
    at Kh (/tmp/c7a54ad1788110f3/node_modules/ws/lib/event-target.js:290:14)
    at Ve.r (/tmp/c7a54ad1788110f3/node_modules/ws/lib/event-target.js:230:9)
    at Ve.emit (node:events:513:28)
    at Yh (/tmp/c7a54ad1788110f3/node_modules/ws/lib/websocket.js:1016:13)
    at ClientRequest.<anonymous> (/tmp/c7a54ad1788110f3/node_modules/ws/lib/websocket.js:864:5)
    at ClientRequest.emit (node:events:513:28) {
  context: Mu {
    [Symbol(kTarget)]: Ve {
      _events: [Object: null prototype] {
        error: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: r] {
          [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: {},
      _paused: false,
      _protocol: '',
      _readyState: 2,
      _receiver: null,
      _sender: null,
      _socket: null,
      _bufferedAmount: 0,
      _isServer: false,
      _redirects: 0,
      _url: 'ws://localhost:3000/query',
      _req: null,
      [Symbol(kCapture)]: false
    },
    [Symbol(kType)]: 'error',
    [Symbol(kError)]: Error: connect ECONNREFUSED 127.0.0.1:3000
        at __node_internal_captureLargerStackTrace (node:internal/errors:477:5)
        at __node_internal_exceptionWithHostPort (node:internal/errors:655:12)
        at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1247:16) {
      errno: -111,
      code: 'ECONNREFUSED',
      syscall: 'connect',
      address: '127.0.0.1',
      port: 3000
    },
    [Symbol(kMessage)]: 'connect ECONNREFUSED 127.0.0.1:3000'
  }
}
21:21:59.114 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"

Again, when I try to redeploy the experiment, it doesn't work unless I get rid of tajriba.json.

aliciamchen commented 10 months ago

I reverted to version 1.7.0, and got this error right when participants were starting to play the game:

23:31:54.485 WRN failed load: [GraphQL] transition step: invalid state
[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "[object Object]".] {
  code: 'ERR_UNHANDLED_REJECTION'
}
23:31:54.503 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"
23:31:54.505 ERR serve: failed server command error="exit status 1"
aliciamchen commented 10 months ago

I added the EMPIRICA_BUILD environment variable and ran EMPIRICA_BUILD="version: v1.8.0" empirica serve exp3.tar.zst, and got the same error:

Error: Unhandled error. (Invalid WebSocket frame: invalid status code 1006)
    at Pae.xt.emit (/tmp/e09d1e606892d83e/node_modules/@empirica/tajriba/src/events.js:156:9)
    at error (/tmp/e09d1e606892d83e/node_modules/@empirica/tajriba/src/tajriba.ts:323:16)
    at Object.emit (/tmp/e09d1e606892d83e/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ve.ue.onerror (/tmp/e09d1e606892d83e/node_modules/graphql-ws/lib/client.mjs:162:47)
    at Kh (/tmp/e09d1e606892d83e/node_modules/ws/lib/event-target.js:290:14)
    at Ve.r (/tmp/e09d1e606892d83e/node_modules/ws/lib/event-target.js:230:9)
    at Ve.emit (node:events:513:28)
    at Y_.D8 (/tmp/e09d1e606892d83e/node_modules/ws/lib/websocket.js:1172:13)
    at Y_.emit (node:events:525:35)
    at emitErrorNT (node:internal/streams/destroy:157:8) {
  context: Mu {
    [Symbol(kTarget)]: <ref *2> Ve {
      _events: [Object: null prototype] {
        error: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: r] {
          [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> V_ {
          _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: 4016772,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 275,
            _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: 14337930,
            _handle: [Zlib],
            _outBuffer: [Buffer [Uint8Array]],
            _outOffset: 6007,
            _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: Y_ {
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: false,
          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 Y_.controlMessage (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:587:18)
              at Y_.getData (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:461:42)
              at Y_.startLoop (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:167:22)
              at <anonymous> (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:180: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 runMicrotasks (<anonymous>)
              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: C8],
          drain: [Function: R8],
          error: [ [Function: D8], [Function: UO] ],
          message: [Function: q8],
          ping: [Function: L8],
          pong: [Function: M8],
          finish: [Function: UO]
        },
        _eventsCount: 7,
        _maxListeners: undefined,
        _binaryType: 'nodebuffer',
        _extensions: {
          'permessage-deflate': <ref *1> V_ {
            _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: li {
        _extensions: {
          'permessage-deflate': <ref *1> V_ {
            _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: true,
            ended: true,
            endEmitted: true,
            reading: false,
            constructed: true,
            sync: false,
            needReadable: false,
            emittedReadable: false,
            readableListening: false,
            resumeScheduled: false,
            errorEmitted: false,
            emitClose: false,
            autoDestroy: true,
            destroyed: true,
            errored: null,
            closed: true,
            closeEmitted: true,
            defaultEncoding: 'utf8',
            awaitDrainWriters: null,
            multiAwaitDrain: false,
            readingMore: false,
            dataEmitted: true,
            decoder: null,
            encoding: null,
            [Symbol(kPaused)]: false
          },
          _events: [Object: null prototype] {
            end: [Function: onReadableStreamEnd],
            error: [Function: ZO]
          },
          _eventsCount: 2,
          _maxListeners: undefined,
          _writableState: WritableState {
            objectMode: false,
            highWaterMark: 16384,
            finalCalled: true,
            needDrain: false,
            ending: true,
            ended: true,
            finished: true,
            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: true,
            errorEmitted: false,
            emitClose: false,
            autoDestroy: true,
            errored: null,
            closed: true,
            closeEmitted: true,
            [Symbol(kOnFinished)]: []
          },
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          parser: null,
          _httpMessage: null,
          timeout: 0,
          write: [Function: writeAfterFIN],
          [Symbol(async_id_symbol)]: 65852,
          [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)]: 14339019,
          [Symbol(kBytesWritten)]: 729309,
          [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: true,
          ended: true,
          endEmitted: true,
          reading: false,
          constructed: true,
          sync: false,
          needReadable: false,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: true,
          destroyed: true,
          errored: null,
          closed: true,
          closeEmitted: true,
          defaultEncoding: 'utf8',
          awaitDrainWriters: null,
          multiAwaitDrain: false,
          readingMore: false,
          dataEmitted: true,
          decoder: null,
          encoding: null,
          [Symbol(kPaused)]: false
        },
        _events: [Object: null prototype] {
          end: [Function: onReadableStreamEnd],
          error: [Function: ZO]
        },
        _eventsCount: 2,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: true,
          needDrain: false,
          ending: true,
          ended: true,
          finished: true,
          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: true,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: true,
          errored: null,
          closed: true,
          closeEmitted: true,
          [Symbol(kOnFinished)]: []
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        parser: null,
        _httpMessage: null,
        timeout: 0,
        write: [Function: writeAfterFIN],
        [Symbol(async_id_symbol)]: 65852,
        [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)]: 14339019,
        [Symbol(kBytesWritten)]: 729309,
        [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 Y_.controlMessage (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:587:18)
        at Y_.getData (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:461:42)
        at Y_.startLoop (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:167:22)
        at <anonymous> (/tmp/e09d1e606892d83e/node_modules/ws/lib/receiver.js:180: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 runMicrotasks (<anonymous>)
        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'
  }
}
23:36:51.957 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"
23:36:51.963 ERR serve: failed server command error="exit status 1"
aliciamchen commented 10 months ago

I tried it with 1.7.0 and ran EMPIRICA_BUILD="version: v1.7.0" empirica serve exp3.tar.zst, and got the potential deadlock error.

00:30:27.075 WRN changes: conn write timeout
POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 123866 lock 0xc001193164
/go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/hooks.go:41 runtime.(*Runtime).propagateHook ??? <<<<<
/go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/hooks.go:40 runtime.(*Runtime).propagateHook ???
/go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/change.go:528 runtime.(*Runtime).SubChanges.func1 ???

Have been trying to lock it again for more than 30s
goroutine 123940 lock 0xc001193164
/go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/hooks.go:175 runtime.(*Runtime).SubOnEvent.func1 ??? <<<<<
/go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/hooks.go:174 runtime.(*Runtime).SubOnEvent.func1 ???

Here is what goroutine 123866 doing now
goroutine 123866 [chan send]:
github.com/empiricaly/tajriba/internal/runtime.(*Runtime).propagateHook(0xc00024faa0, {0xc000516540?, 0xc00a228200?}, {0xcf12d4, 0x16}, {0xc00a228200, 0x1a}, {0xe0ecc0, 0xc0061a33b0})
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/hooks.go:43 +0x407
github.com/empiricaly/tajriba/internal/runtime.(*Runtime).SubChanges.func1()
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/change.go:529 +0x5c5
created by github.com/empiricaly/tajriba/internal/runtime.(*Runtime).SubChanges
    /go/pkg/mod/github.com/empiricaly/tajriba@v1.3.0/internal/runtime/change.go:488 +0x1ea

root@learning-to-teach:~# Error: Unhandled error. (connect ECONNREFUSED 127.0.0.1:3000)
    at Xi.xt.emit (/tmp/6a8d424058d3c18c/node_modules/@empirica/tajriba/src/events.js:156:9)
    at error (/tmp/6a8d424058d3c18c/node_modules/@empirica/tajriba/src/tajriba.ts:305:16)
    at Object.emit (/tmp/6a8d424058d3c18c/node_modules/graphql-ws/lib/client.mjs:104:21)
    at Ve.ue.onerror (/tmp/6a8d424058d3c18c/node_modules/graphql-ws/lib/client.mjs:162:47)
    at Kh (/tmp/6a8d424058d3c18c/node_modules/ws/lib/event-target.js:290:14)
    at Ve.r (/tmp/6a8d424058d3c18c/node_modules/ws/lib/event-target.js:230:9)
    at Ve.emit (node:events:513:28)
    at Yh (/tmp/6a8d424058d3c18c/node_modules/ws/lib/websocket.js:1016:13)
    at ClientRequest.<anonymous> (/tmp/6a8d424058d3c18c/node_modules/ws/lib/websocket.js:864:5)
    at ClientRequest.emit (node:events:513:28) {
  context: Mu {
    [Symbol(kTarget)]: Ve {
      _events: [Object: null prototype] {
        error: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        close: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [Function (anonymous)]
        },
        open: [Function: r] {
          [Symbol(kIsForOnEventAttribute)]: true,
          [Symbol(kListener)]: [AsyncFunction (anonymous)]
        },
        message: [Function: r] {
          [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: {},
      _paused: false,
      _protocol: '',
      _readyState: 2,
      _receiver: null,
      _sender: null,
      _socket: null,
      _bufferedAmount: 0,
      _isServer: false,
      _redirects: 0,
      _url: 'ws://localhost:3000/query',
      _req: null,
      [Symbol(kCapture)]: false
    },
    [Symbol(kType)]: 'error',
    [Symbol(kError)]: Error: connect ECONNREFUSED 127.0.0.1:3000
        at __node_internal_captureLargerStackTrace (node:internal/errors:477:5)
        at __node_internal_exceptionWithHostPort (node:internal/errors:655:12)
        at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1247:16) {
      errno: -111,
      code: 'ECONNREFUSED',
      syscall: 'connect',
      address: '127.0.0.1',
      port: 3000
    },
    [Symbol(kMessage)]: 'connect ECONNREFUSED 127.0.0.1:3000'
  }
}
00:31:38.101 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"

Running echo $EMPIRICA_BUILD shows 1.7.0:

root@learning-to-teach:~# echo $EMPIRICA_BUILD
version: v1.7.0

I also made sure that when I made the experiment bundle, the version on my local machine corresponds to the version on the server.

aliciamchen commented 10 months ago

With 1.8.5 my experiment with a small number of participants still crashed:

22:14:54.838 WRN failed load: [GraphQL] transition step: invalid state
[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "[object Object]".] {
  code: 'ERR_UNHANDLED_REJECTION'
}
22:14:54.859 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"
22:14:54.861 ERR serve: failed server command error="exit status 1"
22:15:05.602 WRN changes: conn write timeout
Version: v1.8.5
SHA:     1d91ea7
Branch:  main
Time:    2023-11-16T03:03:22Z
npaton commented 10 months ago

I'd recommend adding the following to server/src/index.js (it is in there by default in the more recent template):

process.on("unhandledRejection", function (reason, p) {
  process.exitCode = 1;
  console.error("Unhandled Promise Rejection. Reason: ", reason);
});

That last error is thrown "somewhere" and we don't know what it is. By catching it like this, it should show the error in more detail. It is still likely to be an internal problem, but it would be better to identify exactly what the problem is. 👍

aliciamchen commented 9 months ago

Thank you!! I added the code to server/src/index.js, and this is the error it gives me:

19:40:00.129 WRN failed load: [GraphQL] transition step: invalid state
Unhandled Promise Rejection. Reason:  [t [CombinedError]: [GraphQL] transition step: invalid state] {
  graphQLErrors: [
    Wi [GraphQLError]: transition step: invalid state
        at fV (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/error.ts:24:10)
        at Array.map (<anonymous>)
        at t (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/error.ts:61:5)
        at Zc (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/result.ts:22:15)
        at Object.next (/tmp/43a21baa34952e15/node_modules/@urql/core/src/exchanges/subscription.ts:82:15)
        at Object.1e121d09-9817-4569-91ef-0c66097149c8 (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:361:42)
        at emit (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:77:94)
        at Object.emit (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:104:21)
        at Ve.ue.onmessage (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:200:29)
        at Kh (/tmp/43a21baa34952e15/node_modules/ws/lib/event-target.js:290:14) {
      path: [Array],
      locations: undefined,
      extensions: {}
    }
  ],
  networkError: undefined,
  response: undefined
}
19:40:00.370 WRN failed load: [GraphQL] transition step: invalid state
Unhandled Promise Rejection. Reason:  [t [CombinedError]: [GraphQL] transition step: invalid state] {
  graphQLErrors: [
    Wi [GraphQLError]: transition step: invalid state
        at fV (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/error.ts:24:10)
        at Array.map (<anonymous>)
        at t (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/error.ts:61:5)
        at Zc (/tmp/43a21baa34952e15/node_modules/@urql/core/src/utils/result.ts:22:15)
        at Object.next (/tmp/43a21baa34952e15/node_modules/@urql/core/src/exchanges/subscription.ts:82:15)
        at Object.adf644de-6534-4951-a73d-af0bd8a197f1 (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:361:42)
        at emit (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:77:94)
        at Object.emit (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:104:21)
        at Ve.ue.onmessage (/tmp/43a21baa34952e15/node_modules/graphql-ws/lib/client.mjs:200:29)
        at Kh (/tmp/43a21baa34952e15/node_modules/ws/lib/event-target.js:290:14) {
      path: [Array],
      locations: undefined,
      extensions: {}
    }
  ],
  networkError: undefined,
  response: undefined
}

I also sometimes get the warning WRN changes: conn write timeout as I'm running my experiment, but this doesn't always seem to mean the experiment is about to crash.

npaton commented 9 months ago

The conn write timeout issue should be fixed, though the transition step invalid state is still happening. To not be too confusing, I'm closing this ticket, and created a new one here: https://github.com/empiricaly/empirica/issues/454.