Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DRAFT Spec for Buffer Exporting and Logging #11090

Merged
6 commits merged into from
Dec 13, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion .github/actions/spelling/expect/expect.txt
Original file line number Diff line number Diff line change
Expand Up @@ -2113,7 +2113,6 @@ webpage
websites
websockets
wekyb
WEOF
wex
wextest
wextestclass
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,380 @@
---
author: Mike Griese @zadjii-msft
created on: 2021-08-31
last updated: 2021-08-31
issue id: #642
---

# Buffer Exporting and Logging

## Abstract

A common user need is the ability to export the history of a terminal session to
a file, for later inspection or validation. This is something that could be
triggered manually. Many terminal emulators provide the ability to automatically
log the output of a session to a file, so the history is always captured. This
spec will address improvements to the Windows Terminal to enable these kinds of
exporting and logging scenarios.

## Background

### Inspiration

Below are screenshots from the settings pages of three different terminal
emulators with similar features - PuTTY, SecureCRT, and ConEmu:

![PuTTY settings](PuTTY-logging-settings.png)

_figure 1: PuTTY settings_

![SecureCRT settings](SecureCRT-logging-settings.png)

_figure 2: SecureCRT settings_

![ConEmu settings](ConEmu-logging-settings.png)

_figure 3: ConEmu settings_

These applications all offer some settings in common. Primarily, the important
feature is the ability to specify a path to a log file which contains some
special string formatting. This allows the user to log to different files based
on the time & date of the session, or based on the session name.

### User Stories

* **Story A**: The user is able to use a context menu entry on the tab to export
the contents of the buffer to a file, which they are prompted for.
- This is explicitly what was requested in [#642]
* **Story B**: The user can bind an action to export the contents of the buffer
to a file, which they are prompted for.
- Very similar to **A**, but via the command palette or a keybinding.
* **Story C**: The user can export to an explicit file via an action
- similar to **B**, but allowing for declaring the path to a file rather than
prompting at runtime.
* **Story D**: The user can choose to append to a file when exporting, rather
than overwriting.
* **Story E**: The user can specify a format string in the path to the file to
export to, which the Terminal will automatically replace with variables like
the time, date, and profile name.
* **Story F**: When opening a specific profile, the user can automatically log
to a file
* **Story G**: The user can execute an action to start or stop logging to a
given file.


## Solution Design

I'm proposing the following actions and profile settings

* New Action: `exportBuffer()`.
- Export the contents of the buffer to a file.
- `path` (string, defaults to `""`): When empty, prompt the user for a name of
a file to export to, using a file picker. This path accepts special
formatting strings that will be substituted with certain variables
(discussed [below](#path-formatting)).
- `append` (boolean, defaults to `false`): When `false`, the file's contents
will be overwritten. When `true`, the buffer contents will be appended to
the end of the file.
* New Profile Settings object: `logSettings`
- This is an object that describes a set of behavior for logging a profile.
- `path`: Same as the `path` in the `ExportBufferArgs` above
- `append`: Same as the `append` in the `ExportBufferArgs` above
- `captureAllOutput`: (boolean, defaults to `false`) When true, don't log only
printable characters, also log non-printable escape characters written to
the Terminal.
- `captureInput`: (boolean, defaults to `false`) Additionally log input to the
Terminal to the file. Input will be formatted as the traditional VT
sequences, rather than the full `win32-input` encoding.
- `newFileEveryDay`: (boolean, defaults to `false`) This requires the `day` to
be an element of the path format string. When logging with this setting,
opens a new file at midnight and starts writing that one.
<!-- TODO! - `flushFrequently`: (boolean, defaults to `true`) -->
* New Profile setting: `logAutomatically` (boolean, default `false`). When true,
terminals with this profile will begin logging automatically.
* New Action: `toggleLogging()`.
- Start or stop logging to the configured file. If the terminal is already
logging with different settings than in this action, then stop logging
regardless (don't just start logging to the new file)
- This action accepts all the same args the profile's `logSettings` object.
- If _any_ args are provided, use those args. If _none_ are provided, then use
the logging settings present in the profile (if there are any).
- If there's not path provided (either in the args to the action or in the
profile), prompt the user to pick a file to log to.

### Examples
```json
{
"actions": [
{ "keys": "f1", "command": "exportBuffer" },
{ "keys": "f2", "command": { "action": "exportBuffer", "path": "c:\\logs\\${year}-${month}-${date}\\{profile}.txt" } },

{ "keys": "f3", "command": "toggleLogging" },
{ "keys": "f4", "command": { "action": "toggleLogging", "path": "c:\\logs\\${profile}.log", "append": true } },
],
"profiles": [
{
"name": "foo",
"logging": {
"path": "c:\\foo.txt",
"append": true
},
"automaticallyLog": false
},
{
"name": "bar",
"logging": {
"path": "c:\\logs\\${date}\\bar.txt",
"append": false
},
"automaticallyLog": true
}
]
}
```

Revisiting our original stories:

* **Story A**: This is already implemented in [#11062]
* **Story B**: This is the action bound to <kbd>f1</kbd>.
* **Story C**: This is the action bound to <kbd>f2</kbd>.
* **Story D**: This is the `append` property in the actions, profile settings.
* **Story E**: An example of this is in the action bound to <kbd>f2</kbd>,
<kbd>f4</kbd>, and in the profile "bar"'s logging settings.
* **Story F**: The profile "bar" is configured to automatically log when opened.
* **Story G**: This is the action bound to <kbd>f4</kbd>.

In addition,
* When opening the profile "foo", it will not automatically log to a file.
- Pressing <kbd>f3</kbd> will begin logging to `c:\foo.txt`
- Pressing <kbd>f4</kbd> will begin logging to `c:\logs\foo.log`

### Path formatting

[TODO!]: # TODO!

For discussion: What syntax do we want?
* PuTTY uses `&Y`, `&M`, `&D`, `&T`, `&H`, `&P` for year, month, day, time, host
and port respectively.
* SecureCRT uses:
- `%H` – hostname
- `%S` – session name
- `%Y` – four-digit year
- `%M` – two-digit month
- `%D` – two-digit day of the month
- `%h` – two-digit hour
- `%m` – two-digit minute
- `%s` – two-digit seconds
- `%t` – three-digit milliseconds
- `%%` – percent (%)
- `%envvar%` – environment variable (for instance `%USERNAME%`)

We have some precedent for formatting with `${braces}`, a la the iterable
command in the Command Palette (e.g `${profile.name}`). Additionally, [#9287]
implements support for environment variables in the Terminal with the
`${env:VARIABLE}` syntax.

What variables do we want exposed, and how do we want users to be able to format
them?

This doc was initially authored assuming we'd go with a `${braces}` syntax, like:
- `${profile}` – profile name
- `${year}` – four-digit year
- `${month}` – two-digit month
- `${day}` – two-digit day of the month
- `${hour}` – two-digit hour
- `${minute}` – two-digit minute
- `${second}` – two-digit second
- `${ms}` – three-digit milliseconds
- `${env:variable}` – environment variable (for instance `${env:USERPROFILE}`)
(inspired by [#9287])

### Exporting vs Logging
As far as specific implementation details goes, exporting is the easier work to
do. [#11062] already wires up the `TerminalApp` to retrieve the buffer contents
from the `TermControl`, so writing them at request is easy.

Logging is harder. We don't want the `TermControl` telling the `TerminalApp`
layer about every piece of output logged. Especially in the post-[#5000] world
where that's a cross-process hop. Instead, we'll want the `ControlCore` /
`ControlInteractivity` to do _logging_ themselves.

### Logging Mechanics

#### When do we log?

[TODO!]: # TODO!

When do we decide to actually log? Take for example typing in a `pwsh` or
`bash` prompt. Imagine the user types
<kbd>w</kbd><kbd>h</kbd><kbd>a</kbd><kbd>t</kbd>, then hits
<kbd>Bksp</kbd><kbd>Bksp</kbd>, such that the prompt is just `wh`. What should
the log contain? `what^h ^h^h ^h`<sup>[[1]](#footnote-1)</sup>? `wh`?

My worry with logging the backspaces is that conpty is sometimes a bit noisier
than it needs to be with using `^H` as a cursor positioning sequence. Should we
only log lines when the cursor newlines or otherwise moves from the line it is
currently on?

I'll need to look at what PuTTY emits for the "Printable output" option.

#### What happens when we _start_ logging?

If the user has a terminal that did not start with logging enabled, but then
started logging with `toggleLogging`, what should we log? All future output? Or
should we log the current buffer contents as well?

I'm inclined to lean towards simply "all future output", and ignore any current
buffer content. If the user rally wants to log the current buffer contents _and_
start logging, they can use a `multipleActions` action ([#11045]) to
`exportBuffer` to a file, then `toggleLogging` to that same file with
`"append":true`.

## Potential Issues

<table>

<tr>
<td><strong>Compatibility</strong></td>
<td>

Since this functionality is entirely new, nothing here should negatively affect
existing functionality.

</td>
</tr>
<tr>
<td><strong>Performance, Power, and Efficiency</strong></td>
<td>

When logging, it's expected there will be a measurable performance hit. We can
try to mitigate this by only writing to the file on a background thread,
separate from the connection or rendering thread. Since auto-logging will only
take place in the content process, we're not worried about the file writing
occurring on the UI thread.

</td>
</tr>
</table>

Also frequently requested is the ability to log timestamps of when commands are
executed. I don't think that this is a valuable feature for the Terminal to
implement ourselves. Windows Terminal is fundamentally just a _terminal
emulator_, it doesn't really know what's going on behind the scenes with
whatever client application (`cmd`, `powershell`, `bash`, `vim`) that is
connected to it. WT doesn't know when the user is typing in commands to the
shell, or if the user is just typing in text in `emacs` or something. There's no
way for the terminal to know that. It's _typically_ the client application's
responsibility to save it's own command history. `bash` and `powershell` both do
a pretty good job of saving this to another file to restore across sessions,
while `cmd.exe` doesn't.

Windows is a messy world and this model gets a little tricky here. `cmd.exe`
isn't actually managing it's own command history _at all_. `conhost` is doing
that work on behalf of the client applications. Some long time ago someone
thought it would be a good idea to have the `readline` functionality baked
directly into the console host. Whether that was a good idea or not remains to
be seen - it's certainly made things like `python.exe`'s REPL easier to
implement, since they don't need to maintain their own history buffer, but it
makes it hard to de-tangle behavior like this from the console itself.

I'm not sure how it would be possible to add a keybinding to the Windows
Terminal that would be able to save the console's _command_ history. Especially
considering the Terminal might _not_ be connected to a console host session at
all. If the Windows Terminal were directly running a `wsl` instance (something
that's not possible today, but something we've considered adding in the future),
then there wouldn't be a `conhost` in the process tree at all, and now
requesting the command history from the console wouldn't work _mysteriously_.

Furthermore, shells can always be configured to emit timestamps in their prompts
themselves. Since the Terminal has no knowledge of when a command is actually
entered, but the _shell_ does, it makes the most sense to configure the user's
_shell_ to emit that information. The Terminal will then dutifully log that
output along with everything else.

## Implementation Plan

Below is a rough outline of how I'd go about implementing these features. Each
lop-level checkbox could be its own PR, following from [#11062].

### Buffer exporting

* [ ] Add an `exportBuffer()` action that opens the file picker
* [ ] Add a string `path` parameter to `exportBuffer()` that allows the user to
press a key and immediately export the buffer to a whole path
- default to `""`, which indicates "open the file picker"
* [ ] add a boolean `append` (default to `false`) parameter to `exportBuffer`.
When true, export to the file given by appending, not overwriting the file
* [ ] Enable string formatting in the `path` parameter.
- What format do we want? `yyyy-mm-dd`? `%Y-%m-%D`? `&Y-&m-&D`? `${year}-${month}-${day}`?
- What are all the variables we want?
- Year, month, day, hour, minute - those are easy
- `WT_SESSION`, for a uuid for each session maybe?
- Profile name perhaps? Commandline?
* [ ] more...

### Automatic logging

* [ ] `toggleLogging()` Action for start/stop logging, with `path`, `append`
properties (like `exportBuffer()`)
- `ToggleLoggingArgs` contains a single member `LoggingSettings`, which
contains `path` and `append` properties. This will make sense below.
* [ ] add `LoggingSettings` property for "log all output" (default would just be
"log printable output")
* [ ] add `LoggingSettings` property for "log input" (Though, we'd probably want
to log it as normal VT encoded, not as `win32-input` encoded)
* [ ] Per-profile setting for `logSettings`, which can contain an entire
`LoggingSettings` (like the `ToggleLoggingArgs`). When `toggleLogging` with no
args, try to use the profile's `loggingSettings` instead.
* [ ] Per-profile setting for `automaticallyLog`, which would log by default
when the profile is opened
* [ ] `LoggingSettings` property for "New file every day", which only works when
the `{day}` is in the path string. When auto-logging with this setting, opens
a new file at midnight and starts writing that one.
<!-- * [ ] `LoggingSettings` property for "Flush log frequently", defaults to
`true`(?). This causes us to flush all output to the file, instead of just...
on close? on newline? It's unclear exactly when PuTTY flushes with this off.
Need more coffee. -->

### Future Considerations

* When logging begins, the Terminal could display a toast for "Logging to
{filename}", and a similar one for "Stopped logging to {filename}".
* There's no good way of displaying a UI element to indicate that a pane is
currently logging to a file. I don't believe PuTTY displays any sort of
indicator. SecureCRT only displays a checkbox within the context menus of the
application itself.
![SecureCRT context menu](SecureCRT-context-menu.png)

Maybe when logging to a file, we could replace the "Export Text" context menu
entry with "Stop Logging"
* We could maybe add a setting to disable logging from the alt buffer. This
might help make this setting more valuable for users who are using full-screen
applications like `vim`. Since those applications redraw the entire viewport
contents frequently, the log might be unnecessarily noisy. Disabling logging
while in the alt buffer would show that the user opened vim, and then they did
some things after vim exited.
* Logging all output will be VERY helpful to us in the future for trying to
recreate bugs on our end that users can repro but we can't!

## Resources

PuTTY Logging documentation: https://tartarus.org/~simon/putty-snapshots/htmldoc/Chapter4.html#config-logfilename
ConEmu Logging documentation: https://conemu.github.io/en/AnsiLogFiles.html

### Footnotes

<a name="footnote-1"><a>[1]: Remember that `^H` is non-destructive, so the
sequence `what^h ^h^h ^h` is can be read as:
* print "what"
* move the cursor back one
* print a space (overwriting 't')
* move the cursor back one (now it's on the space where 't' was)
* move the cursor back one
* print a space (overwriting 'a')
* move the cursor back one (now it's on the space where 'a' was)

[#642]: https://github.com/microsoft/terminal/issues/642
[#5000]: https://github.com/microsoft/terminal/issues/5000
[#9287]: https://github.com/microsoft/terminal/pull/9287
[#11045]: https://github.com/microsoft/terminal/pull/11045
[#11062]: https://github.com/microsoft/terminal/pull/11062
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.