Fix nightly functional tests failures for datascience (microsoft#6591)

rchiodo · web-flow · commit 5e92f61146ca · 2019-07-15T15:15:38.000-07:00
* Fix stack trace issues

* Attempt to fix restart issues with restart kernel.

* Add async dump for long running test

* Fix loop for session

* Try waiting longer for shutdown

* Put async dump back the way it was before.

* Use pypi to install ptvsd

* Add more logging

* More logging

* More logging

* Just run functional tests

* Remote ready session work. Only wait for ready on restart.

* Fix debugger tests. Try not shutting down during restart

* More logging

* Put off restart session

* Add some more logging

* More logging

* More logging

* Fix restart bug

* More logging

* Linter errors

* Loop for idle for restart

* Fix linter errors

* Let ptvsd be installed

* Update package-lock

* Remove some logging

* Put ptvsd back in the functional requirements. Installer isn't working

* Remove some logging and put back full nightly

* Remove some logging

* Up timeout to 90 minutes
diff --git a/build/ci/templates/test_phases.yml b/build/ci/templates/test_phases.yml
@@ -203,6 +203,7 @@ steps:
       python -m pip install -U pip
       python -m pip install numpy
       python -m pip install --upgrade -r ./build/functional-test-requirements.txt
+      python -m pip install --upgrade --pre ptvsd
     displayName: 'pip install functional requirements'
     condition: and(succeeded(), eq(variables['NeedsPythonFunctionalReqs'], 'true'))
 
diff --git a/build/ci/vscode-python-nightly-ci.yaml b/build/ci/vscode-python-nightly-ci.yaml
@@ -34,7 +34,7 @@ jobs:
 #       ignorePythonVersions: "3.6,3.5"
 
 - job: 'Nightly'
-
+  timeoutInMinutes: 90
   strategy:
     matrix:
       # Each member of this list must contain these values:
diff --git a/build/functional-test-requirements.txt b/build/functional-test-requirements.txt
@@ -4,4 +4,4 @@ jupyter
 numpy
 matplotlib
 pandas
-livelossplot
+livelossplot
diff --git a/src/client/datascience/jupyter/jupyterServer.ts b/src/client/datascience/jupyter/jupyterServer.ts
@@ -14,7 +14,7 @@ import { CancellationToken } from 'vscode-jsonrpc';
 
 import { ILiveShareApi } from '../../common/application/types';
 import { Cancellation, CancellationError } from '../../common/cancellation';
-import { traceInfo, traceWarning } from '../../common/logger';
+import { traceError, traceInfo, traceWarning } from '../../common/logger';
 import { IAsyncDisposableRegistry, IConfigurationService, IDisposableRegistry, ILogger } from '../../common/types';
 import { createDeferred, Deferred, waitForPromise } from '../../common/utils/async';
 import * as localize from '../../common/utils/localize';
@@ -44,17 +44,21 @@ class CellSubscriber {
     private cellRef: ICell;
     private subscriber: Subscriber<ICell>;
     private promiseComplete: (self: CellSubscriber) => void;
-    private startTime: number;
+    private _startTime: number;
 
     constructor(cell: ICell, subscriber: Subscriber<ICell>, promiseComplete: (self: CellSubscriber) => void) {
         this.cellRef = cell;
         this.subscriber = subscriber;
         this.promiseComplete = promiseComplete;
-        this.startTime = Date.now();
+        this._startTime = Date.now();
+    }
+
+    public get startTime(): number {
+        return this._startTime;
     }
 
     public isValid(sessionStartTime: number | undefined) {
-        return sessionStartTime && this.startTime > sessionStartTime;
+        return sessionStartTime && this.startTime >= sessionStartTime;
     }
 
     public next(sessionStartTime: number | undefined) {
@@ -305,15 +309,19 @@ export class JupyterServerBase implements INotebookServer {
             // Update our start time so we don't keep sending responses
             this.sessionStartTime = Date.now();
 
+            traceInfo('restartKernel - finishing cells that are outstanding');
             // Complete all pending as an error. We're restarting
             this.finishUncompletedCells();
+            traceInfo('restartKernel - restarting kernel');
 
             // Restart our kernel
             await this.session.restart(timeoutMs);
 
             // Rerun our initial setup for the notebook
             this.ranInitialSetup = false;
+            traceInfo('restartKernel - initialSetup');
             await this.initialNotebookSetup();
+            traceInfo('restartKernel - initialSetup completed');
 
             return;
         }
@@ -531,6 +539,8 @@ export class JupyterServerBase implements INotebookServer {
             }
         }
 
+        traceError('No session during execute observable');
+
         // Can't run because no session
         return new Observable<ICell[]>(subscriber => {
             subscriber.error(this.getDisposedError());
@@ -539,7 +549,7 @@ export class JupyterServerBase implements INotebookServer {
     }
 
     private generateRequest = (code: string, silent?: boolean): Kernel.IFuture | undefined => {
-        //this.logger.logInformation(`Executing code in jupyter : ${code}`)
+        //traceInfo(`Executing code in jupyter : ${code}`);
         try {
             const cellMatcher = new CellMatcher(this.configService.getSettings().datascience);
             return this.session ? this.session.requestExecute(
@@ -563,25 +573,29 @@ export class JupyterServerBase implements INotebookServer {
     // Set up our initial plotting and imports
     private async initialNotebookSetup(cancelToken?: CancellationToken): Promise<void> {
         if (this.ranInitialSetup) {
+            traceInfo(`Already ran setup for ${this.id}`);
             return;
         }
         this.ranInitialSetup = true;
 
         try {
             // When we start our notebook initial, change to our workspace or user specified root directory
             if (this.launchInfo && this.launchInfo.workingDir && this.launchInfo.connectionInfo.localLaunch) {
+                traceInfo(`Changing directory for ${this.id}`);
                 await this.changeDirectoryIfPossible(this.launchInfo.workingDir);
             }
 
             const settings = this.configService.getSettings().datascience;
             const matplobInit = !settings || settings.enablePlotViewer ? CodeSnippits.MatplotLibInitSvg : CodeSnippits.MatplotLibInitPng;
 
+            traceInfo(`Initialize matplotlib for ${this.id}`);
             // Force matplotlib to inline and save the default style. We'll use this later if we
             // get a request to update style
             await this.executeSilently(
                 matplobInit,
                 cancelToken
             );
+            traceInfo(`Initial setup complete for ${this.id}`);
         } catch (e) {
             traceWarning(e);
         }
@@ -640,6 +654,7 @@ export class JupyterServerBase implements INotebookServer {
             if (this.launchInfo && this.launchInfo.connectionInfo && this.launchInfo.connectionInfo.localProcExitCode) {
                 // Not running, just exit
                 const exitCode = this.launchInfo.connectionInfo.localProcExitCode;
+                traceError(`Jupyter crashed with code ${exitCode}`);
                 subscriber.error(this.sessionStartTime, new Error(localize.DataScience.jupyterServerCrashed().format(exitCode.toString())));
                 subscriber.complete(this.sessionStartTime);
             } else {
@@ -716,6 +731,10 @@ export class JupyterServerBase implements INotebookServer {
                 }
             }
         } else {
+            const sessionDate = new Date(this.sessionStartTime!);
+            const cellDate = new Date(subscriber.startTime);
+            traceInfo(`Session start time is newer than cell : \r\n${sessionDate.toTimeString()}\r\n${cellDate.toTimeString()}`);
+
             // Otherwise just set to an error
             this.handleInterrupted(subscriber.cell);
             subscriber.cell.state = CellState.error;
diff --git a/src/client/datascience/jupyter/jupyterSession.ts b/src/client/datascience/jupyter/jupyterSession.ts
@@ -39,13 +39,14 @@ export class JupyterSession implements IJupyterSession {
     private kernelSpec: IJupyterKernelSpec | undefined;
     private sessionManager: SessionManager | undefined;
     private session: Session.ISession | undefined;
-    private restartSessionPromise: Promise<Session.ISession> | undefined;
+    private restartSessionPromise: Promise<Session.ISession | undefined> | undefined;
     private contentsManager: ContentsManager | undefined;
     private notebookFiles: Contents.IModel[] = [];
     private onRestartedEvent: EventEmitter<void> | undefined;
     private statusHandler: Slot<Session.ISession, Kernel.Status> | undefined;
     private connected: boolean = false;
     private jupyterPasswordConnect: IJupyterPasswordConnect;
+    private oldSessions: Session.ISession[] = [];
 
     constructor(
         connInfo: IConnection,
@@ -87,44 +88,38 @@ export class JupyterSession implements IJupyterSession {
         return this.onRestartedEvent.event;
     }
 
-    public async waitForIdle(timeout: number): Promise<void> {
-        if (this.session && this.session.kernel) {
-            // This function seems to cause CI builds to timeout randomly on
-            // different tests. Waiting for status to go idle doesn't seem to work and
-            // in the past, waiting on the ready promise doesn't work either. Check status with a maximum of 5 seconds
-            const startTime = Date.now();
-            while (this.session &&
-                this.session.kernel &&
-                this.session.kernel.status !== 'idle' &&
-                (Date.now() - startTime < timeout)) {
-                traceInfo(`Waiting for idle: ${this.session.kernel.status}`);
-                await sleep(100);
-            }
-
-            // If we didn't make it out in ten seconds, indicate an error
-            if (!this.session || !this.session.kernel || this.session.kernel.status !== 'idle') {
-                throw new JupyterWaitForIdleError(localize.DataScience.jupyterLaunchTimedOut());
-            }
-        }
+    public waitForIdle(timeout: number): Promise<void> {
+        return this.waitForIdleOnSession(this.session, timeout);
     }
 
     public async restart(_timeout: number): Promise<void> {
         // Just kill the current session and switch to the other
         if (this.restartSessionPromise && this.session && this.sessionManager && this.contentsManager) {
+            traceInfo(`Restarting ${this.session.kernel.id}`);
+
             // Save old state for shutdown
             const oldSession = this.session;
             const oldStatusHandler = this.statusHandler;
 
-            // Just switch to the other session.
+            // Just switch to the other session. It should already be ready
             this.session = await this.restartSessionPromise;
+            if (!this.session) {
+                throw new Error(localize.DataScience.sessionDisposed());
+            }
+            traceInfo(`Got new session ${this.session.kernel.id}`);
 
             // Rewire our status changed event.
             this.statusHandler = this.onStatusChanged.bind(this.onStatusChanged);
             this.session.statusChanged.connect(this.statusHandler);
 
             // After switching, start another in case we restart again.
-            this.restartSessionPromise = this.createSession(oldSession.serverSettings, this.contentsManager);
-            this.shutdownSession(oldSession, oldStatusHandler).ignoreErrors();
+            this.restartSessionPromise = this.createRestartSession(oldSession.serverSettings, this.contentsManager);
+            traceInfo('Started new restart session');
+            if (oldStatusHandler) {
+                oldSession.statusChanged.disconnect(oldStatusHandler);
+            }
+            // Don't shutdown old sessions yet. This seems to hang tests.
+            this.oldSessions.push(oldSession);
         } else {
             throw new Error(localize.DataScience.sessionDisposed());
         }
@@ -157,7 +152,7 @@ export class JupyterSession implements IJupyterSession {
         this.session = await this.createSession(serverSettings, this.contentsManager, cancelToken);
 
         // Start another session to handle restarts
-        this.restartSessionPromise = this.createSession(serverSettings, this.contentsManager, cancelToken);
+        this.restartSessionPromise = this.createRestartSession(serverSettings, this.contentsManager, cancelToken);
 
         // Listen for session status changes
         this.statusHandler = this.onStatusChanged.bind(this.onStatusChanged);
@@ -171,6 +166,54 @@ export class JupyterSession implements IJupyterSession {
         return this.connected;
     }
 
+    private async waitForIdleOnSession(session: Session.ISession | undefined, timeout: number): Promise<void> {
+        if (session && session.kernel) {
+            traceInfo(`Waiting for idle on: ${session.kernel.id}${session.kernel.status}`);
+
+            // This function seems to cause CI builds to timeout randomly on
+            // different tests. Waiting for status to go idle doesn't seem to work and
+            // in the past, waiting on the ready promise doesn't work either. Check status with a maximum of 5 seconds
+            const startTime = Date.now();
+            while (session &&
+                session.kernel &&
+                session.kernel.status !== 'idle' &&
+                (Date.now() - startTime < timeout)) {
+                await sleep(100);
+            }
+
+            traceInfo(`Finished waiting for idle on: ${session.kernel.id}${session.kernel.status}`);
+
+            // If we didn't make it out in ten seconds, indicate an error
+            if (!session || !session.kernel || session.kernel.status !== 'idle') {
+                throw new JupyterWaitForIdleError(localize.DataScience.jupyterLaunchTimedOut());
+            }
+        }
+    }
+
+    private async createRestartSession(serverSettings: ServerConnection.ISettings, contentsManager: ContentsManager, cancelToken?: CancellationToken): Promise<Session.ISession> {
+        let result: Session.ISession | undefined;
+        let tryCount = 0;
+        // tslint:disable-next-line: no-any
+        let exception: any;
+        while (tryCount < 3) {
+            try {
+                result = await this.createSession(serverSettings, contentsManager, cancelToken);
+                await this.waitForIdleOnSession(result, 30000);
+                return result;
+            } catch (exc) {
+                traceInfo(`Error waiting for restart session: ${exc}`);
+                tryCount += 1;
+                if (result) {
+                    // Cleanup later.
+                    this.oldSessions.push(result);
+                }
+                result = undefined;
+                exception = exc;
+            }
+        }
+        throw exception;
+    }
+
     private async createSession(serverSettings: ServerConnection.ISettings, contentsManager: ContentsManager, cancelToken?: CancellationToken): Promise<Session.ISession> {
 
         // Create a temporary notebook for this session.
@@ -277,7 +320,9 @@ export class JupyterSession implements IJupyterSession {
     }
 
     private async shutdownSession(session: Session.ISession | undefined, statusHandler: Slot<Session.ISession, Kernel.Status> | undefined): Promise<void> {
-        if (session) {
+        if (session && session.kernel) {
+            const kernelId = session.kernel.id;
+            traceInfo(`shutdownSession ${kernelId} - start`);
             try {
                 if (statusHandler) {
                     session.statusChanged.disconnect(statusHandler);
@@ -288,23 +333,22 @@ export class JupyterSession implements IJupyterSession {
                     // https://github.com/jupyterlab/jupyterlab/issues/4252
                     // tslint:disable:no-any
                     if (isTestExecution()) {
-                        if (session && session.kernel) {
-                            const defaultKernel = session.kernel as any;
-                            if (defaultKernel && defaultKernel._futures) {
-                                const futures = defaultKernel._futures as Map<any, any>;
-                                if (futures) {
-                                    futures.forEach(f => {
-                                        if (f._status !== undefined) {
-                                            f._status |= 4;
-                                        }
-                                    });
-                                }
+                        const defaultKernel = session.kernel as any;
+                        if (defaultKernel && defaultKernel._futures) {
+                            const futures = defaultKernel._futures as Map<any, any>;
+                            if (futures) {
+                                futures.forEach(f => {
+                                    if (f._status !== undefined) {
+                                        f._status |= 4;
+                                    }
+                                });
                             }
                         }
+                        await waitForPromise(session.shutdown(), 1000);
+                    } else {
+                        // Shutdown may fail if the process has been killed
+                        await waitForPromise(session.shutdown(), 1000);
                     }
-
-                    // Shutdown may fail if the process has been killed
-                    await waitForPromise(session.shutdown(), 1000);
                 } catch {
                     noop();
                 }
@@ -315,22 +359,30 @@ export class JupyterSession implements IJupyterSession {
                 // Ignore, just trace.
                 traceWarning(e);
             }
+            traceInfo(`shutdownSession ${kernelId} - shutdown complete`);
         }
     }
 
     //tslint:disable:cyclomatic-complexity
     private async shutdownSessionAndConnection(): Promise<void> {
         if (this.contentsManager) {
+            traceInfo('ShutdownSessionAndConnection - dispose contents manager');
             this.contentsManager.dispose();
             this.contentsManager = undefined;
         }
         if (this.session || this.sessionManager) {
             try {
+                traceInfo('ShutdownSessionAndConnection - old sessions');
+                await Promise.all(this.oldSessions.map(s => this.shutdownSession(s, undefined)));
+                traceInfo('ShutdownSessionAndConnection - current session');
                 await this.shutdownSession(this.session, this.statusHandler);
+                traceInfo('ShutdownSessionAndConnection - get restart session');
                 const restartSession = await this.restartSessionPromise;
+                traceInfo('ShutdownSessionAndConnection - shutdown restart session');
                 await this.shutdownSession(restartSession, undefined);
 
                 if (this.sessionManager && !this.sessionManager.isDisposed) {
+                    traceInfo('ShutdownSessionAndConnection - dispose session manager');
                     this.sessionManager.dispose();
                 }
             } catch {
@@ -344,9 +396,11 @@ export class JupyterSession implements IJupyterSession {
             this.onRestartedEvent.dispose();
         }
         if (this.connInfo) {
+            traceInfo('ShutdownSessionAndConnection - dispose conn info');
             this.connInfo.dispose(); // This should kill the process that's running
             this.connInfo = undefined;
         }
+        traceInfo('ShutdownSessionAndConnection -- complete');
     }
 
 }
diff --git a/src/test/common/asyncDump.ts b/src/test/common/asyncDump.ts
@@ -5,5 +5,5 @@ const log = require('why-is-node-running');
 
 // Call this function to debug async hangs. It should print out stack traces of still running promises.
 export function asyncDump() {
-  log();
+    log();
 }
diff --git a/src/test/datascience/liveshare.functional.test.tsx b/src/test/datascience/liveshare.functional.test.tsx
diff --git a/src/test/datascience/mockDebugService.ts b/src/test/datascience/mockDebugService.ts
diff --git a/src/test/datascience/notebook.functional.test.ts b/src/test/datascience/notebook.functional.test.ts

Original file line number	Diff line number	Diff line change
`@@ -5,5 +5,5 @@ const log = require('why-is-node-running');`
`5`	`5`
`6`	`6`	`// Call this function to debug async hangs. It should print out stack traces of still running promises.`
`7`	`7`	`export function asyncDump() {`
`8`		`- log();`
	`8`	`+ log();`
`9`	`9`	`}`