Add debug logging for Telnet protocol negotiation
[mudpy.git] / mudpy / tests / selftest.py
1 # Copyright (c) 2004-2018 Jeremy Stanley <fungi@yuggoth.org>. Permission
2 # to use, copy, modify, and distribute this software is granted under
3 # terms provided in the LICENSE file distributed with this software.
4
5 import os
6 import pathlib
7 import re
8 import shutil
9 import subprocess
10 import sys
11 import telnetlib
12 import time
13
14 pidfile = "var/mudpy.pid"
15
16 test_account0_setup = (
17     (0, "Identify yourself:", "luser0"),
18     (0, "Enter your choice:", "n"),
19     (0, 'Enter a new password for "luser0":', "Test123"),
20     (0, "Enter the same new password again:", "Test123"),
21     (0, r"What would you like to do\?", "c"),
22     (0, "Pick a birth gender for your new avatar:", "f"),
23     (0, "Choose a name for her:", "1"),
24     (0, "What would you like to do?", "a"),
25     (0, "Whom would you like to awaken?", ""),
26 )
27
28 test_account1_setup = (
29     (1, "Identify yourself:", "luser1"),
30     (1, "Enter your choice:", "n"),
31     (1, 'Enter a new password for "luser1":', "Test456"),
32     (1, "Enter the same new password again:", "Test456"),
33     (1, r"What would you like to do\?", "c"),
34     (1, "Pick a birth gender for your new avatar:", "m"),
35     (1, "Choose a name for him:", "1"),
36     (1, "What would you like to do?", "a"),
37     (1, "Whom would you like to awaken?", ""),
38 )
39
40 test_actor_appears = (
41     (0, r"You suddenly realize that .* is here\.", ""),
42 )
43
44 test_explicit_punctuation = (
45     (0, "> ", "say Hello there!"),
46     (0, r'You exclaim, "Hello there\!"', ""),
47     (1, r'exclaims, "Hello there\!"', "say And you are?"),
48     (1, r'You ask, "And you are\?"', ""),
49     (0, r'asks, "And you are\?"', "say I'm me, of course."),
50     (0, r'''You say, "I'm me, of course\."''', ""),
51     (1, r'''says, "I'm me, of course\."''', "say I wouldn't be so sure..."),
52     (1, r'''You muse, "I wouldn't be so sure\.\.\."''', ""),
53     (0, r'''muses, "I wouldn't be so sure\.\.\."''', "say You mean,"),
54     (0, 'You begin, "You mean,"', ""),
55     (1, 'begins, "You mean,"', "say I know-"),
56     (1, 'You begin, "I know-"', ""),
57     (0, 'begins, "I know-"', "say Don't interrupt:"),
58     (0, r'''You begin, "Don't interrupt:"''', ""),
59     (1, r'''begins, "Don't interrupt:"''', "say I wasn't interrupting;"),
60     (1, r'''You begin, "I wasn't interrupting;"''', ""),
61     (0, r'''begins, "I wasn't interrupting;"''', ""),
62 )
63
64 test_implicit_punctuation = (
65     (0, '> ', "say Whatever"),
66     (0, r'You say, "Whatever\."', ""),
67     (1, r'says, "Whatever\."', ""),
68 )
69
70 test_typo_replacement = (
71     (1, '> ', "say That's what i think."),
72     (1, r'''You say, "That's what I think\."''', ""),
73     (0, r'''says, "That's what I think\."''', "say You know what i'd like."),
74     (0, r'''You say, "You know what I'd like\."''', ""),
75     (1, r'''says, "You know what I'd like\."''', "say Then i'll tell you."),
76     (1, r'''You say, "Then I'll tell you\."''', ""),
77     (0, r'''says, "Then I'll tell you\."''', "say Now i'm ready."),
78     (0, r'''You say, "Now I'm ready\."''', ""),
79     (1, r'''says, "Now I'm ready\."''', "say That's teh idea."),
80     (1, r'''You say, "That's the idea\."''', ""),
81     (0, r'''says, "That's the idea\."''', "say It's what theyre saying."),
82     (0, r'''You say, "It's what they're saying\."''', ""),
83     (1, r'''says, "It's what they're saying\."''', "say Well, youre right."),
84     (1, r'''You say, "Well, you're right\."''', ""),
85     (0, r'''says, "Well, you're right\."''', ""),
86 )
87
88 test_sentence_capitalization = (
89     (0, "> ", "say this sentence should start with a capital T."),
90     (0, 'You say, "This sentence', ""),
91     (1, 'says, "This sentence', ""),
92 )
93
94 test_chat_mode = (
95     (1, '> ', "chat"),
96     (1, r'(?s)Entering chat mode .*> \(chat\) ', "Feeling chatty."),
97     (1, r'You say, "Feeling chatty\."', "!chat"),
98     (0, r'says, "Feeling chatty\."', ""),
99     (1, '> ', "say Now less chatty."),
100     (1, r'You say, "Now less chatty\."', ""),
101     (0, r'says, "Now less chatty\."', ""),
102 )
103
104 test_wrapping = (
105     (0, '> ', "say " + 100 * "o"),
106     (1, r'says,\r\n"O[o]+\."', ""),
107 )
108
109 test_forbid_ansi_input = (
110     (0, '> ', "say \x1b[35mfoo\x1b[0m"),
111     (1, r'says, "\[35mfoo\[0m\."', ""),
112 )
113
114 test_movement = (
115     (0, "> ", "move north"),
116     (0, r"You exit to the north\.", ""),
117     (1, r"exits to the north\.", "move north"),
118     (0, r"arrives from the south\.", "move south"),
119     (0, r"You exit to the south\.", ""),
120     (1, r"exits to the south\.", "move south"),
121     (0, r"arrives from the north\.", "move east"),
122     (0, r"You exit to the east\.", ""),
123     (1, r"exits to the east\.", "move east"),
124     (0, r"arrives from the west\.", "move west"),
125     (0, r"You exit to the west\.", ""),
126     (1, r"exits to the west\.", "move west"),
127     (0, r"arrives from the east\.", "move up"),
128     (0, r"You exit upward\.", ""),
129     (1, r"exits upward\.", "move up"),
130     (0, r"arrives from below\.", "move down"),
131     (0, r"You exit downward\.", ""),
132     (1, r"exits downward\.", "move down"),
133     (0, r"arrives from above\.", ""),
134 )
135
136 test_actor_disappears = (
137     (1, "> ", "quit"),
138     (0, r"You suddenly wonder where .* went\.", ""),
139 )
140
141 test_account1_teardown = (
142     (1, "What would you like to do?", "d"),
143     (1, "Whom would you like to delete?", ""),
144     (1, "What would you like to do?", "p"),
145     (1, "permanently delete your account?", "y"),
146     (1, "Disconnecting...", ""),
147 )
148
149 test_admin_setup = (
150     (2, "Identify yourself:", "admin"),
151     (2, "Enter your choice:", "n"),
152     (2, 'Enter a new password for "admin":', "Test789"),
153     (2, "Enter the same new password again:", "Test789"),
154     (2, r"What would you like to do\?", "c"),
155     (2, "Pick a birth gender for your new avatar:", "m"),
156     (2, "Choose a name for him:", "1"),
157     (2, "What would you like to do?", "a"),
158     (2, "Whom would you like to awaken?", ""),
159 )
160
161 test_crlf_eol = (
162     # Send a CR+LF at the end of the line instead of the default CR+NUL,
163     # to make sure they're treated the same
164     (2, "> ", b"say I use CR+LF as my EOL, not CR+NUL.\r\n"),
165     (2, r'You say, "I use CR\+LF as my EOL, not CR\+NUL\.".*> ', ""),
166 )
167
168 test_telnet_iac = (
169     # Send a double (escaped) IAC byte within other text, which should get
170     # unescaped and deduplicated to a single \xff in the buffer and then
171     # the line of input discarded as a non-ASCII sequence
172     (2, "> ", b"say argle\xff\xffbargle\r\0"),
173     (2, r"Non-ASCII characters from admin: b'say argle\\xffbargle'.*> ", ""),
174 )
175
176 test_telnet_unknown = (
177     # Send an unsupported negotiation command #127 which should get filtered
178     # from the line of input
179     (2, "> ", b"say glop\xff\x7fglyf\r\0"),
180     (2, r'Ignored unknown command 127 from admin\..*"Glopglyf\.".*> ', ""),
181 )
182
183 test_admin_restriction = (
184     (0, "> ", "help halt"),
185     (0, r"That is not an available command\.", "halt"),
186     (0, '(not sure what "halt" means|Arglebargle, glop-glyf)', ""),
187 )
188
189 test_admin_help = (
190     (2, "> ", "help"),
191     (2, r"halt.*Shut down the world\.", "help halt"),
192     (2, "This will save all active accounts", ""),
193 )
194
195 test_reload = (
196     (2, "> ", "reload"),
197     (2, r"Reloading all code modules, configs and data\."
198         r".* User admin reloaded the world\.",
199      "show element account.admin"),
200     (2, 'These are the properties of the "account.admin" element.*'
201         r'  \x1b\[32mpasshash:\r\n\x1b\[31m\$.*> ', ""),
202 )
203
204 test_set_facet = (
205     (2, "> ", "set actor.avatar_admin_0 gender female"),
206     (2, r'You have successfully \(re\)set the "gender" facet of element', ""),
207 )
208
209 test_set_refused = (
210     (2, "> ", "set mudpy.limit password_tries 10"),
211     (2, r'The "mudpy\.limit" element is kept in read-only file', ""),
212 )
213
214 test_show_version = (
215     (2, "> ", "show version"),
216     (2, r"Running mudpy .* on .* Python 3.*with.*pyyaml.*> ", ""),
217 )
218
219 test_show_files = (
220     (2, "> ", "show files"),
221     (2, r'These are the current files containing the universe:.*'
222         r'  \x1b\[31m\(rw\) \x1b\[32m/.*/account.yaml\x1b\[0m'
223         r' \x1b\[33m\[private\]\x1b\[0m.*> ', ""),
224 )
225
226 test_show_file = (
227     (2, "> ", "show file %s" %
228         os.path.join(os.getcwd(), "data/internal.yaml")),
229     (2, r'These are the nodes in the.*file:.*internal\.counters.*> ', ""),
230 )
231
232 test_show_groups = (
233     (2, "> ", "show groups"),
234     (2, r'These are the element groups:.*'
235         r'  \x1b\[32maccount\x1b\[0m.*> ', ""),
236 )
237
238 test_show_group = (
239     (2, "> ", "show group account"),
240     (2, r'These are the elements in the "account" group:.*'
241         r'  \x1b\[32maccount\.admin\x1b\[0m.*> ', ""),
242 )
243
244 test_show_element = (
245     (2, "> ", "show element mudpy.limit"),
246     (2, r'These are the properties of the "mudpy\.limit" element.*'
247         r'  \x1b\[32mpassword_tries: \x1b\[31m3.*> ',
248      "show element actor.avatar_admin_0"),
249     (2, r'These are the properties of the "actor.avatar_admin_0" element.*'
250         r'  \x1b\[32mgender: \x1b\[31mfemale.*> ', ""),
251 )
252
253 test_show_log = (
254     (2, "> ", "show log"),
255     (2, r"There are [0-9]+ log lines in memory and [0-9]+ at or above level "
256         r"[0-9]+\. The matching lines\r\nfrom [0-9]+ to [0-9]+ are:", ""),
257 )
258
259 test_custom_loglevel = (
260     (2, "> ", "set account.admin loglevel 2"),
261     (2, "You have successfully .*> ", "show log"),
262     (2, r"There are [0-9]+ log lines in memory and [0-9]+ at or above level "
263         r"[0-9]+\. The matching lines\r\nfrom [0-9]+ to [0-9]+ are:", ""),
264 )
265
266 test_invalid_loglevel = (
267     (2, "> ", "set account.admin loglevel two"),
268     (2, r'''Value "two" of type "<class 'str'>" cannot be coerced .*> ''', ""),
269 )
270
271 test_log_no_errors = (
272     (2, "> ", "show log 7"),
273     (2, r"None of the [0-9]+ lines in memory matches your request\.", ""),
274 )
275
276 final_cleanup = (
277     (0, "> ", "quit"),
278     (0, "What would you like to do?", "d"),
279     (0, "Whom would you like to delete?", ""),
280     (0, "What would you like to do?", "p"),
281     (0, "permanently delete your account?", "y"),
282     (0, "Disconnecting...", ""),
283     (2, "> ", "quit"),
284     (2, "What would you like to do?", "d"),
285     (2, "Whom would you like to delete?", ""),
286     (2, "What would you like to do?", "p"),
287     (2, "permanently delete your account?", "y"),
288     (2, "Disconnecting...", ""),
289 )
290
291 dialogue = (
292     (test_account0_setup, "first account setup"),
293     (test_account1_setup, "second account setup"),
294     (test_actor_appears, "actor spontaneous appearance"),
295     (test_explicit_punctuation, "explicit punctuation"),
296     (test_implicit_punctuation, "implicit punctuation"),
297     (test_typo_replacement, "typo replacement"),
298     (test_sentence_capitalization, "sentence capitalization"),
299     (test_chat_mode, "chat mode"),
300     (test_wrapping, "wrapping"),
301     (test_forbid_ansi_input, "raw escape input is filtered"),
302     (test_movement, "movement"),
303     (test_actor_disappears, "actor spontaneous disappearance"),
304     (test_account1_teardown, "second account teardown"),
305     (test_admin_setup, "admin account setup"),
306     (test_crlf_eol, "send crlf from the client as eol"),
307     (test_telnet_iac, "escape stray telnet iac bytes"),
308     (test_telnet_unknown, "strip unknown telnet command"),
309     (test_admin_restriction, "restricted admin commands"),
310     (test_admin_help, "admin help"),
311     (test_reload, "reload"),
312     (test_set_facet, "set facet"),
313     (test_set_refused, "refuse altering read-only element"),
314     (test_show_version, "show version and diagnostic info"),
315     (test_show_files, "show a list of loaded files"),
316     (test_show_file, "show nodes from a specific file"),
317     (test_show_groups, "show groups"),
318     (test_show_group, "show group"),
319     (test_show_element, "show element"),
320     (test_show_log, "show log"),
321     (test_custom_loglevel, "custom loglevel"),
322     (test_invalid_loglevel, "invalid loglevel"),
323     (test_log_no_errors, "no errors logged"),
324     (final_cleanup, "delete remaining accounts"),
325 )
326
327
328 def start_service(config):
329     # Clean up any previously run daemon which didn't terminate
330     if os.path.exists(pidfile):
331         pidfd = open(pidfile)
332         pid = int(pidfd.read())
333         try:
334             # Stop the running service
335             os.kill(pid, 15)
336             time.sleep(1)
337         except ProcessLookupError:
338             # If there was no process, just remove the stale PID file
339             os.remove(pidfile)
340         # If there's a preexisting hung service, we can't proceed
341         assert not os.path.exists(pidfile)
342
343     # Clean up any previous test output
344     for f in pathlib.Path(".").glob("capture_*.log"):
345         # have to use .name here since remove() doesn't support passing a
346         # PosixPath argument until Python3.6
347         os.remove(f.name)
348     for d in ("data", "var"):
349         shutil.rmtree(d, ignore_errors=True)
350     os.mkdir("var")
351
352     # Start the service and wait for it to be ready for connections
353     service = subprocess.Popen(("mudpy", config),
354                                stdout=subprocess.PIPE,
355                                stderr=subprocess.PIPE)
356     time.sleep(1)
357     return(service)
358
359
360 def stop_service(service):
361     success = True
362
363     # The no-op case when no service was started
364     if service is None:
365         return(success)
366
367     # This handles when the service is running as a direct child process
368     service.terminate()
369     returncode = service.wait(10)
370     if returncode != 0:
371         tlog("\nERROR: Service exited with code %s." % returncode)
372         success = False
373
374     # This cleans up a daemonized and disassociated service
375     if os.path.exists(pidfile):
376         pidfd = open(pidfile)
377         pid = int(pidfd.read())
378         try:
379             # Stop the running service
380             os.kill(pid, 15)
381             time.sleep(1)
382         except ProcessLookupError:
383             # If there was no process, just remove the stale PID file
384             os.remove(pidfile)
385         # The PID file didn't disappear, so we have a hung service
386         if os.path.exists(pidfile):
387             tlog("\nERROR: Hung daemon with PID %s." % pid)
388             success = False
389
390     # Log the contents of stdout and stderr, if any
391     stdout, stderr = service.communicate()
392     tlog("\nRecording stdout as capture_stdout.log.")
393     serviceout = open("capture_stdout.log", "w")
394     serviceout.write(stdout.decode("utf-8"))
395     tlog("\nRecording stderr as capture_stderr.log.")
396     serviceerr = open("capture_stderr.log", "w")
397     serviceerr.write(stderr.decode("utf-8"))
398
399     return(success)
400
401
402 def tlog(message, quiet=False):
403     logfile = "capture_tests.log"
404     with open(logfile, "a") as logfd:
405         logfd.write(message + "\n")
406     if not quiet:
407         sys.stdout.write(message)
408     return True
409
410
411 def main():
412     captures = ["", "", ""]
413     lusers = [telnetlib.Telnet(), telnetlib.Telnet(), telnetlib.Telnet()]
414     success = True
415     start = time.time()
416     service = None
417     if len(sys.argv) > 1:
418         # Start the service if a config file was provided on the command line
419         service = start_service(sys.argv[1])
420     for luser in lusers:
421         luser.open("::1", 4000)
422     for test, description in dialogue:
423         tlog("\nTesting %s..." % description)
424         test_start = time.time()
425         for conversant, question, answer in test:
426             tlog("luser%s waiting for: %s" % (conversant, question),
427                  quiet=True)
428             try:
429                 index, match, received = lusers[conversant].expect(
430                     [re.compile(question.encode("utf-8"), flags=re.DOTALL)], 5)
431                 captures[conversant] += received.decode("utf-8")
432             except ConnectionResetError:
433                 tlog("\nERROR: Unable to connect to server.")
434                 success = False
435                 break
436             except EOFError:
437                 tlog("\nERROR: luser%s premature disconnection expecting:\n\n"
438                      "%s\n\n"
439                      "Check the end of capture_%s.log for received data."
440                      % (conversant, question, conversant))
441                 success = False
442                 break
443             try:
444                 captures[conversant] += lusers[
445                     conversant].read_very_eager().decode("utf-8")
446             except Exception:
447                 pass
448             if index is not 0:
449                 tlog("\nERROR: luser%s did not receive expected string:\n\n"
450                      "%s\n\n"
451                      "Check the end of capture_%s.log for received data."
452                      % (conversant, question, conversant))
453                 success = False
454                 break
455             if type(answer) is str:
456                 tlog("luser%s sending: %s" % (conversant, answer), quiet=True)
457                 lusers[conversant].write(("%s\r\0" % answer).encode("utf-8"))
458                 captures[conversant] += "%s\r\n" % answer
459             elif type(answer) is bytes:
460                 tlog("luser%s sending raw bytes: %s" % (conversant, answer),
461                      quiet=True)
462                 lusers[conversant].get_socket().send(answer)
463                 captures[conversant] += "!!!RAW BYTES: %s" % answer
464             else:
465                 tlog("\nERROR: answer provided with unsupported type %s"
466                      % type(answer))
467                 success = False
468                 break
469         if not success:
470             break
471         tlog("Completed in %.3f seconds." % (time.time() - test_start))
472     duration = time.time() - start
473     for conversant in range(len(captures)):
474         try:
475             captures[conversant] += lusers[
476                 conversant].read_very_eager().decode("utf-8")
477         except Exception:
478             pass
479         lusers[conversant].close()
480         logfile = "capture_%s.log" % conversant
481         tlog("\nRecording session %s as %s." % (conversant, logfile))
482         log = open(logfile, "w")
483         log.write(captures[conversant])
484         log.close()
485     if not stop_service(service):
486         success = False
487     tlog("\nRan %s tests in %.3f seconds." % (len(dialogue), duration))
488     if success:
489         tlog("\nSUCCESS\n")
490     else:
491         tlog("\nFAILURE\n")
492         sys.exit(1)
493
494
495 if __name__ == '__main__':
496     sys.exit(main())