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

Incorrect transport closing #197

Closed
rnesytov opened this issue Feb 17, 2020 · 1 comment · Fixed by #198
Closed

Incorrect transport closing #197

rnesytov opened this issue Feb 17, 2020 · 1 comment · Fixed by #198

Comments

@rnesytov
Copy link

Python 3.8.1
naz 0.7.8
MacOS 10.15.3

Hi, I found problem with Client.shutdown method. It causes asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 16 expected bytes every time I call it.

Here is the code to reproduce the problem:

import asyncio

import naz

broker = naz.broker.SimpleBroker(maxsize=1000)
client = naz.Client(smsc_host="127.0.0.1", smsc_port=2775, system_id="smppclient1", password="password", broker=broker,)


async def main():
    await client.connect(),
    await client.tranceiver_bind(),
    asyncio.gather(
        client.dequeue_messages(), client.receive_data(), client.enquire_link(),
    )

    while True:
        await asyncio.sleep(1)


if __name__ == "__main__":
    loop = asyncio.get_event_loop()

    try:
        loop.run_until_complete(main())
    except KeyboardInterrupt:
        loop.run_until_complete(client.shutdown())

Step to reproduce:

  • Start this code
  • Press Ctrl-C

Output

{"timestamp": "2020-02-17 17:50:15,477", "event": "naz.Client.connect", "stage": "start", "log_id": "t08u48h1pnp4rkqa6", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,478", "event": "naz.Client.connect", "stage": "end", "log_id": "t08u48h1pnp4rkqa6", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,478", "event": "naz.Client.tranceiver_bind", "stage": "start", "log_id": "3f4t4r0u04g7j6fk7", "smpp_command": "bind_transceiver", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,478", "event": "naz.Client.send_data", "stage": "start", "smpp_command": "bind_transceiver", "log_id": "3f4t4r0u04g7j6fk7", "msg": "\u0000\u0000\u0000*\u0000\u0000\u0000\t\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0002smppclient1\u0000{REDACTED}\u0000\u00004\u0000\u0000\u0000", "connection_lost": false, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,478", "event": "naz.Client.send_data", "stage": "end", "smpp_command": "bind_transceiver", "log_id": "3f4t4r0u04g7j6fk7", "msg": "\u0000\u0000\u0000*\u0000\u0000\u0000\t\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0002smppclient1\u0000{REDACTED}\u0000\u00004\u0000\u0000\u0000", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,479", "event": "naz.Client.tranceiver_bind", "stage": "end", "log_id": "3f4t4r0u04g7j6fk7", "smpp_command": "bind_transceiver", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,479", "event": "naz.Client.dequeue_messages", "stage": "start", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,479", "event": "naz.Client.receive_data", "stage": "start", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,480", "event": "naz.Client.send_data", "stage": "start", "smpp_command": "enquire_link", "log_id": "si6mbb5pe3mwak6kv", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0015\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0003", "connection_lost": false, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,480", "event": "naz.Client.send_data", "stage": "end", "smpp_command": "enquire_link", "log_id": "si6mbb5pe3mwak6kv", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0015\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0003", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,484", "event": "naz.Client.command_handlers", "stage": "start", "smpp_command": "bind_transceiver_resp", "log_id": "3f4t4r0u04g7j6fk7", "command_status": 0, "state": "Success", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,484", "event": "naz.Client.receive_data", "stage": "end", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,484", "event": "naz.Client.receive_data", "stage": "start", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,484", "event": "naz.Client.command_handlers", "stage": "start", "smpp_command": "enquire_link_resp", "log_id": "si6mbb5pe3mwak6kv", "command_status": 0, "state": "Success", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,485", "event": "naz.Client.receive_data", "stage": "end", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:15,489", "event": "naz.Client.receive_data", "stage": "start", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
^C{"timestamp": "2020-02-17 17:50:17,754", "event": "naz.Client.shutdown", "stage": "start", "state": "intiating shutdown", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,754", "event": "naz.Client.unbind", "stage": "start", "log_id": "vzjg212fyjdbny4oe", "smpp_command": "unbind", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,754", "event": "naz.Client.send_data", "stage": "start", "smpp_command": "unbind", "log_id": "vzjg212fyjdbny4oe", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0006\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0004", "connection_lost": false, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,755", "event": "naz.Client.send_data", "stage": "end", "smpp_command": "unbind", "log_id": "vzjg212fyjdbny4oe", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0006\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0004", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,755", "event": "naz.Client.unbind", "stage": "end", "log_id": "vzjg212fyjdbny4oe", "smpp_command": "unbind", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,755", "event": "naz.Client.receive_data", "stage": "end", "state": "unable to read exactly 16bytes of smpp header.", "error": "0 bytes read on a total of 16 expected bytes", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/zsmpp/shutdown_example.py", line 24, in <module>
    loop.run_until_complete(main())
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 599, in run_until_complete
    self.run_forever()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 567, in run_forever
    self._run_once()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 1819, in _run_once
    event_list = self._selector.select(timeout)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/selectors.py", line 558, in select
    kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/.venv/lib/python3.8/site-packages/naz/client.py", line 1726, in receive_data
    header_data = await self.reader.readexactly(self._header_pdu_length)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 721, in readexactly
    raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 16 expected bytes
{"timestamp": "2020-02-17 17:50:17,783", "event": "naz.Client.unbind", "stage": "start", "log_id": "187eapkdmq6o7arvh", "smpp_command": "unbind", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,783", "event": "naz.Client.send_data", "stage": "start", "smpp_command": "unbind", "log_id": "187eapkdmq6o7arvh", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0006\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0005", "connection_lost": true, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,784", "event": "naz.Client.re_establish_conn_bind", "stage": "start", "smpp_command": "unbind", "log_id": "187eapkdmq6o7arvh", "connection_lost": true, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,784", "event": "naz.Client.send_data", "stage": "end", "smpp_command": "unbind", "log_id": "187eapkdmq6o7arvh", "state": "unable to write to SMSC", "error": "Connection lost", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/zsmpp/shutdown_example.py", line 24, in <module>
    loop.run_until_complete(main())
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 599, in run_until_complete
    self.run_forever()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 567, in run_forever
    self._run_once()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 1819, in _run_once
    event_list = self._selector.select(timeout)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/selectors.py", line 558, in select
    kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/.venv/lib/python3.8/site-packages/naz/client.py", line 1726, in receive_data
    header_data = await self.reader.readexactly(self._header_pdu_length)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 721, in readexactly
    raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 16 expected bytes

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/.venv/lib/python3.8/site-packages/naz/client.py", line 1464, in send_data
    await self.writer.drain()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 387, in drain
    await self._protocol._drain_helper()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 190, in _drain_helper
    raise ConnectionResetError('Connection lost')
ConnectionResetError: Connection lost
{"timestamp": "2020-02-17 17:50:17,785", "event": "naz.Client.send_data", "stage": "end", "smpp_command": "unbind", "log_id": "187eapkdmq6o7arvh", "msg": "\u0000\u0000\u0000\u0010\u0000\u0000\u0000\u0006\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0005", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,785", "event": "naz.Client.unbind", "stage": "end", "log_id": "187eapkdmq6o7arvh", "smpp_command": "unbind", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
{"timestamp": "2020-02-17 17:50:17,785", "event": "naz.Client._unbind_and_disconnect", "stage": "end", "state": "unable to write to SMSC", "error": "Connection lost", "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}
Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/zsmpp/shutdown_example.py", line 24, in <module>
    loop.run_until_complete(main())
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 599, in run_until_complete
    self.run_forever()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 567, in run_forever
    self._run_once()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/base_events.py", line 1819, in _run_once
    event_list = self._selector.select(timeout)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/selectors.py", line 558, in select
    kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/.venv/lib/python3.8/site-packages/naz/client.py", line 1726, in receive_data
    header_data = await self.reader.readexactly(self._header_pdu_length)
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 721, in readexactly
    raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 16 expected bytes

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/rnesytov/zvooq/ZSMPP/.venv/lib/python3.8/site-packages/naz/client.py", line 2317, in _unbind_and_disconnect
    await self.writer.drain()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 387, in drain
    await self._protocol._drain_helper()
  File "/Users/rnesytov/.pyenv/versions/3.8.1/lib/python3.8/asyncio/streams.py", line 190, in _drain_helper
    raise ConnectionResetError('Connection lost')
ConnectionResetError: Connection lost
{"timestamp": "2020-02-17 17:50:17,786", "event": "naz.Client.receive_data", "stage": "start", "state": "no data received from SMSC. sleeping for 120.00 seconds", "retry_count": 1, "smsc_host": "127.0.0.1", "system_id": "smppclient1", "client_id": "SSGVP1MIUIHZQ5A54", "pid": 30649}

This line causes the error

naz/naz/client.py

Line 1726 in 10e44b1

header_data = await self.reader.readexactly(self._header_pdu_length)

But I think the real reason is here

naz/naz/client.py

Line 2318 in 10e44b1

self.writer.close()

Python documentation says that this method also closes TCP socket https://docs.python.org/3/library/asyncio-stream.html#asyncio.StreamWriter.close
And that, as I think, causes asyncio.exceptions.IncompleteReadError.

Instead of writer.close() there could be writer.write_eof, which only closes writer, but reader still can receive data.
https://docs.python.org/3/library/asyncio-stream.html#asyncio.StreamWriter.write_eof
@komuw
Copy link
Owner

komuw commented Feb 18, 2020

Instead of writer.close() there could be writer.write_eof, which only closes writer, but reader still can receive data.

That sounds like a good change.

@komuw komuw mentioned this issue Feb 18, 2020
Merged
komuw added a commit that referenced this issue Feb 18, 2020
@komuw
issues/197: During shutdown, close the writer & not reader (#198)
c74983c 
What:
- During shutdown, close the writer & not reader end of the transport protocol

Why:
- Fixes: #197
- `naz.Client.writer.close()` also closes the transport, on which both the `naz.Client.writer` and 
  `naz.Client.reader` are based on. This means that the reader is also closed. 
   This may not be what we want. When we call `naz.Client.shutdown()` we want to close the writer, 
   however; we want to still be able to read. This is because the SMSC may still send the `UNBIND_RESP` and we want to receive it
@komuw komuw mentioned this issue May 29, 2020
Closed
komuw added a commit that referenced this issue Sep 18, 2020
@komuw
add a test to check that; During shutdown, close the writer & not reader
30f6373 
This is to check that #197 is fixed.
This is an update to PR: #198
This was referenced Sep 18, 2020
Closed
Merged
komuw added a commit that referenced this issue Oct 2, 2020
@komuw
Release/0.8.1: When unbinding and disconnecting from SMSC, set SMPP s…
fa70c29 
…ession state to CLOSED (#214)

What:
- When unbinding and disconnecting from SMSC, set SMPP session state to CLOSED
- add a test to check that; during shutdown we close the writer & not reader

Why:
- Updates: #211
- Updates: #197
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

issues/197: During shutdown, close the writer & not reader komuw/naz
2 participants
@rnesytov @komuw