Redirecting stdout to both devtools and logfile

This commit is contained in:
Darren Burns
2022-04-14 11:10:47 +01:00
parent ee19daf6a6
commit 3b40eb828b
6 changed files with 102 additions and 62 deletions

View File

@@ -32,7 +32,7 @@ from .binding import Bindings, NoBinding
from .css.stylesheet import Stylesheet, StylesheetError
from .design import ColorSystem
from .devtools.client import DevtoolsClient, DevtoolsConnectionError, DevtoolsLog
from .devtools.redirect_output import DevtoolsRedirector
from .devtools.redirect_output import StdoutRedirector
from .dom import DOMNode
from .driver import Driver
from .file_monitor import FileMonitor
@@ -522,22 +522,13 @@ class App(DOMNode):
self.refresh()
await self.animator.start()
if self.devtools.is_connected:
with redirect_stdout(DevtoolsRedirector(self.devtools)): # type: ignore
await super().process_messages()
else:
with redirect_stdout(StdoutRedirector(self.devtools, self.log_file)): # type: ignore
await super().process_messages()
log("PROCESS END")
if self.devtools.is_connected:
await self._disconnect_devtools()
self.log_file.write(
f"Disconnected from devtools ({self.devtools.url})\n"
)
with timer("animator.stop()"):
await self.animator.stop()
with timer("self.close_all()"):
await self.close_all()
log("Message processing stopped")
with timer("animator.stop()"):
await self.animator.stop()
with timer("self.close_all()"):
await self.close_all()
finally:
driver.stop_application_mode()
except Exception as error:
@@ -546,6 +537,12 @@ class App(DOMNode):
self._running = False
if self._exit_renderables:
self._print_error_renderables()
if self.devtools.is_connected:
await self._disconnect_devtools()
if self.log_file is not None:
self.log_file.write(
f"Disconnected from devtools ({self.devtools.url})\n"
)
if self.log_file is not None:
self.log_file.close()

View File

@@ -34,7 +34,7 @@ class DevtoolsLog(NamedTuple):
"""
objects_or_string: tuple[Any, ...] | str
caller: inspect.FrameInfo | None = None
caller: inspect.FrameInfo
class DevtoolsConsole(Console):
@@ -189,7 +189,7 @@ class DevtoolsClient:
return False
return not (self.session.closed or self.websocket.closed)
def log(self, log: DevtoolsLog):
def log(self, log: DevtoolsLog) -> None:
"""Queue a log to be sent to the devtools server for display.
Args:

View File

@@ -1,26 +1,32 @@
from __future__ import annotations
import inspect
from typing import TYPE_CHECKING
from io import TextIOWrapper
from typing import TYPE_CHECKING, cast
from textual.devtools.client import DevtoolsLog
if TYPE_CHECKING:
from textual.devtools.client import DevtoolsClient
class DevtoolsRedirector:
class StdoutRedirector:
"""
A write-only file-like object which redirects anything written to it to the devtools
instance associated with the given Textual application. Used within Textual to redirect
data written using `print` (or any other stdout writes) to the devtools.
data written using `print` (or any other stdout writes) to the devtools and/or to the
log file.
"""
def __init__(self, devtools: DevtoolsClient) -> None:
def __init__(
self, devtools: DevtoolsClient, log_file: TextIOWrapper | None
) -> None:
"""
Args:
devtools (DevtoolsClient): The running Textual app instance.
log_file (TextIOWrapper): The log file for the Textual App.
"""
self.devtools = devtools
self.log_file = log_file
self._buffer: list[DevtoolsLog] = []
def write(self, string: str) -> None:
@@ -31,6 +37,10 @@ class DevtoolsRedirector:
Args:
string (str): The string to write to the buffer.
"""
if not (self.devtools.is_connected or self.log_file is not None):
return
caller = inspect.stack()[1]
self._buffer.append(DevtoolsLog(string, caller=caller))
@@ -46,9 +56,18 @@ class DevtoolsRedirector:
def flush(self) -> None:
"""Flush the buffer. This will send all buffered log messages to
the devtools server. Where possible, log messages will be batched
and sent as one.
the devtools server and the log file. In the case of the devtools,
where possible, log messages will be batched and sent as one.
"""
self._write_to_log_file()
self._write_to_devtools()
self._buffer.clear()
def _write_to_devtools(self) -> None:
"""Send the contents of the buffer to the devtools."""
if not self.devtools.is_connected:
return
log_batch: list[DevtoolsLog] = []
for log in self._buffer:
end_of_batch = log_batch and (
@@ -56,21 +75,32 @@ class DevtoolsRedirector:
or log_batch[-1].caller.lineno != log.caller.lineno
)
if end_of_batch:
self._log_batched(log_batch)
self._log_devtools_batched(log_batch)
log_batch.clear()
log_batch.append(log)
if log_batch:
self._log_batched(log_batch)
self._log_devtools_batched(log_batch)
self._buffer.clear()
def _write_to_log_file(self) -> None:
"""Write the contents of the buffer to the log file."""
if not self.log_file:
return
def _log_batched(self, log_batch: list[DevtoolsLog]) -> None:
"""Write a single batch of logs. A batch means contiguous logs
try:
log_text = "".join(str(log.objects_or_string) for log in self._buffer)
self.log_file.write(log_text)
self.log_file.flush()
except OSError:
# An error writing to the log file should not be
# considered fatal.
pass
def _log_devtools_batched(self, log_batch: list[DevtoolsLog]) -> None:
"""Write a single batch of logs to devtools. A batch means contiguous logs
which have been written from the same line number and file path.
A single `print` call may correspond to multiple writes.
e.g. `print("a", "b", "c")` is 3 calls to `write`, so we batch
up these calls if they come from the same location in code, so that
up these 3 write calls since they come from the same location, so that
they appear inside the same log message in the devtools window
rather than a single `print` statement resulting in 3 separate
logs being displayed.
@@ -79,7 +109,9 @@ class DevtoolsRedirector:
log_batch (list[DevtoolsLog]): A batch of logs to send to the
devtools server as one. Log content will be joined together.
"""
batched_log = "".join(log.objects_or_string for log in log_batch)
# This code is only called via stdout.write, and so by this point we know
# that the log message content is a string. The cast below tells mypy this.
batched_log = "".join(cast(str, log.objects_or_string) for log in log_batch)
batched_log = batched_log.rstrip()
if self.devtools.is_connected:
self.devtools.log(DevtoolsLog(batched_log, caller=log_batch[-1].caller))
self.devtools.log(DevtoolsLog(batched_log, caller=log_batch[-1].caller))

View File

@@ -1,3 +1,5 @@
from io import StringIO
import pytest
from textual.devtools.server import _make_devtools_aiohttp_app
@@ -25,3 +27,8 @@ async def devtools(aiohttp_client, server):
yield devtools
await devtools.disconnect()
await client.close()
@pytest.fixture
def in_memory_logfile():
yield StringIO()

View File

@@ -1,4 +1,5 @@
import json
import types
from asyncio import Queue
from datetime import datetime
@@ -11,6 +12,9 @@ from tests.utilities.render import wait_for_predicate
from textual.devtools.client import DevtoolsClient
from textual.devtools.redirect_output import DevtoolsLog
CALLER_LINENO = 123
CALLER_PATH = "a/b/c.py"
CALLER = types.SimpleNamespace(filename=CALLER_PATH, lineno=CALLER_LINENO)
TIMESTAMP = 1649166819
@@ -26,15 +30,15 @@ async def test_devtools_client_is_connected(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_devtools_log_places_encodes_and_queues_message(devtools):
await devtools._stop_log_queue_processing()
devtools.log(DevtoolsLog("Hello, world!"))
devtools.log(DevtoolsLog("Hello, world!", CALLER))
queued_log = await devtools.log_queue.get()
queued_log_json = json.loads(queued_log)
assert queued_log_json == {
"type": "client_log",
"payload": {
"timestamp": TIMESTAMP,
"path": "",
"line_number": 0,
"path": CALLER_PATH,
"line_number": CALLER_LINENO,
"encoded_segments": "gANdcQAoY3JpY2guc2VnbWVudApTZWdtZW50CnEBWA0AAABIZWxsbywgd29ybGQhcQJOTodxA4FxBGgBWAEAAAAKcQVOTodxBoFxB2Uu",
},
}
@@ -43,15 +47,15 @@ async def test_devtools_log_places_encodes_and_queues_message(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_devtools_log_places_encodes_and_queues_many_logs_as_string(devtools):
await devtools._stop_log_queue_processing()
devtools.log(DevtoolsLog(("hello", "world")))
devtools.log(DevtoolsLog(("hello", "world"), CALLER))
queued_log = await devtools.log_queue.get()
queued_log_json = json.loads(queued_log)
assert queued_log_json == {
"type": "client_log",
"payload": {
"timestamp": TIMESTAMP,
"path": "",
"line_number": 0,
"path": CALLER_PATH,
"line_number": CALLER_LINENO,
"encoded_segments": "gANdcQAoY3JpY2guc2VnbWVudApTZWdtZW50CnEBWAsAAABoZWxsbyB3b3JsZHECTk6HcQOBcQRoAVgBAAAACnEFTk6HcQaBcQdlLg==",
},
}
@@ -63,10 +67,10 @@ async def test_devtools_log_spillover(devtools):
devtools.log_queue = Queue(maxsize=2)
# Force spillover of 2
devtools.log(DevtoolsLog((Panel("hello, world"),)))
devtools.log(DevtoolsLog("second message"))
devtools.log(DevtoolsLog("third message")) # Discarded by rate-limiting
devtools.log(DevtoolsLog("fourth message")) # Discarded by rate-limiting
devtools.log(DevtoolsLog((Panel("hello, world"),), CALLER))
devtools.log(DevtoolsLog("second message", CALLER))
devtools.log(DevtoolsLog("third message", CALLER)) # Discarded by rate-limiting
devtools.log(DevtoolsLog("fourth message", CALLER)) # Discarded by rate-limiting
assert devtools.spillover == 2
@@ -75,7 +79,7 @@ async def test_devtools_log_spillover(devtools):
await devtools.log_queue.get()
# Add another message now that we're under spillover threshold
devtools.log(DevtoolsLog("another message"))
devtools.log(DevtoolsLog("another message", CALLER))
await devtools.log_queue.get()
# Ensure we're informing the server of spillover rate-limiting

View File

@@ -5,16 +5,16 @@ from datetime import datetime
import time_machine
from textual.devtools.redirect_output import DevtoolsRedirector
from textual.devtools.redirect_output import StdoutRedirector
TIMESTAMP = 1649166819
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_is_redirected_to_devtools(devtools):
async def test_print_is_redirected_to_devtools(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
with redirect_stdout(DevtoolsRedirector(devtools)):
with redirect_stdout(StdoutRedirector(devtools, in_memory_logfile)): # type: ignore
print("Hello, world!")
assert devtools.log_queue.qsize() == 1
@@ -32,10 +32,10 @@ async def test_print_is_redirected_to_devtools(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_without_flush_not_sent_to_devtools(devtools):
async def test_print_without_flush_not_sent_to_devtools(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
with redirect_stdout(DevtoolsRedirector(devtools)):
with redirect_stdout(StdoutRedirector(devtools, in_memory_logfile)): # type: ignore
# End is no longer newline character, so print will no longer
# flush the output buffer by default.
print("Hello, world!", end="")
@@ -44,20 +44,20 @@ async def test_print_without_flush_not_sent_to_devtools(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_forced_flush_sent_to_devtools(devtools):
async def test_print_forced_flush_sent_to_devtools(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
with redirect_stdout(DevtoolsRedirector(devtools)):
with redirect_stdout(StdoutRedirector(devtools, in_memory_logfile)): # type: ignore
print("Hello, world!", end="", flush=True)
assert devtools.log_queue.qsize() == 1
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_multiple_args_batched_as_one_log(devtools):
async def test_print_multiple_args_batched_as_one_log(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
with redirect_stdout(DevtoolsRedirector(devtools)):
with redirect_stdout(StdoutRedirector(devtools, in_memory_logfile)): # type: ignore
# We call print with multiple arguments here, but it
# results in a single log added to the log queue.
print("Hello", "world", "multiple")
@@ -77,10 +77,10 @@ async def test_print_multiple_args_batched_as_one_log(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_multiple_args_batched_as_one_log(devtools):
async def test_print_multiple_args_batched_as_one_log(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
redirector = DevtoolsRedirector(devtools)
with redirect_stdout(redirector):
redirector = StdoutRedirector(devtools, in_memory_logfile)
with redirect_stdout(redirector): # type: ignore
# This print adds 3 messages to the buffer that can be batched
print("The first", "batch", "of logs", end="")
# This message cannot be batched with the previous message,
@@ -91,10 +91,10 @@ async def test_print_multiple_args_batched_as_one_log(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_print_strings_containing_newline_flushed(devtools):
async def test_print_strings_containing_newline_flushed(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
with redirect_stdout(DevtoolsRedirector(devtools)):
with redirect_stdout(StdoutRedirector(devtools, in_memory_logfile)): # type: ignore
# Flushing is disabled since end="", but the first
# string will be flushed since it contains a newline
print("Hel\nlo", end="")
@@ -104,11 +104,11 @@ async def test_print_strings_containing_newline_flushed(devtools):
@time_machine.travel(datetime.fromtimestamp(TIMESTAMP))
async def test_flush_flushes_buffered_logs(devtools):
async def test_flush_flushes_buffered_logs(devtools, in_memory_logfile):
await devtools._stop_log_queue_processing()
redirector = DevtoolsRedirector(devtools)
with redirect_stdout(redirector):
redirector = StdoutRedirector(devtools, in_memory_logfile)
with redirect_stdout(redirector): # type: ignore
print("x", end="")
assert devtools.log_queue.qsize() == 0