1#!/usr/bin/env python3
2"""One timeline of what OneNote does to a .one on the share: file IO captured by
3Procmon on the Windows client, merged with the byte-range locks zenith reports."""
4import argparse
5import calendar
6import csv
7import datetime
8import importlib.machinery
9import importlib.util
10import json
11import ntpath
12import os
13import re
14import subprocess
15import sys
16import time
17
18W7 = "/Users/clo/dev/one/tools/w7/mcp_win7.py"
19PML = r"C:\trace\out.pml"
20CSV = r"C:\trace\out.csv"
21LOCAL_CSV = "/tmp/onenote-trace.csv"
22TIME = re.compile(r"(\d+):(\d\d):(\d\d)(?:\.(\d+))?\s*([AaPp])?")
23TARGET = os.environ.get("WIN7_TARGET")
24
25
26def zenith():
27 """The sibling tool, imported for its ssh-agent discovery and BYTERANGE parsing."""
28 path = os.path.join(os.path.dirname(os.path.abspath(__file__)), "zenith-locks")
29 loader = importlib.machinery.SourceFileLoader("zenith_locks", path)
30 mod = importlib.util.module_from_spec(importlib.util.spec_from_loader(loader.name, loader))
31 loader.exec_module(mod)
32 mod.connect()
33 return mod
34
35
36def win(*argv):
37 command = [sys.executable, W7]
38 if TARGET:
39 command += ["--target", TARGET]
40 p = subprocess.run(command + list(argv), capture_output=True, text=True)
41 if p.returncode != 0:
42 sys.exit((p.stderr.strip().splitlines() or ["Windows target is unreachable"])[-1])
43 return p
44
45
46def cmd(command):
47 """(exit code, stdout) of `cmd.exe /c command` on the Windows target."""
48 p = win("cmd", command)
49 code = re.search(r"exit=(\d+)", p.stderr)
50 return (int(code.group(1)) if code else None), p.stdout
51
52
53def procmon_path():
54 """Procmon sits in the payload the agent runs from, wherever that was installed."""
55 vendor = ntpath.dirname(ntpath.dirname(json.loads(win("health").stdout)["python"]))
56 return ntpath.join(vendor, "procmon", "Procmon64.exe")
57
58
59def win_clock():
60 """(epoch of wayback's local midnight, wayback's clock minus ours, round trip)."""
61 before = time.time()
62 _, out = cmd("wmic os get localdatetime /value")
63 after = time.time()
64 m = re.search(r"LocalDateTime=(\d{14})\.(\d{6})([+-]\d+)", out)
65 if not m:
66 sys.exit("could not read wayback's clock: %r" % out.strip()[:120])
67 local = datetime.datetime.strptime(m.group(1), "%Y%m%d%H%M%S")
68 utc = int(m.group(3)) * 60
69 midnight = calendar.timegm(local.replace(hour=0, minute=0, second=0).timetuple()) - utc
70 there = calendar.timegm(local.timetuple()) + int(m.group(2)) / 1e6 - utc
71 return midnight, there - (before + after) / 2, after - before
72
73
74def zenith_clock(z):
75 """(zenith's clock minus ours, round trip)."""
76 before = time.time()
77 out = subprocess.run(z.SSH + ["date +%s.%N"], capture_output=True, text=True)
78 after = time.time()
79 try:
80 return float(out.stdout) - (before + after) / 2, after - before
81 except ValueError:
82 sys.exit("could not read zenith's clock: %r" % out.stdout.strip()[:120])
83
84
85def poll_locks(z, seconds, want):
86 """Lock transitions, stamped with our clock at the poll that first saw them.
87
88 BYTERANGE carries no timestamp of its own, so the sample interval is the
89 real resolution of these rows -- zenith's clock never enters the merge.
90 """
91 events, samples, prev, first = [], [], set(), True
92 end = time.time() + seconds
93 while True:
94 now = set(z.locks(z.status("BYTERANGE")[0]))
95 at = time.time()
96 samples.append(at)
97 for sign, changed in (("-", prev - now), ("=" if first else "+", now - prev)):
98 for share, name, _pid, kind, start, size in sorted(changed):
99 if want and want.lower() not in name.lower():
100 continue
101 events.append((at, "LOCK", sign + kind,
102 "%s/%s" % (os.path.basename(share), os.path.basename(name)),
103 start, size))
104 prev, first = now, False
105 if at >= end:
106 return events, samples
107
108
109def seconds_of_day(text):
110 m = TIME.match(text.strip())
111 if not m:
112 sys.exit("unparseable procmon timestamp %r" % text)
113 hour, half = int(m.group(1)), m.group(5)
114 if half:
115 hour = hour % 12 + (12 if half in "Pp" else 0)
116 return (hour * 3600 + int(m.group(2)) * 60 + int(m.group(3))
117 + float("0." + (m.group(4) or "0")))
118
119
120def detail_num(detail, key):
121 m = re.search(key + r":\s*([\d,]+)", detail)
122 return int(m.group(1).replace(",", "")) if m else None
123
124
125def io_events(path, midnight, skew, want, start_sod):
126 """Procmon rows for OneNote's accesses to .one files, on our clock."""
127 with open(path, newline="", encoding="utf-8-sig", errors="replace") as f:
128 rows = list(csv.DictReader(f))
129 if not rows:
130 return []
131 missing = {"Time of Day", "Process Name", "Operation", "Path", "Detail"} - set(rows[0])
132 if missing:
133 sys.exit("procmon csv is missing columns: %s" % ", ".join(sorted(missing)))
134 events = []
135 for r in rows:
136 target = r["Path"] or ""
137 if "ONENOTE" not in (r["Process Name"] or "").upper():
138 continue
139 if not (target.upper().startswith("A:") or ".one" in target.lower()):
140 continue
141 if want and want.lower() not in target.lower():
142 continue
143 detail = r["Detail"] or ""
144 sod = seconds_of_day(r["Time of Day"])
145 if sod + 43200 < start_sod:
146 sod += 86400 # Procmon logs a time of day with no date; the trace crossed midnight
147 events.append((midnight + sod - skew, "IO",
148 r["Operation"], ntpath.basename(target) or target,
149 detail_num(detail, "Offset"), detail_num(detail, "Length")))
150 return events
151
152
153def render(events):
154 for at, source, what, target, offset, size in sorted(events, key=lambda e: e[0]):
155 span = hexes = ""
156 if offset is not None and size is not None:
157 span, hexes = "%10d +%-8d" % (offset, size), "(0x%x +0x%x)" % (offset, size)
158 print((" %s %-4s %-26s %-24s %s %s" %
159 (datetime.datetime.fromtimestamp(at).strftime("%H:%M:%S.%f")[:-3],
160 source, what, target, span, hexes)).rstrip())
161
162
163def trace(seconds, want):
164 z = zenith()
165 procmon = procmon_path()
166 midnight, skew, win_slop = win_clock()
167 zenith_skew, zenith_slop = zenith_clock(z)
168 start_sod = time.time() + skew - midnight
169 cmd(r"if not exist C:\trace mkdir C:\trace")
170 cmd("del /q %s %s" % (PML, CSV))
171 win("spawn", '"%s" /AcceptEula /Quiet /Minimized /BackingFile %s'
172 % (procmon, PML))
173 if cmd('"%s" /WaitForIdle' % procmon)[0]:
174 sys.exit("procmon never started capturing on the Windows target")
175 events, samples = poll_locks(z, seconds, want)
176 cmd('"%s" /Terminate' % procmon)
177 if cmd('"%s" /OpenLog %s /SaveAs %s' % (procmon, PML, CSV))[0]:
178 sys.exit("procmon could not convert %s to csv" % PML)
179 if os.path.exists(LOCAL_CSV):
180 os.remove(LOCAL_CSV) # a stale csv here would merge as this run's trace
181 win("get", CSV, LOCAL_CSV)
182 if not os.path.exists(LOCAL_CSV) or not os.path.getsize(LOCAL_CSV):
183 sys.exit("no csv came back from wayback; the trace is lost")
184 io = io_events(LOCAL_CSV, midnight, skew, want, start_sod)
185
186 print("onenote-trace %gs %s %d lock transitions, %d procmon rows" %
187 (seconds, "file~%s" % want if want else "every .one and everything on A:",
188 len(events), len(io)))
189 print(" procmon times shifted %+.3fs onto this mac's clock (%s clock %+.3fs, "
190 "measured to +-%.3fs)" % (-skew, TARGET or "wayback", skew, win_slop / 2))
191 print(" lock times are mac-stamped at observation, %.2fs mean sample interval; "
192 "zenith's clock is %+.3fs (+-%.3fs) and does not enter the merge" %
193 ((samples[-1] - samples[0]) / max(len(samples) - 1, 1), zenith_skew, zenith_slop / 2))
194 render(events + io)
195
196
197def main():
198 global TARGET
199 ap = argparse.ArgumentParser(description=__doc__)
200 ap.add_argument("seconds", type=float)
201 ap.add_argument("--file", help="only rows whose path contains this")
202 ap.add_argument("--target", help="Windows MCP target name")
203 args = ap.parse_args()
204 TARGET = args.target or TARGET
205 try:
206 trace(args.seconds, args.file)
207 except KeyboardInterrupt:
208 pass
209
210
211if __name__ == "__main__":
212 main()