Support for log points (#352)

Second part of the fix for #350
Fixes #313
Fixes #350

debugger_protocol/messages/_requests.py

@@ -76,6 +76,7 @@ class Capabilities(FieldsNamespace):
         Field('supportsExceptionOptions', bool),
         Field('supportsValueFormattingOptions', bool),
         Field('supportsExceptionInfoRequest', bool),
+        Field('supportsLogPoints', bool),
         Field('supportTerminateDebuggee', bool),
         Field('supportsDelayedStackTraceLoading', bool),
         Field('supportsLoadedSourcesRequest', bool),

ptvsd/wrapper.py

@@ -20,6 +20,10 @@ try:
     urllib.unquote
 except Exception:
     import urllib.parse as urllib
+try:
+    from functools import reduce
+except Exception:
+    pass
 import warnings
 from xml.sax import SAXParseException
 
@@ -61,6 +65,7 @@ INITIALIZE_RESPONSE = dict(
     supportsValueFormattingOptions=True,
     supportsSetExpression=True,
     supportsModulesRequest=True,
+    supportsLogPoints=True,
     exceptionBreakpointFilters=[
         {
             'filter': 'raised',
@@ -1580,17 +1585,34 @@ class VSCodeMessageProcessor(ipcjson.SocketIO, ipcjson.IpcChannel):
                 self.bp_map.remove(pyd_bpid, vsc_bpid)
 
         cmd = pydevd_comm.CMD_SET_BREAK
-        msgfmt = '{}\t{}\t{}\t{}\tNone\t{}\tNone\t{}'
+        msgfmt = '{}\t{}\t{}\t{}\tNone\t{}\t{}\t{}\t{}'
         for src_bp in src_bps:
             line = src_bp['line']
             vsc_bpid = self.bp_map.add(
                     lambda vsc_bpid: (path, vsc_bpid))
             self.path_casing.track_file_path_case(path)
+
             hit_condition = self._get_hit_condition_expression(
                                 src_bp.get('hitCondition', None))
-            msg = msgfmt.format(vsc_bpid, bp_type, path, line,
-                                src_bp.get('condition', None),
-                                hit_condition)
+            logMessage = src_bp.get('logMessage', '')
+            if len(logMessage) == 0:
+                is_logpoint = None
+                condition = src_bp.get('condition', None)
+                expression = None
+            else:
+                is_logpoint = True
+                condition = None
+                expressions = re.findall('\{.*?\}', logMessage)
+                if len(expressions) == 0:
+                    expression = 'print({})'.format(repr(logMessage)) # noqa
+                else:
+                    raw_text = reduce(lambda a, b: a.replace(b, '{}'), expressions, logMessage) # noqa
+                    raw_text = raw_text.replace('"', '\\"')
+                    expression_list = ', '.join([s.strip('{').strip('}').strip() for s in expressions]) # noqa
+                    expression = 'print("{}".format({}))'.format(raw_text, expression_list) # noqa
+
+            msg = msgfmt.format(vsc_bpid, bp_type, path, line, condition,
+                                expression, hit_condition, is_logpoint)
             self.pydevd_notify(cmd, msg)
             bps.append({
                 'id': vsc_bpid,

tests/highlevel/test_live_pydevd.py

@@ -58,6 +58,10 @@ class TestBase(VSCTest):
     def workspace(self):
         return self._workspace
 
+    @property
+    def filename(self):
+        return None if self._filename is None else self._filePath
+
     def _new_fixture(self, new_daemon):
         self.assertIsNotNone(self._filename)
         return self.FIXTURE(self._filename, new_daemon)
@@ -67,6 +71,7 @@ class TestBase(VSCTest):
         if content is not None:
             filename = self.workspace.write(filename, content=content)
         self.workspace.install()
+        self._filePath = filename
         self._filename = 'file:' + filename
 
     def set_module(self, name, content=None):
@@ -196,3 +201,73 @@ class BreakpointTests(VSCFlowTest, unittest.TestCase):
 
         self.assert_received(self.vsc, [])
         self.assert_vsc_received(received, [])
+
+
+class LogpointTests(TestBase, unittest.TestCase):
+    FILENAME = 'spam.py'
+    SOURCE = """
+        a = 1
+        b = 2
+        c = 3
+        d = 4
+        """
+
+    @contextlib.contextmanager
+    def running(self):
+        addr = (None, 8888)
+        with self.fake.start(addr):
+                yield
+
+    def test_basic(self):
+        addr = (None, 8888)
+        with self.fake.start(addr):
+            with self.vsc.wait_for_event('output'):
+                pass
+
+            with self.vsc.wait_for_event('initialized'):
+                req_initialize = self.send_request('initialize', {
+                    'adapterID': 'spam',
+                })
+                req_attach = self.send_request('attach', {
+                    'debugOptions': ['RedirectOutput']
+                })
+                req_breakpoints = self.send_request('setBreakpoints', {
+                    'source': {'path': self.filename},
+                    'breakpoints': [
+                        {
+                            'line': '4',
+                            'logMessage': '{a}+{b}=3'
+                        },
+                    ],
+                })
+
+            req_config = self.send_request('configurationDone')
+
+            with self.wait_for_events(['exited', 'terminated']):
+                self.fix.binder.done()
+            self.fix.binder.wait_until_done()
+            received = self.vsc.received
+
+        self.assert_vsc_received(received, [
+            self.new_event(
+                'output',
+                category='telemetry',
+                output='ptvsd',
+                data={'version': ptvsd.__version__}),
+            self.new_response(req_initialize, **INITIALIZE_RESPONSE),
+            self.new_event('initialized'),
+            self.new_response(req_attach),
+            self.new_response(req_breakpoints, **dict(
+                breakpoints=[{'id': 1, 'verified': True, 'line': '4'}]
+            )),
+            self.new_response(req_config),
+            self.new_event('process', **dict(
+                name=sys.argv[0],
+                systemProcessId=os.getpid(),
+                isLocalProcess=True,
+                startMethod='attach',
+            )),
+            self.new_event('exited', exitCode=0),
+            self.new_event('terminated'),
+            self.new_event('output', **dict(category='stdout', output='1+2=3' + os.linesep)), # noqa
+        ])

tests/highlevel/test_messages.py

@@ -923,9 +923,9 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tpython-line\tspam.py\t15\tNone\ti == 3\tNone\tNone'),
+                '2\tpython-line\tspam.py\t15\tNone\ti == 3\tNone\tNone\tNone'),
         ])
 
     def test_with_hit_condition(self):
@@ -972,15 +972,63 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\t@HIT@ == 5'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\t@HIT@ == 5\tNone'), # noqa
             self.expected_pydevd_request(
-                '2\tpython-line\tspam.py\t15\tNone\tNone\tNone\t@HIT@ ==5'),
+                '2\tpython-line\tspam.py\t15\tNone\tNone\tNone\t@HIT@ ==5\tNone'), # noqa
             self.expected_pydevd_request(
-                '3\tpython-line\tspam.py\t20\tNone\tNone\tNone\t@HIT@ > 5'),
+                '3\tpython-line\tspam.py\t20\tNone\tNone\tNone\t@HIT@ > 5\tNone'), # noqa
             self.expected_pydevd_request(
-             '4\tpython-line\tspam.py\t25\tNone\tNone\tNone\t@HIT@ % 5 == 0'),
+             '4\tpython-line\tspam.py\t25\tNone\tNone\tNone\t@HIT@ % 5 == 0\tNone'), # noqa
             self.expected_pydevd_request(
-                '5\tpython-line\tspam.py\t30\tNone\tNone\tNone\tx'),
+                '5\tpython-line\tspam.py\t30\tNone\tNone\tNone\tx\tNone'),
+        ])
+
+    def test_with_logpoint(self):
+        with self.launched():
+            self.send_request(
+                source={'path': 'spam.py'},
+                breakpoints=[
+                    {'line': '10',
+                     'logMessage': '5'},
+                    {'line': '15',
+                     'logMessage': 'Hello World'},
+                    {'line': '20',
+                     'logMessage': '{a}'},
+                    {'line': '25',
+                     'logMessage': '{a}+{b}=Something'}
+                ],
+            )
+            received = self.vsc.received
+
+        self.assert_vsc_received(received, [
+            self.expected_response(
+                breakpoints=[
+                    {'id': 1,
+                     'verified': True,
+                     'line': '10'},
+                    {'id': 2,
+                     'verified': True,
+                     'line': '15'},
+                    {'id': 3,
+                     'verified': True,
+                     'line': '20'},
+                    {'id': 4,
+                     'verified': True,
+                     'line': '25'}
+                ],
+            ),
+            # no events
+        ])
+        self.PYDEVD_CMD = CMD_SET_BREAK
+        self.assert_received(self.debugger, [
+            self.expected_pydevd_request(
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tprint(' + repr("5") + ')\tNone\tTrue'), # noqa
+            self.expected_pydevd_request(
+                '2\tpython-line\tspam.py\t15\tNone\tNone\tprint(' + repr("Hello World") + ')\tNone\tTrue'), # noqa
+            self.expected_pydevd_request(
+                '3\tpython-line\tspam.py\t20\tNone\tNone\tprint("{}".format(a))\tNone\tTrue'), # noqa
+            self.expected_pydevd_request(
+             '4\tpython-line\tspam.py\t25\tNone\tNone\tprint("{}+{}=Something".format(a, b))\tNone\tTrue'), # noqa
         ])
 
     def test_with_existing(self):
@@ -988,9 +1036,9 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
             with self.hidden():
                 self.PYDEVD_CMD = CMD_SET_BREAK
                 self.expected_pydevd_request(
-                    '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone')
+                    '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone') # noqa
                 self.expected_pydevd_request(
-                    '2\tpython-line\tspam.py\t17\tNone\tNone\tNone\tNone')
+                    '2\tpython-line\tspam.py\t17\tNone\tNone\tNone\tNone\tNone') # noqa
                 self.fix.send_request('setBreakpoints', dict(
                     source={'path': 'spam.py'},
                     breakpoints=[
@@ -1038,11 +1086,11 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, removed + [
             self.expected_pydevd_request(
-                '3\tpython-line\tspam.py\t113\tNone\tNone\tNone\tNone'),
+                '3\tpython-line\tspam.py\t113\tNone\tNone\tNone\tNone\tNone'), # noqa
             self.expected_pydevd_request(
-                '4\tpython-line\tspam.py\t2\tNone\tNone\tNone\tNone'),
+                '4\tpython-line\tspam.py\t2\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '5\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '5\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
         ])
 
     def test_multiple_files(self):
@@ -1078,9 +1126,9 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tpython-line\teggs.py\t17\tNone\tNone\tNone\tNone'),
+                '2\tpython-line\teggs.py\t17\tNone\tNone\tNone\tNone\tNone'),
         ])
 
     def test_vs_django(self):
@@ -1115,9 +1163,46 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tdjango-line\teggs.html\t17\tNone\tNone\tNone\tNone'),
+                '2\tdjango-line\teggs.html\t17\tNone\tNone\tNone\tNone\tNone'), # noqa
+        ])
+
+    def test_vs_django_logpoint(self):
+        with self.launched(args={'options': 'DJANGO_DEBUG=True'}):
+            self.send_request(
+                source={'path': 'spam.py'},
+                breakpoints=[{'line': '10', 'logMessage': 'Hello World'}],
+            )
+            self.send_request(
+                source={'path': 'eggs.html'},
+                breakpoints=[{'line': '17', 'logMessage': 'Hello Django World'}], # noqa
+            )
+            received = self.vsc.received
+
+        self.assert_vsc_received(received, [
+            self.expected_response(
+                breakpoints=[
+                    {'id': 1,
+                     'verified': True,
+                     'line': '10'},
+                ],
+            ),
+            self.expected_response(
+                breakpoints=[
+                    {'id': 2,
+                     'verified': True,
+                     'line': '17'},
+                ],
+            ),
+        ])
+
+        self.PYDEVD_CMD = CMD_SET_BREAK
+        self.assert_received(self.debugger, [
+            self.expected_pydevd_request(
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tprint(' + repr("Hello World") + ')\tNone\tTrue'), # noqa
+            self.expected_pydevd_request(
+                '2\tdjango-line\teggs.html\t17\tNone\tNone\tprint(' + repr("Hello Django World") + ')\tNone\tTrue'), # noqa
         ])
 
     def test_vs_flask_jinja2(self):
@@ -1152,9 +1237,46 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone'),
+                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone\tNone'), # noqa
+        ])
+
+    def test_vs_flask_jinja2_logpoint(self):
+        with self.launched(args={'options': 'FLASK_DEBUG=True'}):
+            self.send_request(
+                source={'path': 'spam.py'},
+                breakpoints=[{'line': '10', 'logMessage': 'Hello World'}],
+            )
+            self.send_request(
+                source={'path': 'eggs.html'},
+                breakpoints=[{'line': '17', 'logMessage': 'Hello Jinja World'}], # noqa
+            )
+            received = self.vsc.received
+
+        self.assert_vsc_received(received, [
+            self.expected_response(
+                breakpoints=[
+                    {'id': 1,
+                     'verified': True,
+                     'line': '10'},
+                ],
+            ),
+            self.expected_response(
+                breakpoints=[
+                    {'id': 2,
+                     'verified': True,
+                     'line': '17'},
+                ],
+            ),
+        ])
+
+        self.PYDEVD_CMD = CMD_SET_BREAK
+        self.assert_received(self.debugger, [
+            self.expected_pydevd_request(
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tprint(' + repr("Hello World") + ')\tNone\tTrue'), # noqa
+            self.expected_pydevd_request(
+                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tprint(' + repr("Hello Jinja World") + ')\tNone\tTrue'), # noqa
         ])
 
     def test_vsc_flask_jinja2(self):
@@ -1189,9 +1311,9 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone'),
+                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone\tNone'), # noqa
         ])
 
     def test_vsc_jinja2(self):
@@ -1226,9 +1348,9 @@ class SetBreakpointsTests(NormalRequestTest, unittest.TestCase):
         self.PYDEVD_CMD = CMD_SET_BREAK
         self.assert_received(self.debugger, [
             self.expected_pydevd_request(
-                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone'),
+                '1\tpython-line\tspam.py\t10\tNone\tNone\tNone\tNone\tNone'),
             self.expected_pydevd_request(
-                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone'),
+                '2\tjinja2-line\teggs.html\t17\tNone\tNone\tNone\tNone\tNone'), # noqa
         ])