More of the functional tests are failing (microsoft#14346)

* Splitting test log

* Fix problem with kernels ports being reused

* Make kernel launcher port round robin only for testing

* Make formatters change only apply during testing

* Add news entry

* Apply black formatting

* Code review feedback and skip flakey remote password test

* Another flakey test

* More CR feedback

* Missed a spot

* Some more log parser changes and try to get interrupt to be less flakey

* Fix interrupt killing kernel and add more logging for export

* More logging

* See if updating fixes the problem

* Dont delete temp files

* Upload webview output to figure out trust failure

* Add name to step

* Try another way to upload

* Upload doesn't seem to work

* Try a different way to upload

* Try without webview logging as this makes the test pass

* Try fixing test another way. Any logging is making the test pass

* Compile error

.github/workflows/pr_datascience.yml

@@ -151,7 +151,7 @@ jobs:
         with:
           github_token: ${{ secrets.GITHUB_TOKEN }}
           report_paths: ${{ env.TEST_RESULTS_GLOB }}
-          check_name: Functional Test Report
+          check_name: Functional Test Report ${{matrix.test-suite}}
         if: steps.test_functional_group.outcome == 'failure' && failure()
 
   testsInVSCode:

.vscode/launch.json

@@ -292,7 +292,9 @@
                 // Remove `X` prefix and update path to test with real python interpreter (for DS functional tests).
                 "XCI_PYTHON_PATH": "<Python Path>",
                 // Remove 'X' prefix to dump output for debugger. Directory has to exist prior to launch
-                "XDEBUGPY_LOG_DIR": "${workspaceRoot}/tmp/Debug_Output"
+                "XDEBUGPY_LOG_DIR": "${workspaceRoot}/tmp/Debug_Output",
+                // Remove 'X' prefix to dump webview redux action log
+                "XVSC_PYTHON_WEBVIEW_LOG_FILE": "${workspaceRoot}/test-webview.log"
             },
             "outFiles": ["${workspaceFolder}/out/**/*.js", "!${workspaceFolder}/**/node_modules**/*"],
             "preLaunchTask": "Compile",

build/ci/scripts/runFunctionalTests.js

@@ -68,12 +68,13 @@ async function generateGroups(files) {
 
 async function runIndividualTest(extraArgs, file, index) {
     var subMochaFile = `${mochaBaseFile}_${index}_${path.basename(file)}${mochaFileExt}`;
-    process.env['MOCHA_FILE'] = subMochaFile;
     var args = gatherArgs(extraArgs, file);
     console.log(`Running functional test for file ${file} ...`);
     var exitCode = await new Promise((resolve) => {
         // Spawn the sub node process
-        var proc = child_process.fork('./node_modules/mocha/bin/_mocha', args);
+        var proc = child_process.fork('./node_modules/mocha/bin/_mocha', args, {
+            env: { ...process.env, MOCHA_FILE: subMochaFile }
+        });
         proc.on('exit', resolve);
     });
 

pythonFiles/vscode_datascience_helpers/jupyter_daemon.py

@@ -140,11 +140,15 @@ def _print_kernel_list_json(self):
         sys.stdout.flush()
 
     def _convert(self, args):
-        self.log.info("nbconvert")
+        self.log.info("Starting nbconvert wirth args %s", args)
         from nbconvert import nbconvertapp as app
 
-        sys.argv = [""] + args
-        app.main()
+        try:
+            sys.argv = [""] + args
+            app.main()
+        except Exception as e:
+            self.log.info("Nbconvert error: %s", e)
+            raise
 
     def _start_notebook(self, args, cwd, env):
         from notebook import notebookapp as app

pythonFiles/vscode_datascience_helpers/tests/logParser.py

@@ -1,3 +1,4 @@
+from io import TextIOWrapper
 import sys
 import argparse
 import os
@@ -18,13 +19,25 @@
 )
 ansi_escape = re.compile(r"\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])")
 pid_regex = re.compile(r"(\d+).*")
+timestamp_regex = re.compile(r"\d{4}-\d{2}-\d{2}T.*\dZ")
+
+
+def stripTimestamp(line: str):
+    match = timestamp_regex.match(line)
+    if match:
+        return line[match.end() :]
+    return line
+
+
+def readStripLines(f: TextIOWrapper):
+    return map(stripTimestamp, f.readlines())
 
 
 def printTestOutput(testlog):
     # Find all the lines that don't have a PID in them. These are the test output
     p = Path(testlog[0])
     with p.open() as f:
-        for line in f.readlines():
+        for line in readStripLines(f):
             stripped = line.strip()
             if len(stripped) > 2 and stripped[0] == "\x1B" and stripped[1] == "[":
                 print(line.rstrip())  # Should be a test line as it has color encoding
@@ -38,15 +51,14 @@ def splitByPid(testlog):
     logs = {}
     pid = None
     with p.open() as f:
-        for line in f.readlines():
+        for line in readStripLines(f):
             stripped = ansi_escape.sub("", line.strip())
-            # See if starts with a pid
-            if len(stripped) > 0 and stripped[0] <= "9" and stripped[0] >= "0":
+            if len(stripped) > 0:
                 # Pull out the pid
                 match = pid_regex.match(stripped)
 
                 # Pids are at least two digits
-                if match != None and len(match.group(1)) > 2:
+                if match and len(match.group(1)) > 2:
                     # Pid is found
                     pid = int(match.group(1))
 

src/client/datascience/export/exportBase.ts

@@ -56,7 +56,8 @@ export class ExportBase implements IExport {
             '--output',
             path.basename(tempTarget.filePath),
             '--output-dir',
-            path.dirname(tempTarget.filePath)
+            path.dirname(tempTarget.filePath),
+            '--debug'
         ];
         const result = await service.execModule('jupyter', ['nbconvert'].concat(args), {
             throwOnStdErr: false,

src/test/datascience/dataScienceIocContainer.ts

@@ -3,8 +3,6 @@
 //tslint:disable:trailing-comma no-any
 import * as child_process from 'child_process';
 import { ReactWrapper } from 'enzyme';
-import * as fs from 'fs-extra';
-import * as glob from 'glob';
 import { interfaces } from 'inversify';
 import * as os from 'os';
 import * as path from 'path';
@@ -27,7 +25,6 @@ import {
 import * as vsls from 'vsls/vscode';
 import { KernelDaemonPool } from '../../client/datascience/kernel-launcher/kernelDaemonPool';
 
-import { promisify } from 'util';
 import { LanguageServerExtensionActivationService } from '../../client/activation/activationService';
 import { LanguageServerDownloader } from '../../client/activation/common/downloader';
 import { JediExtensionActivator } from '../../client/activation/jedi';
@@ -500,18 +497,6 @@ export class DataScienceIocContainer extends UnitTestIocContainer {
         // Make sure to disable all command handling during dispose. Don't want
         // anything to startup again.
         this.commandManager.dispose();
-        try {
-            // Make sure to delete any temp files written by native editor storage
-            const globPr = promisify(glob);
-            const tempLocation = os.tmpdir;
-            const tempFiles = await globPr(`${tempLocation}/*.ipynb`);
-            if (tempFiles && tempFiles.length) {
-                await Promise.all(tempFiles.map((t) => fs.remove(t)));
-            }
-        } catch (exc) {
-            // tslint:disable-next-line: no-console
-            console.log(`Exception on cleanup: ${exc}`);
-        }
         await this.asyncRegistry.dispose();
         await super.dispose();
         this.disposed = true;

src/test/datascience/notebook.functional.test.ts

@@ -680,8 +680,8 @@ suite('DataScience notebook tests', () => {
                     try {
                         importer.dispose();
                         temp.dispose();
-                    } catch {
-                        // Don't care if they don't delete
+                    } catch (exc) {
+                        console.log(exc);
                     }
                 }
             });

src/test/datascience/raw-kernel/rawKernel.functional.test.ts

@@ -120,13 +120,23 @@ suite('DataScience raw kernel tests', () => {
         // Hence timeout is a test failure.
         const longCellExecutionRequest = requestExecute(
             rawKernel,
-            'import time\nfor i in range(300):\n    time.sleep(1)',
+            `
+import time
+import sys
+for i in range(3000):
+    sys.stdout.write('.')
+    sys.stdout.flush()
+    time.sleep(0.1)
+    sys.stdout.write('\\\r')`,
             executionStarted
         );
 
         // Wait until the execution has started (cuz we cannot interrupt until exec has started).
         await executionStarted.promise;
 
+        // Give it a bit to start running
+        await sleep(300);
+
         // Then throw the interrupt
         await rawKernel.interrupt();
 

src/test/datascience/trustedNotebooks.functional.test.tsx

@@ -6,6 +6,7 @@ import * as chaiAsPromised from 'chai-as-promised';
 import { ReactWrapper } from 'enzyme';
 import * as fs from 'fs-extra';
 import { Disposable } from 'vscode';
+import { sleep } from '../../client/common/utils/async';
 import { noop } from '../../client/common/utils/misc';
 import { InteractiveWindowMessages } from '../../client/datascience/interactive-common/interactiveWindowTypes';
 import { INotebookEditor, INotebookEditorProvider, ITrustService } from '../../client/datascience/types';
@@ -440,10 +441,14 @@ suite('DataScience Notebook trust', () => {
             // Reopen
             const newNativeEditor = await openEditor(ioc, baseFile, notebookFile.filePath);
             const newWrapper = newNativeEditor.mount.wrapper;
+            assert.ok(newNativeEditor.editor.model.isTrusted, 'Editor did not open as trusted');
+
+            // Wait a bit. UI doesn't seem to update right away
+            await sleep(500);
 
             // Verify notebook is now trusted
             const after = newWrapper.find(TrustMessage);
-            assert.equal(after.text(), 'Trusted');
+            assert.equal(after.text(), 'Trusted', 'Notebook UI not reflecting trust state');
         });
     });
 });