Skip to content

Commit 54f5427

Browse files
logs: Add --verbose-logs to write debug logs to a file
Verbose output is usually wanted after a command has already run and exited, which -v can't provide retroactively. Leaving -v on all the time isn't a workable substitute either, since it clutters normal output. Add a second logging backend, off by default and enabled with --verbose-logs. It writes debug logs to $XDG_STATE_HOME/revup/logs, one file per invocation named after the start time and pid, keeping 20 runs of history. The root logger level now only gates what any handler can see; each handler decides for itself, so the console keeps showing INFO while the file gets DEBUG. Both handlers share one filter, so an oauth discovered partway through a run is redacted in the file too. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Signed-off-by: Brian Kubisiak <brian.kubisiak@skydio.com>
1 parent 20c3780 commit 54f5427

5 files changed

Lines changed: 338 additions & 30 deletions

File tree

‎docs/revup.md‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,19 @@ full command-line of any subprocesses that are run along with
2727
their full output, as well as the full input and output of any
2828
graphql requests to the forge.
2929

30+
**--verbose-logs**
31+
: Writes debug details to a log file instead of the terminal, leaving
32+
normal output unchanged. Off by default. Useful for inspecting a run
33+
that has already finished, since it doesn't require knowing ahead of
34+
time that you'd want verbose output. Can be combined with --verbose,
35+
which additionally shows debug logs on the terminal and makes
36+
subprocesses themselves verbose.
37+
38+
Logs are written to `$XDG_STATE_HOME/revup/logs` (or
39+
`~/.local/state/revup/logs` if that isn't set), one file per
40+
invocation named after the start time and process id. The 20 newest
41+
files are kept and older ones are deleted.
42+
3043
**--help, -h**
3144
: Show this help page.
3245

‎revup/logs.py‎

Lines changed: 114 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,18 @@
11
import logging
2+
import os
23
import re
3-
from typing import Dict
4+
import sys
5+
import time
6+
from typing import Dict, List, Optional, Type, TypeVar
47

58
from rich._log_render import LogRender
69
from rich.logging import RichHandler
710
from rich.text import Text
811

12+
from revup.version import REVUP_VERSION
13+
14+
HandlerType = TypeVar("HandlerType", bound=logging.Handler)
15+
916

1017
class RedactingFilter(logging.Filter):
1118
redactions: Dict[str, str]
@@ -53,21 +60,47 @@ def set_render(self, log_render: LogRender) -> None:
5360
self._log_render = log_render
5461

5562

56-
def configure_logger(debug: bool, redactions: Dict[str, str]) -> None:
57-
root_logger = logging.getLogger()
58-
root_logger.setLevel(logging.DEBUG if debug else logging.INFO)
59-
60-
for h in root_logger.handlers:
61-
if isinstance(h, RichHandler):
62-
for k, v in redactions.items():
63-
for f in h.filters:
64-
if isinstance(f, RedactingFilter):
65-
f.redact(k, v)
66-
return
67-
68-
log_filter = RedactingFilter()
69-
for k, v in redactions.items():
70-
log_filter.redact(k, v)
63+
def find_handler(handler_type: Type[HandlerType]) -> Optional[HandlerType]:
64+
"""
65+
Find an already installed handler of the given type.
66+
"""
67+
for h in logging.getLogger().handlers:
68+
if isinstance(h, handler_type):
69+
return h
70+
return None
71+
72+
73+
def get_log_filter() -> RedactingFilter:
74+
"""
75+
The filter shared by all handlers, so redactions added at any point apply to all
76+
backends. Must be called after configure_logger().
77+
"""
78+
for h in logging.getLogger().handlers:
79+
for f in h.filters:
80+
if isinstance(f, RedactingFilter):
81+
return f
82+
raise AssertionError("Logger must be configured before redacting")
83+
84+
85+
def prune_old_logs(log_dir: str, keep: int) -> None:
86+
"""
87+
Delete all but the newest `keep` log files. Names sort chronologically so we can
88+
prune without stat-ing every file.
89+
"""
90+
try:
91+
names: List[str] = sorted(n for n in os.listdir(log_dir) if n.endswith(".log"))
92+
except OSError:
93+
return
94+
95+
for name in names[: max(len(names) - keep, 0)]:
96+
try:
97+
os.remove(os.path.join(log_dir, name))
98+
except OSError:
99+
# Another revup may have pruned it already, or we may not own it.
100+
pass
101+
102+
103+
def make_console_handler(log_filter: logging.Filter) -> RichHandler:
71104
handler = RevupRichHandler(keywords=[])
72105
handler.addFilter(log_filter)
73106
handler.set_render(
@@ -79,12 +112,74 @@ def configure_logger(debug: bool, redactions: Dict[str, str]) -> None:
79112
)
80113
)
81114
handler.highlighter = None # type: ignore
115+
return handler
116+
117+
118+
def make_file_handler(log_filter: logging.Filter) -> Optional[logging.FileHandler]:
119+
"""
120+
Create a handler that writes debug logs for this invocation to a new file. Returns
121+
None if the file couldn't be created, since logging is never worth failing over.
122+
"""
123+
# Follow the XDG base directory spec for state that should persist between restarts
124+
# but isn't precious.
125+
state_home = os.environ.get("XDG_STATE_HOME")
126+
if not state_home:
127+
state_home = os.path.join(os.path.expanduser("~"), ".local", "state")
128+
log_dir = os.path.join(state_home, "revup", "logs")
129+
130+
try:
131+
os.makedirs(log_dir, exist_ok=True)
132+
# Keep 19 old logs plus the one we're about to add, for 20 runs of history.
133+
prune_old_logs(log_dir, 19)
134+
path = os.path.join(
135+
log_dir, "{}-{}.log".format(time.strftime("%Y%m%dT%H%M%S"), os.getpid())
136+
)
137+
handler = logging.FileHandler(path, encoding="utf-8")
138+
except OSError as e:
139+
logging.warning(f"Couldn't write verbose logs to {log_dir}: {e}")
140+
return None
141+
142+
handler.setLevel(logging.DEBUG)
143+
handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)-7s %(message)s"))
144+
handler.addFilter(log_filter)
145+
return handler
146+
147+
148+
def configure_logger(debug: bool, redactions: Dict[str, str], log_to_file: bool = False) -> None:
149+
"""
150+
Set up logging backends. Can be called more than once to update options, which is
151+
needed since some logging happens before config and args are fully parsed.
152+
153+
Args:
154+
debug: Show debug logs on the console.
155+
redactions: Strings that must never appear in any log, and their replacements.
156+
log_to_file: Additionally write debug logs to a file in the state directory,
157+
regardless of what the console shows.
158+
"""
159+
root_logger = logging.getLogger()
160+
# The root level must allow debug logs through if any handler wants them; each
161+
# handler then decides for itself what to show.
162+
root_logger.setLevel(logging.DEBUG if debug or log_to_file else logging.INFO)
163+
164+
console_handler = find_handler(RichHandler)
165+
if console_handler is None:
166+
console_handler = make_console_handler(RedactingFilter())
167+
root_logger.addHandler(console_handler)
168+
console_handler.setLevel(logging.DEBUG if debug else logging.INFO)
169+
170+
log_filter = get_log_filter()
171+
for k, v in redactions.items():
172+
log_filter.redact(k, v)
82173

83-
root_logger.addHandler(handler)
174+
if log_to_file and find_handler(logging.FileHandler) is None:
175+
file_handler = make_file_handler(log_filter)
176+
if file_handler is not None:
177+
root_logger.addHandler(file_handler)
178+
# Record what was run, since the file outlives the terminal it came from.
179+
logging.debug("revup {} : {}".format(REVUP_VERSION, " ".join(sys.argv[1:])))
84180

85181

86182
def redact(redactions: Dict[str, str]) -> None:
87-
log_filter = logging.getLogger().handlers[0].filters[0]
88-
assert isinstance(log_filter, RedactingFilter)
183+
log_filter = get_log_filter()
89184
for k, v in redactions.items():
90185
log_filter.redact(k, v)

‎revup/revup.py‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,7 @@ def make_toplevel_parser() -> RevupArgParser:
5656
revup_parser.add_argument("--fork-name", default="")
5757
revup_parser.add_argument("--editor")
5858
revup_parser.add_argument("--verbose", "-v", action="store_true")
59+
revup_parser.add_argument("--verbose-logs", action="store_true")
5960
revup_parser.add_argument("--keep-temp", "-k", action="store_true")
6061
revup_parser.add_argument("--git-path", default="")
6162
revup_parser.add_argument("--main-branch", default="main")
@@ -110,7 +111,7 @@ async def get_config() -> config.Config:
110111

111112

112113
def dump_args(args: argparse.Namespace) -> None:
113-
if args.verbose:
114+
if logging.getLogger().isEnabledFor(logging.DEBUG):
114115
import json
115116

116117
logging.debug(json.dumps(vars(args), default=str, indent=2))
@@ -338,6 +339,7 @@ async def main(revup_parser: RevupArgParser, all_parsers: List[RevupArgParser])
338339
logs.configure_logger(
339340
debug=args.verbose,
340341
redactions={args.forge_oauth: "<GITHUB_OAUTH>"} if args.forge_oauth else {},
342+
log_to_file=args.verbose_logs,
341343
)
342344

343345
if args.cmd != "toolkit":

‎revup/shell.py‎

Lines changed: 18 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,14 @@
2222
_HANDLE = Union[None, int, IO[Any]]
2323

2424

25+
def debug_enabled() -> bool:
26+
"""
27+
Whether any logging backend consumes debug logs. Verbose messages can be expensive
28+
to format (decoding entire command outputs), so skip them if nobody will see them.
29+
"""
30+
return logging.getLogger().isEnabledFor(logging.DEBUG)
31+
32+
2533
def log_command(args: Sequence[str]) -> None:
2634
"""
2735
Given a command, print it in a both machine and human readable way.
@@ -126,10 +134,10 @@ def __init__(
126134
Args:
127135
cwd: Current working directory of the shell. Pass None to
128136
initialize to the current cwd of the current process.
129-
quiet: If True, suppress printing out the command executed
130-
by the shell. By default, we print out commands for ease
131-
of debugging. Quiet is most useful for non-mutating
132-
shell commands.
137+
quiet: If True, don't ask subprocesses to be verbose about what
138+
they're doing, since that output goes straight to the user's
139+
terminal. Note this doesn't affect debug logging of commands
140+
and their output, which is governed by the log level.
133141
"""
134142
self.quiet = quiet
135143
self.cwd = cwd if cwd else os.getcwd()
@@ -208,7 +216,7 @@ async def sh(
208216
and return it
209217
raiseonerror: whether to raise an error if return value is not 0
210218
"""
211-
if not self.quiet:
219+
if debug_enabled():
212220
log_command(args)
213221
start_time = time.time()
214222
tasks = await self.create_sh_task(
@@ -224,7 +232,7 @@ async def sh(
224232
_, out, err, ret = await asyncio.gather(*tasks)
225233

226234
ret = self.handle_sh_results(ret, out, err, stdout, raiseonerror, quiet, *args)
227-
if not self.quiet:
235+
if debug_enabled():
228236
logging.debug("Took {}s".format(time.time() - start_time))
229237
return ret
230238

@@ -245,7 +253,7 @@ async def piped_sh(
245253
start_time = time.time()
246254
read, write = os.pipe()
247255
log_args = args1 + ["|"] + args2
248-
if not self.quiet:
256+
if debug_enabled():
249257
log_command(log_args)
250258

251259
tasks = await asyncio.gather(
@@ -268,7 +276,7 @@ async def piped_sh(
268276
ret2 if ret1 == 0 else ret1, out2, err1 + err2, stdout, raiseonerror, quiet, *log_args
269277
)
270278
os.close(read)
271-
if not self.quiet:
279+
if debug_enabled():
272280
logging.debug("Took {}s".format(time.time() - start_time))
273281
return ret
274282

@@ -284,9 +292,9 @@ def handle_sh_results(
284292
) -> Tuple[int, str]:
285293
if returncode and err:
286294
logging.warning(err.decode(errors="backslashreplace"))
287-
elif not (quiet or self.quiet) and err:
295+
elif not quiet and debug_enabled() and err:
288296
logging.debug("# stderr:\n{}".format(err.decode(errors="backslashreplace")))
289-
if not (quiet or self.quiet) and out:
297+
if not quiet and debug_enabled() and out:
290298
logging.debug(
291299
"{}{}".format(
292300
("# stdout:\n" if err else ""),

0 commit comments

Comments
 (0)