Add tests for the asynchronous logging assertion feature

This commit also fixes various issues with asynchronous logging: - Standard output could not be an exception if followed by a log. - Unrelated comments were treated as outputs when following a log. - Channel mismatches were not handled. - Inconsistencies in how assertions were shown. - Incorrect handling of exception assertions. It also adds a feature that hints users who don't get their expected output that it may have happened because their test timed out.
davidchambers · Jun 12, 2020 · 3bae914 · 3bae914
1 parent 0a8b1e1
commit 3bae914
Show file tree

Hide file tree

Showing 3 changed files with 126 additions and 32 deletions.
diff --git a/lib/doctest.js b/lib/doctest.js
@@ -182,9 +182,14 @@ var INPUT = 'input';
 var OUTPUT = 'output';
 var LOG = 'log';
 
+//  isStandardOutput :: { channel :: Nullable String } -> Boolean
+function isStandardOutput(output) {
+  return output.channel == null;
+}
+
 //  normalizeTest :: { output :: { value :: String } } -> Undefined
 function normalizeTest($test) {
-  $test[OUTPUT].forEach (function($output) {
+  ($test[OUTPUT].filter (isStandardOutput)).forEach (function($output) {
     var match = $output.value.match (/^![ ]?([^:]*)(?::[ ]?(.*))?$/);
     $test['!'] = match != null;
     if ($test['!']) {
@@ -241,14 +246,16 @@ function processLine(
       });
       output ($test);
     } else if (accum.state === INPUT || accum.state === LOG) {
-      accum.state = OUTPUT;
-      value = trimmedLine;
       $test = last (accum.tests);
-      $test[OUTPUT].push ({
-        channel: null,
-        value: value
-      });
-      output ($test);
+      if (!$test[OUTPUT].some (isStandardOutput)) {
+        accum.state = OUTPUT;
+        value = trimmedLine;
+        $test[OUTPUT].push ({
+          channel: null,
+          value: value
+        });
+        output ($test);
+      }
     }
   }
 }
@@ -671,21 +678,39 @@ function run(options, queue, logMediator) {
         return '! ' + value.name + value.message.replace (/^(?!$)/, ': ');
       }
 
-      function showOutput(asError, output) {
-        return output.channel == null ? (
-          asError ? showError (output.value) : show (output.value)
-        ) : (
-          '[' + output.channel + ']: ' + show (output.value)
-        );
+      function showOutput(output) {
+        return (isStandardOutput (output)) ?
+               (errored ? showError (output.value) : show (output.value)) :
+               ('[' + output.channel + ']: ' + show (output.value));
+      }
+
+      function showExpected(expected) {
+        return (isStandardOutput (expected)) ?
+               (io['!'] ? showError (expected.value) : show (expected.value)) :
+               ('[' + expected.channel + ']: ' + show (expected.value));
       }
 
       function verifyOutput() {
         outputs.forEach (function(output, idx) {
           var expected = expecteds[idx];
-          var pass, actualRepr, expectedRepr;
+          var actualRepr = showOutput (output);
+
+          if (!expected) {
+            return void accum.results.push ([
+              false,
+              actualRepr,
+              'no output',
+              // TODO: Show location of input once io is a single structure.
+              '-'
+            ]);
+          }
 
-          if (expected) {
-            expectedRepr = showOutput (io['!'], expected);
+          var pass = false;
+          var expectedRepr = showExpected (expected);
+
+          if (expected.channel !== output.channel) {
+            pass = false;
+          } else if (isStandardOutput (output)) {
             if (errored) {
               var name = output.value.name;
               var message = output.value.message;
@@ -695,32 +720,24 @@ function run(options, queue, logMediator) {
                      expected.value.message.replace (/^$/, message);
               actualRepr = io['!'] && expected.value.message === '' ?
                            '! ' + output.value.name :
-                           showOutput (true, output);
+                           showOutput (output);
             } else {
               pass = !io['!'] && Z.equals (output.value, expected.value);
-              actualRepr = showOutput (false, output);
             }
           } else {
-            pass = false;
-            expectedRepr = 'no output';
-            actualRepr = showOutput (errored, output);
+            pass = Z.equals (output.value, expected.value);
           }
 
-          accum.results.push ([
-            pass,
-            actualRepr,
-            expectedRepr,
-            expected.loc
-          ]);
+          accum.results.push ([pass, actualRepr, expectedRepr, expected.loc]);
         });
 
         expecteds
         .slice (outputs.length)
         .forEach (function(expected) {
           accum.results.push ([
             false,
-            'no output',
-            showOutput (io['!'], expected),
+            'no output' + (isStandardOutput (expected) ? '' : ' fast enough'),
+            showExpected (expected),
             expected.loc
           ]);
         });

diff --git a/test/index.js b/test/index.js
@@ -234,6 +234,23 @@ testCommand ('bin/doctest --log-function stdout --log-function stderr test/share
   stderr: ''
 });
 
+testCommand ('bin/doctest --log-function stdout test/shared/logging.js', {
+  status: 1,
+  stdout: unlines ([
+    'running doctests in test/shared/logging.js...',
+    '.........xx.xxxx..x..x',
+    'FAIL: expected [stdout]: 2 on line 33 (got 3)',
+    'FAIL: expected 3 on line 34 (got no output)',
+    'FAIL: expected 3 on line 40 (got [stdout]: 2)',
+    'FAIL: expected no output on line - (got 3)',
+    'FAIL: expected [stdout]: 2 on line 45 (got [stdout]: 1)',
+    'FAIL: expected [stdout]: 1 on line 46 (got [stdout]: 2)',
+    'FAIL: expected [stderr]: 2 on line 53 (got [stdout]: 2)',
+    'FAIL: expected [stdout]: 1 on line 60 (got no output fast enough)'
+  ]),
+  stderr: ''
+});
+
 testCommand ('bin/doctest --module commonjs lib/doctest.js', {
   status: 0,
   stdout: unlines ([
@@ -278,9 +295,9 @@ if (esmSupported) {
       'running doctests in test/esm/async.mjs...',
       'xxxx',
       'FAIL: expected [stdout]: 1 on line 4 (got ! ReferenceError: stdout is not defined)',
-      'FAIL: expected [stderr]: 3 on line 5 (got no output)',
+      'FAIL: expected [stderr]: 3 on line 5 (got no output fast enough)',
       'FAIL: expected undefined on line 6 (got no output)',
-      'FAIL: expected [stdout]: 2 on line 7 (got no output)'
+      'FAIL: expected [stdout]: 2 on line 7 (got no output fast enough)'
     ]),
     stderr: ''
   });

diff --git a/test/shared/logging.js b/test/shared/logging.js
@@ -0,0 +1,60 @@
+function crash(){
+  throw new Error;
+}
+
+// Synchronous log with output
+//
+// > (stdout (1), 2)
+// [stdout]: 1
+// 2
+
+// Synchronous log with exception
+//
+// > (stdout (1), crash())
+// [stdout]: 1
+// ! Error
+
+// Asynchronous log with output
+//
+// > (setImmediate (stdout, 1), 2)
+// 2
+// [stdout]: 1
+
+// Asynchronous log with exception
+//
+// > (setImmediate (stdout, 1), crash())
+// ! Error
+// [stdout]: 1
+
+// Failure due to not enough output
+//
+// > (stdout (1), 3)
+// [stdout]: 1
+// [stdout]: 2
+// 3
+
+// Failure due to too much output
+//
+// > (stdout (1), stdout (2), 3)
+// [stdout]: 1
+// 3
+
+// Failure due to incorrectly ordered output
+//
+// > (stdout (1), stdout (2), 3)
+// [stdout]: 2
+// [stdout]: 1
+// 3
+
+// Failure due to output on the wrong channel
+//
+// > (stdout (1), stdout (2), 3)
+// [stdout]: 1
+// [stderr]: 2
+// 3
+
+// Failure due to timing out
+//
+// > (setTimeout (stdout, 200, 1), 2)
+// 2
+// [stdout]: 1