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

* 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

Author: rchiodo

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'))
 

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:

build/functional-test-requirements.txt

@@ -4,4 +4,4 @@ jupyter
 numpy
 matplotlib
 pandas
-livelossplot
+livelossplot

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;

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');
  }
 
 }

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();
 }