Skip to content

Commit 74f69af

Browse files
DonJayamanneDonJayamanne
committed
more logging for jupyter
1 parent 79d97fe commit 74f69af

8 files changed

Lines changed: 47 additions & 14 deletions

‎pythonFiles/PythonTools/ipythonServer.py‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -171,6 +171,7 @@ def start_processing(self, channel, *args):
171171
json_to_send = json.dumps(exe_result, default=str)
172172
with self.send_lock:
173173
_debug_write('shell_result')
174+
_debug_write(json_to_send)
174175
write_bytes(self.conn, iPythonSocketServer._SHEL)
175176
write_string(self.conn, json_to_send)
176177
except Empty:
@@ -182,6 +183,7 @@ def start_processing(self, channel, *args):
182183
json_to_send = json.dumps(msg, default=str)
183184
with self.send_lock:
184185
_debug_write('iopub_msg')
186+
_debug_write(json_to_send)
185187
write_bytes(self.conn, iPythonSocketServer._IOPB)
186188
write_string(self.conn, json_to_send)
187189
except Empty:
@@ -196,7 +198,6 @@ def start_processing(self, channel, *args):
196198
_debug_write(traceback.format_exc())
197199
pass
198200
except:
199-
print('crap')
200201
_debug_write('error in repl loop')
201202
_debug_write(traceback.format_exc())
202203

@@ -306,7 +307,6 @@ def start_processing(self):
306307
_debug_write(traceback.format_exc())
307308
pass
308309
except:
309-
print('crap')
310310
_debug_write('error in repl loop')
311311
_debug_write(traceback.format_exc())
312312

@@ -518,6 +518,7 @@ def _cmd_run(self, id):
518518
except socket.timeout:
519519
pass
520520
msg_id = self.shell_channel.execute(code)
521+
_debug_write('msg_id = ' + msg_id)
521522
with self.send_lock:
522523
write_bytes(self.conn, iPythonSocketServer._RUN)
523524
write_string(self.conn, id)

‎src/client/jupyter/jupyter_client/jupyterSocketClient.ts‎

Lines changed: 35 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,10 +10,13 @@ import { JupyterMessage, ParsedIOMessage } from '../contracts';
1010
import { Helpers } from '../common/helpers';
1111
import * as Rx from 'rx';
1212
import { KernelRestartedError, KernelShutdownError } from '../common/errors';
13+
import { OutputChannel } from 'vscode';
1314

1415
export class JupyterSocketClient extends SocketCallbackHandler {
15-
constructor(socketServer: SocketServer) {
16+
private isDebugging: boolean;
17+
constructor(socketServer: SocketServer, private outputChannel: OutputChannel) {
1618
super(socketServer);
19+
this.isDebugging = process.env['DEBUG_DJAYAMANNE_IPYTHON'] === '1';
1720
this.registerCommandHandler(ResponseCommands.Pong, this.onPong.bind(this));
1821
this.registerCommandHandler(ResponseCommands.ListKernelsSpecs, this.onKernelsListed.bind(this));
1922
this.registerCommandHandler(ResponseCommands.Error, this.onError.bind(this));
@@ -30,7 +33,12 @@ export class JupyterSocketClient extends SocketCallbackHandler {
3033
private idDispenser: IdDispenser;
3134
private pid: number;
3235
private guid: string;
33-
36+
private writeToDebugLog(message: string) {
37+
if (!this.isDebugging){
38+
return;
39+
}
40+
this.outputChannel.appendLine(message);
41+
}
3442
public dispose() {
3543
super.dispose();
3644
}
@@ -205,7 +213,7 @@ export class JupyterSocketClient extends SocketCallbackHandler {
205213
const [def, id] = this.createId<string>();
206214
const observable = new Rx.Subject<ParsedIOMessage>();
207215
this.msgSubjectIndexedWithRunId.set(id, observable);
208-
216+
this.writeToDebugLog(`Send Code with Id = ${id}`);
209217
this.SendRawCommand(Commands.RunCodeBytes);
210218
this.stream.WriteString(id);
211219
this.stream.WriteString(code);
@@ -224,6 +232,7 @@ export class JupyterSocketClient extends SocketCallbackHandler {
224232
if (typeof msg_id !== 'string') {
225233
return;
226234
}
235+
this.writeToDebugLog(`Code with Id = ${id} has msg_id = ${msg_id}`);
227236
const def = this.pendingCommands.get(id);
228237
this.releaseId(id);
229238
def.resolve(msg_id);
@@ -245,6 +254,7 @@ export class JupyterSocketClient extends SocketCallbackHandler {
245254
}
246255
const msg_type = message.header.msg_type;
247256
if (msg_type === 'status') {
257+
this.writeToDebugLog(`Kernel Status = ${message.content.execution_state}`);
248258
this.emit('status', message.content.execution_state);
249259
}
250260
const msg_id = message.parent_header.msg_id;
@@ -278,21 +288,30 @@ export class JupyterSocketClient extends SocketCallbackHandler {
278288
}
279289
}
280290
}
291+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} with status = ${status}`);
281292
if (!parsedMesage) {
293+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} with status = ${status} ignored`);
282294
return;
283295
}
296+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} has message of: '\n${jsonResult}`);
284297
if (this.finalMessage.has(msg_id) && this.msgSubject.has(msg_id)) {
285298
const subject = this.msgSubject.get(msg_id);
286299
const info = this.finalMessage.get(msg_id);
300+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} found in finalMessage and msgSubject`);
287301
// If th io message with status='idle' has been received, that means message execution is deemed complete
288302
if (info.ioStatusSent) {
303+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} found in finalMessage and msgSubject, and ioStatusSent = true`);
289304
this.finalMessage.delete(msg_id);
290305
this.msgSubject.delete(msg_id);
291306
subject.onNext(parsedMesage);
292307
subject.onCompleted();
293308
}
309+
else {
310+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} found in finalMessage and msgSubject, and ioStatusSent = false`);
311+
}
294312
}
295313
else {
314+
this.writeToDebugLog(`Shell Result with msg_id = ${msg_id} not found in finalMessage or not found in msgSubject`);
296315
// Wait for the io message with status='idle' to arrive
297316
const info = this.finalMessage.has(msg_id) ? this.finalMessage.get(msg_id) : { ioStatusSent: false };
298317
info.shellMessage = parsedMesage;
@@ -316,41 +335,52 @@ export class JupyterSocketClient extends SocketCallbackHandler {
316335
}
317336
const msg_type = message.header.msg_type;
318337
if (msg_type === 'status') {
338+
this.writeToDebugLog(`io Kernel Status = ${message.content.execution_state}`);
319339
this.emit('status', message.content.execution_state);
320340
}
321341
const msg_id = message.parent_header.msg_id;
322342
if (!msg_id) {
323343
return;
324344
}
345+
this.writeToDebugLog(`iopub with msg_id = ${msg_id}`);
325346

326347
// Ok, if we have received a status of 'idle' this means the execution has completed
327348
if (msg_type === 'status' && message.content.execution_state === 'idle') {
349+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle`);
328350
let timesWaited = 0;
329351
const waitForFinalIOMessage = () => {
330352
timesWaited += 1;
331353
// The Shell message handler has processed the message
332354
if (!this.msgSubject.has(msg_id)) {
355+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, not yet in msgSubject`);
333356
return;
334357
}
335358
// Last message sent on shell channel (status='ok' or status='error')
336359
// and now we have a status message, this means the exection is deemed complete
337360
if (this.finalMessage.has(msg_id)) {
361+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, found in finalMessage`);
338362
const subject = this.msgSubject.get(msg_id);
339363
const info = this.finalMessage.get(msg_id);
340364
if (!info.shellMessage && timesWaited < 10) {
365+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, found in finalMessage and info.shellMessage = ` + typeof (info.shellMessage));
366+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, found in finalMessage and timesWaited = ` + timesWaited.toString());
341367
setTimeout(() => {
342368
waitForFinalIOMessage();
343369
}, 10);
344370
return;
345371
}
346372
this.finalMessage.delete(msg_id);
347373
this.msgSubject.delete(msg_id);
374+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle almost done`);
348375
if (info.shellMessage) {
376+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, and shell message being sent out`);
349377
subject.onNext(info.shellMessage);
350378
}
379+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, done`);
351380
subject.onCompleted();
352381
}
353382
else {
383+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} and msg_type == status and execution_state == idle, inserted into finalMessage`);
354384
this.finalMessage.set(msg_id, { ioStatusSent: true });
355385
}
356386
};
@@ -366,9 +396,11 @@ export class JupyterSocketClient extends SocketCallbackHandler {
366396
return;
367397
}
368398
if (this.msgSubject.has(msg_id)) {
399+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} found in msgSubject`);
369400
this.msgSubject.get(msg_id).onNext(parsedMesage);
370401
}
371402
else {
403+
this.writeToDebugLog(`iopub with msg_id = ${msg_id} not found in msgSubject and inserted into unhandledMessages`);
372404
let data = [];
373405
if (this.unhandledMessages.has(msg_id)) {
374406
data = this.unhandledMessages.get(msg_id);

‎src/client/jupyter/jupyter_client/main.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ export class JupyterClientAdapter extends EventEmitter implements IJupyterClient
123123
}
124124
private startSocketServer(): Promise<number> {
125125
this.socketServer = new SocketServer();
126-
this.ipythonAdapter = new JupyterSocketClient(this.socketServer);
126+
this.ipythonAdapter = new JupyterSocketClient(this.socketServer, this.outputChannel);
127127
this.ipythonAdapter.on('status', status => {
128128
this.emit('status', status);
129129
});

‎src/test/extension.jupyter.comms.jupyterClient.test.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -68,10 +68,10 @@ suite('JupyterClient', () => {
6868
done();
6969
});
7070
setup(() => {
71-
output = new MockOutputChannel('Jupyter');
72-
jupyter = new JupyterClientAdapter(output, __dirname);
7371
process.env['PYTHON_DONJAYAMANNE_TEST'] = '0';
7472
process.env['DEBUG_DJAYAMANNE_IPYTHON'] = '1';
73+
output = new MockOutputChannel('Jupyter');
74+
jupyter = new JupyterClientAdapter(output, __dirname);
7575
});
7676
teardown(() => {
7777
process.env['PYTHON_DONJAYAMANNE_TEST'] = '1';

‎src/test/extension.jupyter.comms.jupyterKernel.test.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -73,13 +73,13 @@ suite('Jupyter Kernel', () => {
7373
done();
7474
});
7575
setup(() => {
76+
process.env['PYTHON_DONJAYAMANNE_TEST'] = '0';
77+
process.env['DEBUG_DJAYAMANNE_IPYTHON'] = '1';
7678
disposables = [];
7779
output = new MockOutputChannel('Jupyter');
7880
disposables.push(output);
7981
jupyter = new JupyterClientAdapter(output, __dirname);
8082
disposables.push(jupyter);
81-
process.env['PYTHON_DONJAYAMANNE_TEST'] = '0';
82-
process.env['DEBUG_DJAYAMANNE_IPYTHON'] = '1';
8383
});
8484
teardown(() => {
8585
process.env['PYTHON_DONJAYAMANNE_TEST'] = '1';

‎src/test/extension.jupyter.comms.jupyterKernelManager.test.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -69,13 +69,13 @@ suite('Kernel Manager', () => {
6969
done();
7070
});
7171
setup(() => {
72+
process.env['PYTHON_DONJAYAMANNE_TEST'] = '0';
73+
process.env['DEBUG_DJAYAMANNE_IPYTHON'] = '1';
7274
disposables = [];
7375
output = new MockOutputChannel('Jupyter');
7476
disposables.push(output);
7577
jupyter = new JupyterClientAdapter(output, __dirname);
7678
disposables.push(jupyter);
77-
process.env['PYTHON_DONJAYAMANNE_TEST'] = '0';
78-
process.env['DEBUG_DJAYAMANNE_IPYTHON'] = '1';
7979
// Hack hack hack hack hack :)
8080
cmds.registerCommand = function () { };
8181
});

‎src/test/extension.sort.test.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,7 @@ const fileToFormatWithConfig1 = path.join(__dirname, '..', '..', 'src', 'test',
2626
const originalFileToFormatWithConfig1 = path.join(__dirname, '..', '..', 'src', 'test', 'pythonFiles', 'sorting', 'withconfig', 'original.1.py');
2727
const extensionDir = path.join(__dirname, '..', '..');
2828

29-
suite('Formatting', () => {
29+
suite('Sorting', () => {
3030
suiteSetup(done => {
3131
initialize().then(() => {
3232
pythonSettings.pythonPath = PYTHON_PATH;

‎src/test/index.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,7 @@ let testRunner = require('vscode/lib/testrunner');
1717
testRunner.configure({
1818
ui: 'tdd', // the TDD UI is being used in extension.test.ts (suite, test, etc.)
1919
useColors: true, // colored output from test results
20-
timeout: 10000
20+
timeout: 15000
2121
});
2222

2323
module.exports = testRunner;

0 commit comments

Comments
 (0)