search

jquast / telnetlib3

Python Telnet server and client Protocol library using asyncio
Other
147 stars 32 forks source link

Reversed roles with CHARSET negotiation #59

Open amotzkau opened 2 years ago

amotzkau commented 2 years ago

It seems that telnetlib3 sends the CHARSET subnegotiation upon receiving a WILL CHARSET (and waits for the subnegotiation after receiving a DO CHARSET).

RFC 2066 says about the IAC SB CHARSET REQUEST:

This message initiates a new CHARSET subnegotiation. It can only be sent by a side that has received a DO CHARSET message and sent a WILL CHARSET message (in either order).

This is exactly the other way around.

And it also seems that telnetlib3 doesn't respond to a WILL CHARSET with a DO CHARSET, which I think it should.

jquast commented 1 year ago

@amotzkau can you suggest any telnet client and server that supports CHARSET negotiation?

I vaguely remember implementing against "Atlantis" MUD telnet client, which was the only reference I could find compatible with my computers at the time I developed it.

amotzkau commented 1 year ago

Mud clients (that I know of):

Except the one that we have, I'm not aware of servers implementing that:

gtaylor commented 1 year ago

Would this bug be causing us to hit connect_maxwait like this?

2023-02-19 00:43:58,216 DEBUG server.py:155 encoding failed after 4.00s: US-ASCII

Here's what Mudlet saw:

Server sent telnet IAC DO TTYPE (24)
We ARE willing to enable telnet option TERMINAL_TYPE
WE send telnet IAC WILL TTYPE (24)
Server sent telnet IAC WILL SUPPRESS_GO_AHEAD (3)
WE send telnet IAC DONT SUPPRESS_GO_AHEAD (3)
Server sent telnet IAC WILL ECHO (1)
WE send telnet IAC DO ECHO (1)
Enabling Server ECHOing of our output - perhaps he want us to type a password?
Server sent telnet IAC WILL BINARY (0)
WE send telnet IAC DONT BINARY (0)
Server sent telnet IAC DO NEW_ENVIRONMENT_OPTION (39)
We are NOT WILLING to enable this telnet option.
WE send telnet IAC WONT NEW_ENVIRONMENT_OPTION (39)
Server sent telnet IAC DO NAWS (31)
We ARE willing to enable telnet option NAWS
WE send telnet IAC WILL NAWS (31)
Server sent telnet IAC DO CHARSET (42)
WE send telnet IAC WILL CHARSET (42)
CHARSET enabled
Game changed encoding to "UTF-8"
Server sent telnet IAC WONT ECHO (1)
WE send telnet IAC DONT ECHO (1)
Server is stopping the ECHOing our output - so back to normal after, perhaps, sending a password...

Here are the complete session logs from the server side:

2023-02-19 00:53:16,590 INFO server_base.py:154 Connection from <Peer 127.0.0.1 40854>
2023-02-19 00:53:16,590 DEBUG stream_writer.py:2621 pending_option[DO + TTYPE] = True
2023-02-19 00:53:16,590 DEBUG stream_writer.py:673 send IAC DO TTYPE
2023-02-19 00:53:16,602 DEBUG stream_writer.py:434 recv IAC WILL TTYPE
2023-02-19 00:53:16,602 DEBUG stream_writer.py:1501 handle_will(TTYPE)
2023-02-19 00:53:16,602 DEBUG stream_writer.py:2621 remote_option[TTYPE] = True
2023-02-19 00:53:16,602 DEBUG stream_writer.py:870 send IAC SB TTYPE SEND IAC SE
2023-02-19 00:53:16,602 DEBUG stream_writer.py:2621 pending_option[SB + TTYPE] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[DO + TTYPE] = False
2023-02-19 00:53:16,603 DEBUG server_base.py:296 begin advanced negotiation
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[WILL + SGA] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC WILL SGA
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[WILL + ECHO] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC WILL ECHO
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[WILL + BINARY] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC WILL BINARY
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[DO + NEW_ENVIRON] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC DO NEW_ENVIRON
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[DO + NAWS] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC DO NAWS
2023-02-19 00:53:16,603 DEBUG stream_writer.py:2621 pending_option[DO + CHARSET] = True
2023-02-19 00:53:16,603 DEBUG stream_writer.py:673 send IAC DO CHARSET
2023-02-19 00:53:16,605 DEBUG stream_writer.py:414 sub-negotiation cmd TTYPE SE completion byte
2023-02-19 00:53:16,605 DEBUG stream_writer.py:2621 pending_option[SB + TTYPE] = False
2023-02-19 00:53:16,605 DEBUG stream_writer.py:1830 recv TTYPE IS: b'Mudlet 4.16.0'
2023-02-19 00:53:16,605 DEBUG stream_writer.py:1844 recv IAC SB TTYPE IS 'Mudlet 4.16.0'
2023-02-19 00:53:16,605 DEBUG server.py:435 ttype cycle cont at ttype1: Mudlet 4.16.0.
2023-02-19 00:53:16,605 DEBUG stream_writer.py:870 send IAC SB TTYPE SEND IAC SE
2023-02-19 00:53:16,605 DEBUG stream_writer.py:2621 pending_option[SB + TTYPE] = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:434 recv IAC DONT SGA
2023-02-19 00:53:16,609 DEBUG stream_writer.py:1471 handle_dont(SGA)
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[WILL + SGA] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 local_option[SGA] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:434 recv IAC DO ECHO
2023-02-19 00:53:16,609 DEBUG stream_writer.py:1381 handle_do(ECHO)
2023-02-19 00:53:16,609 DEBUG stream_writer.py:641 skip WILL ECHO; pending_option = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 local_option[ECHO] = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[WILL + ECHO] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:434 recv IAC DONT BINARY
2023-02-19 00:53:16,609 DEBUG stream_writer.py:1471 handle_dont(BINARY)
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[WILL + BINARY] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 local_option[BINARY] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:434 recv IAC WONT NEW_ENVIRON
2023-02-19 00:53:16,609 DEBUG stream_writer.py:1588 handle_wont(NEW_ENVIRON)
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 remote_option[NEW_ENVIRON] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[DO + NEW_ENVIRON] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:434 recv IAC WILL NAWS
2023-02-19 00:53:16,609 DEBUG stream_writer.py:1501 handle_will(NAWS)
2023-02-19 00:53:16,609 DEBUG stream_writer.py:641 skip DO NAWS; pending_option = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 remote_option[NAWS] = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[SB + NAWS] = True
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[DO + NAWS] = False
2023-02-19 00:53:16,609 DEBUG stream_writer.py:414 sub-negotiation cmd NAWS SE completion byte
2023-02-19 00:53:16,609 DEBUG stream_writer.py:2621 pending_option[SB + NAWS] = False
2023-02-19 00:53:16,610 DEBUG stream_writer.py:1964 recv IAC SB NAWS (cols=100, rows=33) IAC SE
2023-02-19 00:53:16,610 DEBUG stream_writer.py:434 recv IAC WILL CHARSET
2023-02-19 00:53:16,610 DEBUG stream_writer.py:1501 handle_will(CHARSET)
2023-02-19 00:53:16,610 DEBUG stream_writer.py:2621 remote_option[CHARSET] = True
2023-02-19 00:53:16,610 DEBUG stream_writer.py:785 send IAC SB CHARSET REQUEST UTF-8 UTF-16 LATIN1 US-ASCII BIG5 GBK SHIFTJIS GB18030 KOI8-R KOI8-U ISO8859-1 ISO8859-2 ISO8859-3 ISO8859-4 ISO8859-5 ISO8859-6 ISO8859-7 ISO8859-8 ISO8859-9 ISO8859-10 ISO8859-11 ISO8859-13 ISO8859-14 ISO8859-15 CP154 CP437 CP500 CP737 CP775 CP850 CP852 CP855 CP856 CP857 CP860 CP861 CP862 CP863 CP864 CP865 CP866 CP869 CP874 CP875 CP932 CP949 CP950 CP1006 CP1026 CP1140 CP1250 CP1251 CP1252 CP1253 CP1254 CP1255 CP1257 CP1257 CP1258 CP1361 IAC SE
2023-02-19 00:53:16,610 DEBUG stream_writer.py:2621 pending_option[SB + CHARSET] = True
2023-02-19 00:53:16,610 DEBUG stream_writer.py:2621 pending_option[DO + CHARSET] = False
2023-02-19 00:53:16,613 DEBUG stream_writer.py:414 sub-negotiation cmd TTYPE SE completion byte
2023-02-19 00:53:16,613 DEBUG stream_writer.py:2621 pending_option[SB + TTYPE] = False
2023-02-19 00:53:16,613 DEBUG stream_writer.py:1830 recv TTYPE IS: b'Mudlet 4.16.0'
2023-02-19 00:53:16,613 DEBUG stream_writer.py:1844 recv IAC SB TTYPE IS 'Mudlet 4.16.0'
2023-02-19 00:53:16,613 DEBUG server.py:416 ttype cycle stop at ttype2: Mudlet 4.16.0, looped.
2023-02-19 00:53:16,653 DEBUG stream_writer.py:414 sub-negotiation cmd CHARSET SE completion byte
2023-02-19 00:53:16,653 DEBUG stream_writer.py:2621 pending_option[SB + CHARSET] = False
2023-02-19 00:53:16,653 DEBUG stream_writer.py:1713 recv IAC SB CHARSET ACCEPTED UTF-8 IAC SE
2023-02-19 00:53:20,596 DEBUG server.py:155 encoding failed after 4.01s: US-ASCII
2023-02-19 00:53:20,596 DEBUG server_base.py:313 negotiation complete after 4.01s.
2023-02-19 00:53:20,596 DEBUG stream_writer.py:2621 local_option[ECHO] = False
2023-02-19 00:53:20,596 DEBUG stream_writer.py:673 send IAC WONT ECHO
2023-02-19 00:53:20,603 DEBUG stream_writer.py:434 recv IAC DONT ECHO
2023-02-19 00:53:20,603 DEBUG stream_writer.py:1471 handle_dont(ECHO)
jquast commented 1 year ago

I might consider just removing charset temporarily until a correct implementation can tested.

gtaylor commented 1 year ago

That may be safest. Probably not of much consolation, but Mudlet somehow ends up in the correct state despite the non-compliant negotiation!

jquast commented 1 year ago

Yeah I see that in the logs I've got mudlet installed and I hope to work it out over the weekend for next release

gtaylor commented 1 year ago

Cool! I was trying to take a shot at this but my unfamiliarity with the codebase made it impossible in the time I had. Happy to help test and refine once you've got the basics in place!