Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Task already disappeared teardown error? #46

Closed
goodboy opened this issue Nov 29, 2018 · 2 comments
Closed

Task already disappeared teardown error? #46

goodboy opened this issue Nov 29, 2018 · 2 comments
Labels
bug Something isn't working testing

Comments

@goodboy
Copy link
Owner

goodboy commented Nov 29, 2018

I got this testing out the new options data feed in piker:

27.0.0.1', 1616), raddr=('127.0.0.1', 59706)>
Nov 28 22:43:28 (MainProcess: MainThread) [TRACE] tractor.ipc _ipc.py:122 send `None`
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:416 Exiting msg loop for <Channel fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 59696)> from ('anonymous', 'da40804a-f387-11e8-80a0-a402b9cc051a')
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:272 Releasing channel <Channel fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 59696)> from ('anonymous', 'da40804a-f387-11e8-80a0-a402b9cc051a')
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:276 No more channels for ('anonymous', 'da40804a-f387-11e8-80a0-a402b9cc051a')
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:279 Peers is defaultdict(<class 'list'>, {})
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:283 Signalling no more peer channels
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:287 Disconnecting channel <Channel fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 59696)>
Nov 28 22:43:28 (MainProcess: MainThread) [TRACE] tractor.ipc _ipc.py:122 send `None`
Nov 28 22:43:28 (MainProcess: MainThread) [INFO] piker.broker.data data.py:371 No more subscriptions for questrade
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] piker.broker-config config.py:33 Writing config file /home/tyler/.config/piker/brokers.ini
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:537 All peer channels are complete
Nov 28 22:43:28 (MainProcess: MainThread) [DEBUG] tractor _actor.py:619 Shutting down channel server
Traceback (most recent call last):
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/bin/pikerd", line 11, in <module>
    load_entry_point('piker', 'console_scripts', 'pikerd')()
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/home/tyler/repos/piker/piker/cli.py", line 37, in pikerd
    loglevel=loglevel if tl else None,
  File "/home/tyler/repos/tractor/tractor/__init__.py", line 116, in run_daemon
    return run(partial(trio.sleep, float('inf')), **kwargs)
  File "/home/tyler/repos/tractor/tractor/__init__.py", line 98, in run
    return trio.run(_main, async_fn, args, kwargs, name, arbiter_addr)
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 1337, in run
    raise runner.main_task_outcome.error
  File "/home/tyler/repos/tractor/tractor/__init__.py", line 83, in _main
    actor, main, host, port, arbiter_addr=arbiter_addr)
  File "/home/tyler/repos/tractor/tractor/_actor.py", line 738, in _start_actor
    actor.cancel_server()
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 397, in __aexit__
    raise combined_error_from_nursery
  File "/home/tyler/repos/tractor/tractor/_actor.py", line 500, in _async_main
    log.debug("Waiting on root nursery to complete")
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 397, in __aexit__
    raise combined_error_from_nursery
  File "/home/tyler/repos/tractor/tractor/_actor.py", line 140, in _invoke
    tasks.remove((cs, func))
ValueError: list.remove(x): x not in list

Setup was:

  • started pikerd as standalone daemon-actor
  • started piker monitor
  • started options feed test from piker test suite
  • close the piker monitor
  • pikerd bailed as above...
@goodboy goodboy added bug Something isn't working testing labels Nov 29, 2018
@goodboy goodboy changed the title Task already dissapeared teardown error Task already disappeared teardown error? Nov 29, 2018
@goodboy
Copy link
Owner Author

goodboy commented Nov 29, 2018

This may have something to do with a race when using async generators wrapped by a portal where the far end actor errors and closes the connection, the channel get's de-allocated by the current actor, and the generator is just left hanging waiting on an already closed connection to recv data because the queue / consumer side hasn't been alerted of the break. I'm not sure why there isn't an error getting raised in the msg loop but it's probably something stupid.

@goodboy
Copy link
Owner Author

goodboy commented Nov 29, 2018

Well here's the second issue in more detail with logging from piker:

ov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:345 Received msg {'functype': 'asyncgen', 'cid': 'f6fbcdaa-f3de-11e8-bed6-a402b9cc051a'} from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (data_feed: MainThread) [INFO] piker.broker.data data.py:236 <Channel fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 35866), raddr=('127.0.0.1', 1616)> changed symbol subscription to ()
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:305 Getting result queue for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') cid f6fbcdaa-f3de-11e8-bed6-a402b9cc051a
Nov 29 08:59:18 (data_feed: MainThread) [INFO] piker.broker.data data.py:275 Subscribing with existing `questrade` daemon
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:296 Delivering {'functype': 'asyncgen', 'cid': 'f6fbcdaa-f3de-11e8-bed6-a402b9cc051a'} from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') to caller f6fbcdaa-f3de-11e8-bed6-a402b9cc051a
Nov 29 08:59:18 (data_feed: MainThread) [INFO] tractor _actor.py:394 RPC func is <function modify_quote_stream at 0x7f8db024a9d8>
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:351 Waiting on next msg for <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:399 Waiting on next msg for <Channel fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 35866), raddr=('127.0.0.1', 1616)> from ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _trionics.py:279 Cancelling nursery
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:416 Exiting msg loop for <Channel fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 35866), raddr=('127.0.0.1', 1616)> from ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [WARNING] tractor _portal.py:206 Sending cancel request to ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') on <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)>
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:305 Getting result queue for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') cid f6fc39d4-f3de-11e8-bed6-a402b9cc051a
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:319 Sending cmd to ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a'): self.cancel({})
Nov 29 08:59:18 (data_feed: MainThread) [INFO] piker.broker.data data.py:373 No more subscriptions for questrade
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] piker.broker-config config.py:33 Writing config file /home/tyler/.config/piker/brokers.ini
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:345 Received msg {'error': {'tb_str': 'Traceback (most recent call last):\n  File "/home/tyler/repos/tractor/tractor/_actor.py", line 500, in _async_main\n    log.debug("Waiting on root nursery to complete")\n  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 397, in __aexit__\n    raise combined_error_from_nursery\n  File "/home/tyler/repos/tractor/tractor/_actor.py", line 140, in _invoke\n    tasks.remove((cs, func))\nValueError: list.remove(x): x not in list\n', 'type_str': 'ValueError'}} from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [ERROR] tractor _actor.py:409 Actor errored:
Traceback (most recent call last):
  File "/home/tyler/repos/tractor/tractor/_actor.py", line 356, in _process_messages
    ns, funcname, kwargs, actorid, cid = msg['cmd']
KeyError: 'cmd'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tyler/repos/tractor/tractor/_actor.py", line 366, in _process_messages
    f"{chan.uid}\n" + tb_str,
TypeError: can only concatenate str (not "NoneType") to str
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:416 Exiting msg loop for <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:272 Releasing channel <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:276 No more channels for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:279 Peers is defaultdict(<class 'list'>, {})
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:283 Signalling no more peer channels
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:287 Disconnecting channel <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)>
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor.ipc _ipc.py:136 Closing <Channel fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35866)>
Nov 29 08:59:18 (MainProcess: MainThread) [INFO] tractor _actor.py:238 New connection to us <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)>
Nov 29 08:59:18 (data_feed: MainThread) [INFO] tractor _portal.py:45 Handshake with actor ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a')@('127.0.0.1', 1616) complete
Nov 29 08:59:18 (MainProcess: MainThread) [INFO] tractor _portal.py:45 Handshake with actor ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')@('127.0.0.1', 35876) complete
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:305 Getting result queue for ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a') cid f6fe5cdc-f3de-11e8-a717-a402b9cc051a
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:262 Registered <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)> for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:332 Entering msg loop for <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:319 Sending cmd to ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a'): self.unregister_actor({'uid': ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')})
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:416 Exiting msg loop for <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:332 Entering msg loop for <Channel fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 35876), raddr=('127.0.0.1', 1616)> from ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:272 Releasing channel <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)> from ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:276 No more channels for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:279 Peers is defaultdict(<class 'list'>, {})
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:283 Signalling no more peer channels
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:287 Disconnecting channel <Channel fd=22, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 1616), raddr=('127.0.0.1', 35876)>
Nov 29 08:59:18 (data_feed: MainThread) [ERROR] tractor.ipc _ipc.py:34 Stream connection ('127.0.0.1', 1616) broke
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor.ipc _ipc.py:136 Closing <Channel fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 35876)>
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:537 All peer channels are complete
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:402 <Channel [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6> from ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a') disconnected
Nov 29 08:59:18 (data_feed: MainThread) [DEBUG] tractor _actor.py:416 Exiting msg loop for <Channel [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6> from ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:619 Shutting down channel server
Nov 29 08:59:18 (MainProcess: MainThread) [WARNING] tractor _portal.py:219 May have failed to cancel ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a')
Nov 29 08:59:18 (MainProcess: MainThread) [ERROR] tractor _trionics.py:326 Nursery for ('arbiter', 'f5c43170-f3de-11e8-bed6-a402b9cc051a') errored with <class 'trio.MultiError'>, 
Traceback (most recent call last):
  File "/home/tyler/repos/tractor/tractor/_trionics.py", line 357, in open_nursery
    yield nursery
  File "/home/tyler/repos/piker/tests/test_questrade.py", line 241, in test_option_streaming
    await nursery.cancel()
  File "/home/tyler/repos/tractor/tractor/_trionics.py", line 304, in cancel
    n.start_soon(portal.cancel_actor)
  File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 397, in __aexit__
    raise combined_error_from_nursery
trio.MultiError: Cancelled(), Cancelled()

Details of embedded exception 1:

  Traceback (most recent call last):
    File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 632, in raise_cancel
      raise exc
  trio.Cancelled

Details of embedded exception 2:

  Traceback (most recent call last):
    File "/home/tyler/.local/share/virtualenvs/piker-PaB62peT/lib/python3.7/site-packages/trio/_core/_run.py", line 632, in raise_cancel
      raise exc
  trio.Cancelled
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _trionics.py:279 Cancelling nursery
Nov 29 08:59:18 (MainProcess: MainThread) [WARNING] tractor _portal.py:206 Sending cancel request to ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') on <Channel [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6>
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:305 Getting result queue for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') cid f70cd776-f3de-11e8-bed6-a402b9cc051a
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _actor.py:319 Sending cmd to ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a'): self.cancel({})
Nov 29 08:59:18 (MainProcess: MainThread) [WARNING] tractor _portal.py:216 <Channel [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6> for ('data_feed', 'f5c4a6a0-f3de-11e8-bed6-a402b9cc051a') was already closed?
Nov 29 08:59:18 (MainProcess: MainThread) [DEBUG] tractor _trionics.py:224 Waiting on all subactors to complete
``

goodboy pushed a commit that referenced this issue Nov 30, 2018
Stop channel based async gen streams on exit
a588047 
I'm not sure how this ever worked but when a "fake" async gen
(i.e. function with special `chan`, `cid` kwargs) is completed
we need to signal the end of the stream just like with normal
async gens. Also don't fail when trying to remove tasks that were
never tracked.

Fixes #46
@goodboy goodboy mentioned this issue Nov 30, 2018
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working testing
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@goodboy