/quit when connection is not completed puts poezio in a useless state (#3466) · Issues · poezio / poezio

/quit when connection is not completed puts poezio in a useless state

Poezio version: e5e0533b
Slixmpp version: slixmpp@2b666eb1

Steps to reproduce

Start poezio
Type /quit quite rapidly while poezio connects

What I expect

Poezio quits, (taking its time to shutdown if necessary)

What happens

"Nothing". The connection seems to get reset, and poezio is unusable. /quit triggers another "disconnect wait", /reconnect also seems to call /quit, etc..

Logs

2019-03-02 11:55:32,673 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,673 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,673 DEBUG:roster_win:The roster has changed, rebuilding the cache…
2019-03-02 11:55:32,674 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,674 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,674 DEBUG:roster_win:Refresh: ContactInfoWin
2019-03-02 11:55:32,674 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,674 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:32,675 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,675 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,675 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,675 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,675 DEBUG:roster_win:Refresh: ContactInfoWin                                                                                                                                                                                                                
2019-03-02 11:55:32,676 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,676 DEBUG:input_placeholders:Refresh: HelpText                                                                                                                                                                                                              
2019-03-02 11:55:32,676 DEBUG:xmlstream:Event triggered: connecting
2019-03-02 11:55:32,676 DEBUG:disco:Looking up local disco#info data for None, node None.                                                                                                                                                                                       
2019-03-02 11:55:32,677 DEBUG:resolver:DNS: Querying SRV records for bouah.net
2019-03-02 11:55:32,678 DEBUG:core:Input is readable.
2019-03-02 11:55:32,678 DEBUG:core:Got from keyboard: (['/'],)
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Exception while querying for bouah.net SRV records: (4, 'Domain name not found')
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Querying bouah.net for AAAA records.
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Querying bouah.net for A records.
2019-03-02 11:55:32,852 DEBUG:core:Input is readable.
2019-03-02 11:55:32,852 DEBUG:core:Got from keyboard: (['q'],)
2019-03-02 11:55:32,952 DEBUG:xmlstream:Event triggered: connected
2019-03-02 11:55:32,953 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,953 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,954 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,954 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,955 DEBUG:roster_win:Refresh: ContactInfoWin
2019-03-02 11:55:32,955 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,956 DEBUG:inputs:Refresh: CommandInput
2019-03-02 11:55:32,956 DEBUG:xmlstream:SEND: <stream:stream to='bouah.net' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2019-03-02 11:55:33,003 DEBUG:core:Input is readable.
2019-03-02 11:55:33,004 DEBUG:core:Got from keyboard: (['u'],)
2019-03-02 11:55:33,090 DEBUG:core:Input is readable.
2019-03-02 11:55:33,091 DEBUG:core:Got from keyboard: (['i'],)
2019-03-02 11:55:33,122 DEBUG:core:Input is readable.
2019-03-02 11:55:33,122 DEBUG:core:Got from keyboard: (['t'],)
2019-03-02 11:55:33,197 DEBUG:xmlstream:RECV: <stream:stream xml:lang="en" from="bouah.net" id="9d881d4b-3af4-47d1-a5cd-a4c74ea70ddd" version="1.0">
2019-03-02 11:55:33,350 DEBUG:xmlstream:RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls></stream:features>
2019-03-02 11:55:33,353 DEBUG:xmlstream:SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls>
2019-03-02 11:55:33,353 DEBUG:core:Input is readable.
2019-03-02 11:55:33,353 DEBUG:core:Got from keyboard: (['^M'],)
2019-03-02 11:55:33,355 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-1"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/mood"><item id="current"><mood xmlns="http://jabber.org/protocol/mood" /></i
tem></publish></pubsub></iq>
2019-03-02 11:55:33,355 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-2"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/activity"><item id="current"><activity xmlns="http://jabber.org/protocol/act
ivity" /></item></publish></pubsub></iq>
2019-03-02 11:55:33,356 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-3"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="urn:xmpp:gaming:0"><item id="current"><gaming xmlns="urn:xmpp:gaming:0" /></item></publish></pubsub></i
q>
2019-03-02 11:55:33,356 DEBUG:roster:folded:

2019-03-02 11:55:33,360 DEBUG:xmlstream:SEND: </stream:stream>
2019-03-02 11:55:33,361 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:33,594 DEBUG:xmlstream:RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
2019-03-02 11:55:33,597 DEBUG:starttls:Starting TLS
2019-03-02 11:55:33,598 ERROR:stanzabase:Error handling {jabber:client}proceed stanza
Traceback (most recent call last):
  File "/home/ppjet/Src/slixmpp/master/slixmpp/xmlstream/handler/coroutine_callback.py", line 50, in pointer_wrapper
    await pointer(stanza, *args, **kwargs)
  File "/home/ppjet/Src/slixmpp/master/slixmpp/features/feature_starttls/starttls.py", line 64, in _handle_starttls_proceed
    if await self.xmpp.start_tls():
  File "/home/ppjet/Src/slixmpp/master/slixmpp/xmlstream/xmlstream.py", line 550, in start_tls
    self, ssl_context)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1134, in start_tls
    await waiter
  File "/usr/lib/python3.7/asyncio/selector_events.py", line 857, in write
    n = self._sock.send(data)
ConnectionResetError: [Errno 104] Connection reset by peer
2019-03-02 11:55:35,362 DEBUG:xmlstream:Scheduled event: Disconnect wait
2019-03-02 11:55:35,363 DEBUG:xmlstream:Event triggered: killed
2019-03-02 11:55:35,363 DEBUG:xmlstream:Event triggered: killed
2019-03-02 11:55:37,439 DEBUG:core:Input is readable.
2019-03-02 11:55:37,440 DEBUG:core:Got from keyboard: (['/'],)
2019-03-02 11:55:37,711 DEBUG:core:Input is readable.
2019-03-02 11:55:37,711 DEBUG:core:Got from keyboard: (['q'],)
2019-03-02 11:55:37,862 DEBUG:core:Input is readable.
2019-03-02 11:55:37,863 DEBUG:core:Got from keyboard: (['u'],)
2019-03-02 11:55:37,965 DEBUG:core:Input is readable.
2019-03-02 11:55:37,966 DEBUG:core:Got from keyboard: (['i'],)
2019-03-02 11:55:38,059 DEBUG:core:Input is readable.
2019-03-02 11:55:38,060 DEBUG:core:Got from keyboard: (['t'],)
2019-03-02 11:55:38,298 DEBUG:core:Input is readable.
2019-03-02 11:55:38,299 DEBUG:core:Got from keyboard: (['^M'],)
2019-03-02 11:55:38,300 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-4"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/mood"><item id="current"><mood xmlns="http://jabber.org/protocol/mood" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,301 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-5"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/activity"><item id="current"><activity xmlns="http://jabber.org/protocol/activity" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,301 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-6"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="urn:xmpp:gaming:0"><item id="current"><gaming xmlns="urn:xmpp:gaming:0" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,302 DEBUG:roster:folded:

2019-03-02 11:55:38,304 DEBUG:xmlstream:SEND: </stream:stream>
2019-03-02 11:55:38,305 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:40,306 DEBUG:xmlstream:Scheduled event: Disconnect wait
2019-03-02 11:55:40,306 DEBUG:xmlstream:Event triggered: killed

Poezio version: e5e0533b  
Slixmpp version: poezio/slixmpp@2b666eb1de14e3ce74f17efd6b85723273e30333

## Steps to reproduce

- Start poezio
- Type `/quit` quite rapidly while poezio connects

## What I expect

Poezio quits, (taking its time to shutdown if necessary)

## What happens

"Nothing". The connection seems to get reset, and poezio is unusable. `/quit` triggers another "disconnect wait", `/reconnect` also seems to call `/quit`, etc..

## Logs

```
2019-03-02 11:55:32,673 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,673 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,673 DEBUG:roster_win:The roster has changed, rebuilding the cache…
2019-03-02 11:55:32,674 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,674 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,674 DEBUG:roster_win:Refresh: ContactInfoWin
2019-03-02 11:55:32,674 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,674 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:32,675 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,675 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,675 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,675 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,675 DEBUG:roster_win:Refresh: ContactInfoWin                                                                                                                                                                                                                
2019-03-02 11:55:32,676 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,676 DEBUG:input_placeholders:Refresh: HelpText                                                                                                                                                                                                              
2019-03-02 11:55:32,676 DEBUG:xmlstream:Event triggered: connecting
2019-03-02 11:55:32,676 DEBUG:disco:Looking up local disco#info data for None, node None.                                                                                                                                                                                       
2019-03-02 11:55:32,677 DEBUG:resolver:DNS: Querying SRV records for bouah.net
2019-03-02 11:55:32,678 DEBUG:core:Input is readable.
2019-03-02 11:55:32,678 DEBUG:core:Got from keyboard: (['/'],)
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Exception while querying for bouah.net SRV records: (4, 'Domain name not found')
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Querying bouah.net for AAAA records.
2019-03-02 11:55:32,711 DEBUG:resolver:DNS: Querying bouah.net for A records.
2019-03-02 11:55:32,852 DEBUG:core:Input is readable.
2019-03-02 11:55:32,852 DEBUG:core:Got from keyboard: (['q'],)
2019-03-02 11:55:32,952 DEBUG:xmlstream:Event triggered: connected
2019-03-02 11:55:32,953 DEBUG:rostertab:  TAB   Refresh: RosterInfoTab
2019-03-02 11:55:32,953 DEBUG:roster_win:Refresh: RosterWin
2019-03-02 11:55:32,954 DEBUG:misc:Refresh: VerticalSeparator
2019-03-02 11:55:32,954 DEBUG:text_win:Refresh: TextWin
2019-03-02 11:55:32,955 DEBUG:roster_win:Refresh: ContactInfoWin
2019-03-02 11:55:32,955 DEBUG:info_bar:Refresh: GlobalInfoBar
2019-03-02 11:55:32,956 DEBUG:inputs:Refresh: CommandInput
2019-03-02 11:55:32,956 DEBUG:xmlstream:SEND: <stream:stream to='bouah.net' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2019-03-02 11:55:33,003 DEBUG:core:Input is readable.
2019-03-02 11:55:33,004 DEBUG:core:Got from keyboard: (['u'],)
2019-03-02 11:55:33,090 DEBUG:core:Input is readable.
2019-03-02 11:55:33,091 DEBUG:core:Got from keyboard: (['i'],)
2019-03-02 11:55:33,122 DEBUG:core:Input is readable.
2019-03-02 11:55:33,122 DEBUG:core:Got from keyboard: (['t'],)
2019-03-02 11:55:33,197 DEBUG:xmlstream:RECV: <stream:stream xml:lang="en" from="bouah.net" id="9d881d4b-3af4-47d1-a5cd-a4c74ea70ddd" version="1.0">
2019-03-02 11:55:33,350 DEBUG:xmlstream:RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls></stream:features>
2019-03-02 11:55:33,353 DEBUG:xmlstream:SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls>
2019-03-02 11:55:33,353 DEBUG:core:Input is readable.
2019-03-02 11:55:33,353 DEBUG:core:Got from keyboard: (['^M'],)
2019-03-02 11:55:33,355 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-1"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/mood"><item id="current"><mood xmlns="http://jabber.org/protocol/mood" /></i
tem></publish></pubsub></iq>
2019-03-02 11:55:33,355 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-2"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/activity"><item id="current"><activity xmlns="http://jabber.org/protocol/act
ivity" /></item></publish></pubsub></iq>
2019-03-02 11:55:33,356 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-3"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="urn:xmpp:gaming:0"><item id="current"><gaming xmlns="urn:xmpp:gaming:0" /></item></publish></pubsub></i
q>
2019-03-02 11:55:33,356 DEBUG:roster:folded:

2019-03-02 11:55:33,360 DEBUG:xmlstream:SEND: </stream:stream>
2019-03-02 11:55:33,361 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:33,594 DEBUG:xmlstream:RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
2019-03-02 11:55:33,597 DEBUG:starttls:Starting TLS
2019-03-02 11:55:33,598 ERROR:stanzabase:Error handling {jabber:client}proceed stanza
Traceback (most recent call last):
  File "/home/ppjet/Src/slixmpp/master/slixmpp/xmlstream/handler/coroutine_callback.py", line 50, in pointer_wrapper
    await pointer(stanza, *args, **kwargs)
  File "/home/ppjet/Src/slixmpp/master/slixmpp/features/feature_starttls/starttls.py", line 64, in _handle_starttls_proceed
    if await self.xmpp.start_tls():
  File "/home/ppjet/Src/slixmpp/master/slixmpp/xmlstream/xmlstream.py", line 550, in start_tls
    self, ssl_context)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1134, in start_tls
    await waiter
  File "/usr/lib/python3.7/asyncio/selector_events.py", line 857, in write
    n = self._sock.send(data)
ConnectionResetError: [Errno 104] Connection reset by peer
2019-03-02 11:55:35,362 DEBUG:xmlstream:Scheduled event: Disconnect wait
2019-03-02 11:55:35,363 DEBUG:xmlstream:Event triggered: killed
2019-03-02 11:55:35,363 DEBUG:xmlstream:Event triggered: killed
2019-03-02 11:55:37,439 DEBUG:core:Input is readable.
2019-03-02 11:55:37,440 DEBUG:core:Got from keyboard: (['/'],)
2019-03-02 11:55:37,711 DEBUG:core:Input is readable.
2019-03-02 11:55:37,711 DEBUG:core:Got from keyboard: (['q'],)
2019-03-02 11:55:37,862 DEBUG:core:Input is readable.
2019-03-02 11:55:37,863 DEBUG:core:Got from keyboard: (['u'],)
2019-03-02 11:55:37,965 DEBUG:core:Input is readable.
2019-03-02 11:55:37,966 DEBUG:core:Got from keyboard: (['i'],)
2019-03-02 11:55:38,059 DEBUG:core:Input is readable.
2019-03-02 11:55:38,060 DEBUG:core:Got from keyboard: (['t'],)
2019-03-02 11:55:38,298 DEBUG:core:Input is readable.
2019-03-02 11:55:38,299 DEBUG:core:Got from keyboard: (['^M'],)
2019-03-02 11:55:38,300 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-4"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/mood"><item id="current"><mood xmlns="http://jabber.org/protocol/mood" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,301 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-5"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="http://jabber.org/protocol/activity"><item id="current"><activity xmlns="http://jabber.org/protocol/activity" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,301 DEBUG:xmlstream:SEND: <iq type="set" id="f990d030-925f-4da4-866b-6f99ff7d737e-6"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="urn:xmpp:gaming:0"><item id="current"><gaming xmlns="urn:xmpp:gaming:0" /></item></publish></pubsub></iq>
2019-03-02 11:55:38,302 DEBUG:roster:folded:

2019-03-02 11:55:38,304 DEBUG:xmlstream:SEND: </stream:stream>
2019-03-02 11:55:38,305 DEBUG:input_placeholders:Refresh: HelpText
2019-03-02 11:55:40,306 DEBUG:xmlstream:Scheduled event: Disconnect wait
2019-03-02 11:55:40,306 DEBUG:xmlstream:Event triggered: killed
```

Edited Mar 02, 2019 by Maxime Buquet

Discussion
Designs

The one place for your designs

To enable design management, you'll need to meet the requirements. If you need help, reach out to our support team for assistance.