Skip to content

Commit 366f70d

Browse files
DonJayamannerchiodo
DonJayamanne
authored and
rchiodo
committed
Send logs from daemon into python extension (microsoft#8588)
* Add logging * Fix test * Better logging * Daemons weren't disposed when closing VS Code * Dispose daemons properly * Fix tests * Restore counts * Use linux VM
1 parent 207657c commit 366f70d

12 files changed

Lines changed: 113 additions & 60 deletions

File tree

‎build/ci/templates/jobs/build_compile.yml‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,19 +4,19 @@
44
jobs:
55
- job: Compile
66
pool:
7-
vmImage: "macos-latest"
7+
vmImage: "ubuntu-16.04"
88
steps:
99
- template: ../steps/compile.yml
1010

1111
- job: Build
1212
pool:
13-
vmImage: "macos-latest"
13+
vmImage: "ubuntu-16.04"
1414
steps:
1515
- template: ../steps/build.yml
1616

1717
- job: Hygiene
1818
pool:
19-
vmImage: "macos-latest"
19+
vmImage: "ubuntu-16.04"
2020
steps:
2121
- template: ../steps/initialization.yml
2222
parameters:

‎build/ci/templates/jobs/build_uitests.yml‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
jobs:
44
- job: Compile
55
pool:
6-
vmImage: "macos-latest"
6+
vmImage: "ubuntu-16.04"
77
steps:
88
- template: ../steps/initialization.yml
99
parameters:
@@ -14,7 +14,7 @@ jobs:
1414

1515
- job: Hygiene
1616
pool:
17-
vmImage: "macos-latest"
17+
vmImage: "ubuntu-16.04"
1818
steps:
1919
- template: ../steps/initialization.yml
2020
parameters:

‎build/ci/templates/jobs/coverage.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
jobs:
22
- job: Coverage
33
pool:
4-
vmImage: "macos-latest"
4+
vmImage: "ubuntu-16.04"
55
variables:
66
TestsToRun: 'testUnitTests'
77
steps:

‎build/ci/templates/jobs/merge_upload_uitest_report.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ jobs:
55
- job: UI_Test_Report
66
timeoutInMinutes: 120
77
pool:
8-
vmImage: "macos-latest"
8+
vmImage: "ubuntu-16.04"
99
steps:
1010
- template: ../steps/initialization.yml
1111
parameters:

‎pythonFiles/datascience/daemon/__main__.py‎

Lines changed: 31 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212
log = logging.getLogger(__name__)
1313

1414
LOG_FORMAT = "%(asctime)s UTC - %(levelname)s - %(name)s - %(message)s"
15-
15+
queue_handler = None
1616

1717
def add_arguments(parser):
1818
parser.description = "Daemon"
@@ -42,9 +42,33 @@ def add_arguments(parser):
4242
)
4343

4444

45+
class TemporaryQueueHandler(logging.Handler):
46+
""" Logger used to temporarily store everything into a queue.
47+
Later the messages are pushed back to the RPC client as a notification.
48+
Once the RPC channel is up, we'll stop queuing messages and sending id directly.
49+
"""
50+
def __init__(self):
51+
logging.Handler.__init__(self)
52+
self.queue = []
53+
self.server = None
54+
def set_server(self, server):
55+
# Send everything that has beeen queued until now.
56+
self.server = server
57+
for msg in self.queue:
58+
self.server._endpoint.notify("log", msg)
59+
self.queue = []
60+
def emit(self, record):
61+
data = {"level": record.levelname, "msg": self.format(record)}
62+
# If we don't have the server, then queue it and send it later.
63+
if self.server is None:
64+
self.queue.append(data)
65+
else:
66+
self.server._endpoint.notify("log", data)
67+
68+
4569
def _configure_logger(verbose=0, log_config=None, log_file=None):
4670
root_logger = logging.root
47-
71+
global queue_handler
4872
if log_config:
4973
with open(log_config, "r") as f:
5074
logging.config.dictConfig(json.load(f))
@@ -59,10 +83,11 @@ def _configure_logger(verbose=0, log_config=None, log_file=None):
5983
encoding=None,
6084
delay=0,
6185
)
86+
log_handler.setFormatter(formatter)
87+
root_logger.addHandler(log_handler)
6288
else:
63-
log_handler = logging.StreamHandler()
64-
log_handler.setFormatter(formatter)
65-
root_logger.addHandler(log_handler)
89+
queue_handler = TemporaryQueueHandler()
90+
root_logger.addHandler(queue_handler)
6691

6792
if verbose == 0:
6893
level = logging.WARNING
@@ -89,7 +114,7 @@ def main():
89114
try:
90115
daemon_module = importlib.import_module(args.daemon_module)
91116
daemon_cls = daemon_module.PythonDaemon
92-
daemon_cls.start_daemon()
117+
daemon_cls.start_daemon(queue_handler)
93118
except Exception:
94119
import traceback
95120

‎pythonFiles/datascience/daemon/daemon_python.py‎

Lines changed: 17 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@ class PythonDaemon(MethodDispatcher):
6767
"""
6868

6969
def __init__(self, rx, tx):
70+
self.log = logging.getLogger("{0}.{1}".format(self.__class__.__module__,self.__class__.__name__))
7071
self._jsonrpc_stream_reader = JsonRpcStreamReader(rx)
7172
self._jsonrpc_stream_writer = JsonRpcStreamWriter(tx)
7273
self._endpoint = Endpoint(
@@ -78,10 +79,10 @@ def __getitem__(self, item):
7879
"""Override getitem to fallback through multiple dispatchers."""
7980
if self._shutdown and item != "exit":
8081
# exit is the only allowed method during shutdown
81-
log.debug("Ignoring non-exit method during shutdown: %s", item)
82+
self.log.debug("Ignoring non-exit method during shutdown: %s", item)
8283
raise KeyError
8384

84-
log.info("Execute rpc method %s", item)
85+
self.log.info("Execute rpc method %s", item)
8586
return super().__getitem__(item)
8687

8788
def start(self):
@@ -91,7 +92,7 @@ def start(self):
9192

9293
def m_ping(self, data):
9394
"""ping & pong (check if daemon is alive)."""
94-
log.info("pinged with %s", data)
95+
self.log.info("pinged with %s", data)
9596
return {"pong": data}
9697

9798
def _execute_and_capture_output(self, func):
@@ -110,7 +111,7 @@ def _execute_and_capture_output(self, func):
110111
return output
111112

112113
def close(self):
113-
log.info("Closing rpc channel")
114+
self.log.info("Closing rpc channel")
114115
self._shutdown = True
115116
self._endpoint.shutdown()
116117
self._jsonrpc_stream_reader.close()
@@ -122,18 +123,18 @@ def m_exit(self, **_kwargs):
122123
@error_decorator
123124
def m_exec_file(self, file_name, args=[], cwd=None, env=None):
124125
args = [] if args is None else args
125-
log.info("Exec file %s with args %s", file_name, args)
126+
self.log.info("Exec file %s with args %s", file_name, args)
126127

127128
def exec_file():
128-
log.info("execute file %s", file_name)
129+
self.log.info("execute file %s", file_name)
129130
runpy.run_path(file_name, globals())
130131

131132
with change_exec_context(args, cwd, env):
132133
return self._execute_and_capture_output(exec_file)
133134

134135
@error_decorator
135136
def m_exec_code(self, code):
136-
log.info("Exec code %s", code)
137+
self.log.info("Exec code %s", code)
137138

138139
def exec_code():
139140
eval(code, globals())
@@ -144,21 +145,21 @@ def exec_code():
144145
def m_exec_file_observable(self, file_name, args=[], cwd=None, env=None):
145146
args = [] if args is None else args
146147
old_argv, sys.argv = sys.argv, [""] + args
147-
log.info("Exec file (observale) %s with args %s", file_name, args)
148+
self.log.info("Exec file (observale) %s with args %s", file_name, args)
148149

149150
with change_exec_context(args, cwd, env):
150151
runpy.run_path(file_name, globals())
151152

152153
@error_decorator
153154
def m_exec_module(self, module_name, args=[], cwd=None, env=None):
154155
args = [] if args is None else args
155-
log.info("Exec module %s with args %s", module_name, args)
156+
self.log.info("Exec module %s with args %s", module_name, args)
156157
if args[-1] == "--version":
157158
return self._get_module_version(module_name, args)
158159

159160
def exec_module():
160161

161-
log.info("execute module %s", module_name)
162+
self.log.info("execute module %s", module_name)
162163
runpy.run_module(module_name, globals(), run_name="__main__")
163164

164165
with change_exec_context(args, cwd, env):
@@ -167,7 +168,7 @@ def exec_module():
167168
@error_decorator
168169
def m_exec_module_observable(self, module_name, args=None, cwd=None, env=None):
169170
args = [] if args is None else args
170-
log.info("Exec module (observable) %s with args %s", module_name, args)
171+
self.log.info("Exec module (observable) %s with args %s", module_name, args)
171172

172173
with change_exec_context(args, cwd, env):
173174
runpy.run_module(module_name, globals(), run_name="__main__")
@@ -184,7 +185,7 @@ def _get_module_version(self, module_name, args):
184185
module_name = args[0]
185186

186187
try:
187-
log.info("getting module_version %s", module_name)
188+
self.log.info("getting module_version %s", module_name)
188189
m = importlib.import_module(module_name)
189190
return {"stdout": m.__version__}
190191
except Exception:
@@ -209,7 +210,7 @@ def m_is_module_installed(self, module_name=None):
209210
return {"exists": False}
210211

211212
@classmethod
212-
def start_daemon(cls):
213+
def start_daemon(cls, logging_queue_handler=None):
213214
""" Starts the daemon. """
214215
if not issubclass(cls, PythonDaemon):
215216
raise ValueError("Handler class must be an instance of PythonDaemon")
@@ -224,4 +225,7 @@ def on_write_stderr(output):
224225
stdin, stdout = get_io_buffers()
225226
server = cls(stdin, stdout)
226227
redirect_output(on_write_stdout, on_write_stderr)
228+
# Set up the queue handler that'll send log messages over to the client.
229+
if logging_queue_handler is not None:
230+
logging_queue_handler.set_server(server)
227231
server.start()

‎pythonFiles/datascience/jupyter_daemon.py‎

Lines changed: 8 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -10,22 +10,19 @@
1010
change_exec_context,
1111
)
1212

13-
log = logging.getLogger(__name__)
14-
15-
1613
class PythonDaemon(BasePythonDaemon):
1714
def __init__(self, rx, tx):
18-
log.info("DataScience Daemon init")
1915
super().__init__(rx, tx)
16+
self.log.info("DataScience Daemon init")
2017

2118
def __getitem__(self, item):
2219
"""Override getitem to ensure we use these methods."""
23-
log.info("Execute rpc method %s in Jupyter class", item)
20+
self.log.info("Execute rpc method %s in DS Daemon", item)
2421
return super().__getitem__(item)
2522

2623
@error_decorator
2724
def m_exec_module(self, module_name, args=[], cwd=None, env=None):
28-
log.info("Exec in DS Daemon %s with args %s", module_name, args)
25+
self.log.info("Exec in DS Daemon %s with args %s", module_name, args)
2926
args = [] if args is None else args
3027

3128
if module_name == "jupyter" and args == ["kernelspec", "list"]:
@@ -35,12 +32,12 @@ def m_exec_module(self, module_name, args=[], cwd=None, env=None):
3532
elif module_name == "jupyter" and args[0] == "nbconvert" and args[-1] != "--version":
3633
return self._execute_and_capture_output(lambda : self._convert(args))
3734
else:
38-
log.info("check base class stuff")
35+
self.log.info("check base class stuff")
3936
return super().m_exec_module(module_name, args, cwd, env)
4037

4138
@error_decorator
4239
def m_exec_module_observable(self, module_name, args=None, cwd=None, env=None):
43-
log.info("Exec in DS Daemon (observable) %s with args %s", module_name, args)
40+
self.log.info("Exec in DS Daemon (observable) %s with args %s", module_name, args)
4441
args = [] if args is None else args
4542

4643
# Assumption is that `python -m jupyter notebook` or `python -m notebook` with observable output
@@ -52,7 +49,7 @@ def m_exec_module_observable(self, module_name, args=None, cwd=None, env=None):
5249
):
5350
# Args must not have ['notebook'] in the begining. Drop the `notebook` subcommand when using `jupyter`
5451
args = args[1:] if args[0] == "notebook" else args
55-
log.info("Starting notebook with args %s", args)
52+
self.log.info("Starting notebook with args %s", args)
5653

5754
# When launching notebook always ensure the first argument is `notebook`.
5855
with change_exec_context(args, cwd, env):
@@ -79,7 +76,7 @@ def _print_kernelspec_version(self):
7976
sys.stdout.flush()
8077

8178
def _print_kernel_list(self):
82-
log.info("check kernels")
79+
self.log.info("check kernels")
8380
# Get kernel specs.
8481
import jupyter_client.kernelspec
8582

@@ -90,7 +87,7 @@ def _print_kernel_list(self):
9087
sys.stdout.flush()
9188

9289
def _convert(self, args):
93-
log.info("nbconvert")
90+
self.log.info("nbconvert")
9491
from nbconvert import nbconvertapp as app
9592

9693
sys.argv = [""] + args

‎src/client/common/process/pythonDaemon.ts‎

Lines changed: 16 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ import * as os from 'os';
88
import { Subject } from 'rxjs/Subject';
99
import * as util from 'util';
1010
import { MessageConnection, NotificationType, RequestType, RequestType0 } from 'vscode-jsonrpc';
11-
import { traceError, traceWarning } from '../logger';
11+
import { traceError, traceInfo, traceVerbose, traceWarning } from '../logger';
1212
import { IDisposable } from '../types';
1313
import { createDeferred, Deferred } from '../utils/async';
1414
import { noop } from '../utils/misc';
@@ -57,8 +57,8 @@ export class PythonDaemonExecutionService implements IPythonDaemonExecutionServi
5757
}
5858
public dispose() {
5959
try {
60-
this.connection.dispose();
61-
this.proc.kill();
60+
// The daemon should die as a result of this.
61+
this.connection.sendNotification(new NotificationType('exit'));
6262
} catch {
6363
noop();
6464
}
@@ -274,6 +274,19 @@ export class PythonDaemonExecutionService implements IPythonDaemonExecutionServi
274274
// Wire up stdout/stderr.
275275
const OuputNotification = new NotificationType<Output<string>, void>('output');
276276
this.connection.onNotification(OuputNotification, output => this.outputObservale.next(output));
277+
const logNotification = new NotificationType<{level: 'WARN'|'WARNING'|'INFO'|'DEBUG'|'NOTSET'; msg: string}, void>('log');
278+
this.connection.onNotification(logNotification, output => {
279+
if (output.level === 'DEBUG' || output.level === 'NOTSET'){
280+
traceVerbose(output.msg);
281+
} else if (output.level === 'INFO'){
282+
traceInfo(output.msg);
283+
} else if (output.level === 'WARN' || output.level === 'WARNING') {
284+
traceWarning(output.msg);
285+
} else {
286+
traceError(output.msg);
287+
}
288+
});
289+
this.connection.onUnhandledNotification(traceError);
277290
}
278291
private throwIfRPCConnectionIsDead() {
279292
if (this.connectionClosedMessage) {

0 commit comments

Comments
 (0)