search

Dallinger / Griduniverse

Welcome to the Griduniverse.
7 stars 3 forks source link

Game sometimes hangs at Waiting Room only with one (or more) bot(s) and one human #196

Closed mmosleh closed 5 years ago

mmosleh commented 6 years ago

The game hangs in the waiting room sometimes. This happens with only one (or more) bots and one human. The human player receives the message "Waiting for the other players to join" with the progress bar but the game never proceeds. This happens from time to time with one or more (random) bots.

recruiter config

max_participants =2
recruiter = multi
recruiters = bots: 1, cli: 1

Debug log

❯❯ Starting up the server...
6:17:44 PM worker.1 |  2018-09-08 18:17:44,005 RQ GEVENT worker (Greenlet pool size=20) '6:17:44 PM worker.1 |  2018-09-08 18:17:44,006 Cleaning registries for queue: high
6:17:44 PM worker.1 |  2018-09-08 18:17:44,007 Cleaning registries for queue: default
6:17:44 PM worker.1 |  2018-09-08 18:17:44,007 Cleaning registries for queue: low
6:17:44 PM web.1    |  /Users/.virtualenvs/ngs2/lib/python3.6/site-packages/sqlalchemy/orm/mapper.py:1057: SAWarning: Reassigning polymorphic association for identity 'event' from <Mapper at 0x112556710; Event> to <Mapper at 0x1125f8a90; Event>: Check for duplicate use of 'event' as value for polymorphic_identity.
6:17:44 PM web.1    |    self, self.polymorphic_identity)
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [DEBUG] Current configuration:
6:17:44 PM web.1    |    config: None
6:17:44 PM web.1    |    bind: ['0.0.0.0:5000']
6:17:44 PM web.1    |    backlog: 2048
6:17:44 PM web.1    |    workers: 13
6:17:44 PM web.1    |    worker_class: geventwebsocket.gunicorn.workers.GeventWebSocketWorker
6:17:44 PM web.1    |    threads: 1
6:17:44 PM web.1    |    worker_connections: 1000
6:17:44 PM web.1    |    max_requests: 0
6:17:44 PM web.1    |    max_requests_jitter: 0
6:17:44 PM web.1    |    timeout: 30
6:17:44 PM web.1    |    graceful_timeout: 30
6:17:44 PM web.1    |    keepalive: 2
6:17:44 PM web.1    |    limit_request_line: 0
6:17:44 PM web.1    |    limit_request_fields: 100
6:17:44 PM web.1    |    limit_request_field_size: 8190
6:17:44 PM web.1    |    reload: False
6:17:44 PM web.1    |    reload_engine: auto
6:17:44 PM web.1    |    reload_extra_files: []
6:17:44 PM web.1    |    spew: False
6:17:44 PM web.1    |    check_config: False
6:17:44 PM web.1    |    preload_app: False
6:17:44 PM web.1    |    sendfile: None
6:17:44 PM web.1    |    reuse_port: False
6:17:44 PM web.1    |    chdir: /private/var/folders/c6/s0wv1m5x711cw1jygdt91vbc0000gn/T/tmpxc7c8f9i/2ceb75b5-8871-cc74-d3a1-133281319a3b
6:17:44 PM web.1    |    daemon: False
6:17:44 PM web.1    |    raw_env: []
6:17:44 PM web.1    |    pidfile: None
6:17:44 PM web.1    |    worker_tmp_dir: None
6:17:44 PM web.1    |    user: 501
6:17:44 PM web.1    |    group: 20
6:17:44 PM web.1    |    umask: 0
6:17:44 PM web.1    |    initgroups: False
6:17:44 PM web.1    |    tmp_upload_dir: None
6:17:44 PM web.1    |    secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'}
6:17:44 PM web.1    |    forwarded_allow_ips: ['127.0.0.1']
6:17:44 PM web.1    |    accesslog: -
6:17:44 PM web.1    |    disable_redirect_access_to_syslog: False
6:17:44 PM web.1    |    access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
6:17:44 PM web.1    |    errorlog: -
6:17:44 PM web.1    |    loglevel: debug
6:17:44 PM web.1    |    capture_output: False
6:17:44 PM web.1    |    logger_class: gunicorn.glogging.Logger
6:17:44 PM web.1    |    logconfig: None
6:17:44 PM web.1    |    logconfig_dict: {}
6:17:44 PM web.1    |    syslog_addr: unix:///var/run/syslog
6:17:44 PM web.1    |    syslog: False
6:17:44 PM web.1    |    syslog_prefix: None
6:17:44 PM web.1    |    syslog_facility: user
6:17:44 PM web.1    |    enable_stdio_inheritance: False
6:17:44 PM web.1    |    statsd_host: None
6:17:44 PM web.1    |    statsd_prefix: 
6:17:44 PM web.1    |    proc_name: dallinger_experiment_server
6:17:44 PM web.1    |    default_proc_name: gunicorn
6:17:44 PM web.1    |    pythonpath: None
6:17:44 PM web.1    |    paste: None
6:17:44 PM web.1    |    on_starting: <function OnStarting.on_starting at 0x1125c99d8>
6:17:44 PM web.1    |    on_reload: <function OnReload.on_reload at 0x1125c9ae8>
6:17:44 PM web.1    |    when_ready: <function when_ready at 0x11256f158>
6:17:44 PM web.1    |    pre_fork: <function Prefork.pre_fork at 0x1125c9d08>
6:17:44 PM web.1    |    post_fork: <function Postfork.post_fork at 0x1125c9e18>
6:17:44 PM web.1    |    post_worker_init: <function PostWorkerInit.post_worker_init at 0x1125c9f28>
6:17:44 PM web.1    |    worker_int: <function WorkerInt.worker_int at 0x1125e30d0>
6:17:44 PM web.1    |    worker_abort: <function WorkerAbort.worker_abort at 0x1125e31e0>
6:17:44 PM web.1    |    pre_exec: <function PreExec.pre_exec at 0x1125e32f0>
6:17:44 PM web.1    |    pre_request: <function PreRequest.pre_request at 0x1125e3400>
6:17:44 PM web.1    |    post_request: <function PostRequest.post_request at 0x1125e3488>
6:17:44 PM web.1    |    child_exit: <function ChildExit.child_exit at 0x1125e3598>
6:17:44 PM web.1    |    worker_exit: <function WorkerExit.worker_exit at 0x1125e36a8>
6:17:44 PM web.1    |    nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x1125e37b8>
6:17:44 PM web.1    |    on_exit: <function OnExit.on_exit at 0x1125e38c8>
6:17:44 PM web.1    |    proxy_protocol: False
6:17:44 PM web.1    |    proxy_allow_ips: ['127.0.0.1']
6:17:44 PM web.1    |    keyfile: None
6:17:44 PM web.1    |    certfile: None
6:17:44 PM web.1    |    ssl_version: 2
6:17:44 PM web.1    |    cert_reqs: 0
6:17:44 PM web.1    |    ca_certs: None
6:17:44 PM web.1    |    suppress_ragged_eofs: True
6:17:44 PM web.1    |    do_handshake_on_connect: False
6:17:44 PM web.1    |    ciphers: TLSv1
6:17:44 PM web.1    |    raw_paste_global_conf: []
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [INFO] Starting gunicorn 19.9.0
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [DEBUG] Arbiter booted
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [INFO] Listening at: http://0.0.0.0:5000 (40047)
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [INFO] Using worker: geventwebsocket.gunicorn.workers.GeventWebSocketWorker
6:17:44 PM web.1    |  2018-09-08 18:17:44,040 Ready.
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40065] [INFO] Booting worker with pid: 40065
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40066] [INFO] Booting worker with pid: 40066
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40067] [INFO] Booting worker with pid: 40067
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40068] [INFO] Booting worker with pid: 40068
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40069] [INFO] Booting worker with pid: 40069
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40070] [INFO] Booting worker with pid: 40070
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40071] [INFO] Booting worker with pid: 40071
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40072] [INFO] Booting worker with pid: 40072
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40073] [INFO] Booting worker with pid: 40073
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40074] [INFO] Booting worker with pid: 40074
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40075] [INFO] Booting worker with pid: 40075
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40076] [INFO] Booting worker with pid: 40076
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40077] [INFO] Booting worker with pid: 40077
6:17:44 PM web.1    |  [2018-09-08 18:17:44 -0400] [40047] [DEBUG] 13 workers

❯❯ Server is running on http://0.0.0.0:5000. Press Ctrl+C to exit.

❯❯ Launching the experiment...

❯❯ Initial recruitment list:
http://0.0.0.0:5000/ad?recruiter=bots&assignmentId=Z0FB4U&hitId=BIC649&workerId=1S785E&mode=sandbox
http://0.0.0.0:5000/ad?recruiter=cli&assignmentId=YGS6EU&hitId=IU3Q1J&workerId=BV4WQ1&mode=debug
Additional details:
Bot recruitment started using RandomBot
Search for "New participant requested:" in the logs for subsequent recruitment URLs.
Open the logs for this experiment with "dallinger logs --app 2ceb75b5-8871-cc74-d3a1-133281319a3b"
6:17:54 PM web.1    |  2018-09-08 18:17:54,593 Initializing WebSocket
6:17:54 PM web.1    |  2018-09-08 18:17:54,593 Validating WebSocket request
6:17:54 PM web.1    |  2018-09-08 18:17:54,594 Can only upgrade connection if using GET method.
6:17:54 PM web.1    |  >>>> ----- Launching experiment...
6:17:54 PM web.1    |  2018-09-08 18:17:54,721 Opening recruitment.
6:17:54 PM web.1    |  2018-09-08 18:17:54,724 Initialized BotRecruiter.
6:17:54 PM web.1    |  2018-09-08 18:17:54,724 Open recruitment.
6:17:54 PM web.1    |  2018-09-08 18:17:54,725 Creating bot with URL: http://0.0.0.0:5000/ad?recruiter=bots&assignmentId=Z0FB4U&hitId=BIC649&workerId=1S785E&mode=sandbox.
6:17:54 PM web.1    |  2018-09-08 18:17:54,728 Created job d638a7d5-ed37-492f-974a-61e34f06810a for url http://0.0.0.0:5000/ad?recruiter=bots&assignmentId=Z0FB4U&hitId=BIC649&workerId=1S785E&mode=sandbox.
6:17:54 PM web.1    |  2018-09-08 18:17:54,732 Opening recruitment.
6:17:54 PM web.1    |  2018-09-08 18:17:54,733 New participant requested: http://0.0.0.0:5000/ad?recruiter=cli&assignmentId=YGS6EU&hitId=IU3Q1J&workerId=BV4WQ1&mode=debug

❯❯ new recruitment request!
6:17:54 PM web.1    |  2018-09-08 18:17:54,735 40065/4604162888: Subscribed client <dallinger_experiment.experiment.Griduniverse object at 0x112cea978> to channel griduniverse_ctrl
6:17:54 PM web.1    |  2018-09-08 18:17:54,736 Closing Dallinger DB session at flask request end
6:17:54 PM web.1    |  2018-09-08 18:17:54,737 127.0.0.1 - - [2018-09-08 18:17:54] "POST /launch HTTP/1.1" 200 629 0.143490
6:17:54 PM web.1    |  2018-09-08 18:17:54,737 40065/4610131272: Listening on channel griduniverse_ctrl
6:17:54 PM web.1    |  2018-09-08 18:17:54,837 Spawning food
6:18:00 PM web.1    |  2018-09-08 18:18:00,686 Initializing WebSocket
6:18:00 PM web.1    |  2018-09-08 18:18:00,687 Validating WebSocket request
6:18:00 PM web.1    |  2018-09-08 18:18:00,687 Attempting to upgrade connection
6:18:00 PM web.1    |  2018-09-08 18:18:00,688 WebSocket request accepted, switching protocols
6:18:00 PM web.1    |  2018-09-08 18:18:00,690 40077/4604162888: Subscribed client <dallinger.experiment_server.sockets.Client object at 0x115c7c1d0> to channel quorum
6:18:00 PM web.1    |  2018-09-08 18:18:00,694 40077/4571960392: Listening on channel quorum