Coverage for src/local_deep_research/web/utils/request_timing.py: 100%

1"""Request-arrival/duration forensics for CI test runs (issue #4431). 

2 

3The UI test shards intermittently fail with 60-second navigation 

4timeouts, and the server logs go silent for the same window — but the 

5app only logs explicit events, so a silent window cannot distinguish 

6"the request never reached the server" (connection-level stall: listen 

7backlog, docker-proxy, browser socket pool starved by engine.io polls) 

8from "the request reached the app and hung" (app-level stall: lock, DB 

9pool, GIL hog). 

10 

11This middleware settles that by logging every request's arrival and its 

12WSGI-call duration. 

13 

14STATUS: NOT WIRED UP. On main this was installed by ``app_factory``'s 

15``create_app`` (wrapping ``app.wsgi_app``) only when CI or TESTING was 

16set. The FastAPI port deleted ``app_factory.py`` and never ported that 

17wiring, and ``RequestTimingMiddleware`` below is still a plain WSGI 

18callable (``__call__(environ, start_response)``), so it cannot be handed 

19to ``app.add_middleware`` as-is. Nothing in ``src/`` imports it; only 

20``tests/web/utils/test_request_timing.py`` exercises the class directly. 

21Re-arming the #4431 forensics needs an ASGI rewrite plus a conditional 

22registration in ``fastapi_app.py`` — a code change, not a doc fix. 

23 

24Log format (kept compact — engine.io polls arrive every ~5s/client): 

25 [req] > GET /chat/ 

26 [req] < GET /chat/ 0.04s 

27Slow completions get a WARNING with the duration, which the CI workflow 

28log-grep surfaces. 

29 

30Freeze thread-dump (dead-man's switch) 

31-------------------------------------- 

32The arrival log proves *that* the pipeline froze, but not *what* it was 

33stuck on. So this middleware also arms ``faulthandler.dump_traceback_later`` 

34and re-arms it on every request arrival. If no request arrives for 

35``FREEZE_DUMP_SECONDS`` (i.e. a freeze), faulthandler dumps ALL thread 

36stacks to stderr — and because it runs on a dedicated C timer thread it 

37fires even when the GIL is starved, which a Python watchdog thread could 

38not. During a ~60s freeze this yields 2-3 dumps showing exactly which 

39threads are blocked (werkzeug accept loop? a lock? a DB/SQLCipher call? 

40the scheduler?). Healthy operation re-arms the timer faster than it 

41fires, so no dumps appear. Captured in the CI server-log artifact. 

42""" 

43 

44import faulthandler 

45import sys 

46import time 

47 

48from loguru import logger 

49 

50# Above this, completion is logged as a warning — the interesting cases. 

51SLOW_REQUEST_SECONDS = 2.0 

52 

53# No request for this long ⇒ assume a freeze and dump all thread stacks. 

54# Smaller than the 60s navigation timeout so a freeze produces 2-3 dumps, 

55# larger than legitimate inter-test idle so healthy runs stay quiet-ish. 

56FREEZE_DUMP_SECONDS = 20.0 

57 

58 

59def _should_arm_freeze_dump(): 

60 """Arm the dead-man's switch only for the real, long-running server. 

61 

62 create_app() runs thousands of times under pytest (with CI=true), and 

63 arming a repeating faulthandler dump in each would spew stack traces 

64 across the whole pytest run. The freeze we care about only happens on 

65 the live UI-shard server, so skip arming when pytest is in the process. 

66 """ 

67 return "pytest" not in sys.modules 

68 

69 

70def _arm_freeze_dump(): 

71 if not _should_arm_freeze_dump(): 

72 return 

73 try: 

74 faulthandler.enable() 

75 faulthandler.dump_traceback_later( 

76 FREEZE_DUMP_SECONDS, repeat=True, file=sys.stderr 

77 ) 

78 except Exception as exc: # noqa: silent-exception 

79 # Diagnostics must never take the server down. 

80 logger.debug(f"freeze thread-dump arm failed: {exc}") 

81 

82 

83class RequestTimingMiddleware: 

84 """Outermost WSGI wrapper that logs request arrival and duration. 

85 

86 Duration covers the WSGI call (view execution), not response 

87 streaming — for stall forensics the arrival line is the signal that 

88 matters: its absence during a navigation timeout proves the request 

89 never reached the WSGI layer. 

90 """ 

91 

92 def __init__(self, wsgi_app): 

93 self.wsgi_app = wsgi_app 

94 # Arm the freeze thread-dump dead-man's switch (no-op under pytest). 

95 _arm_freeze_dump() 

96 

97 def __call__(self, environ, start_response): 

98 # Re-arm the dead-man's switch: as long as requests keep arriving 

99 # the dump never fires; a freeze (no arrivals) lets it fire and 

100 # capture the stuck thread stacks. 

101 _arm_freeze_dump() 

102 

103 method = environ.get("REQUEST_METHOD", "-") 

104 path = environ.get("PATH_INFO", "-") 

105 # engine.io transport/sid make poll churn correlatable. (sid is 

106 # logged on purpose for correlation; logs are CI-only artifacts.) 

107 if path.startswith("/socket.io"): 

108 query = environ.get("QUERY_STRING", "") 

109 path = f"{path}?{query}" if query else path 

110 # Strip CR/LF so a crafted PATH_INFO/QUERY_STRING can't inject fake 

111 # log lines (the forensics output is grep'd downstream). 

112 path = path.replace("\r", "\\r").replace("\n", "\\n") 

113 logger.info(f"[req] > {method} {path}") 

114 start = time.monotonic() 

115 try: 

116 return self.wsgi_app(environ, start_response) 

117 finally: 

118 elapsed = time.monotonic() - start 

119 if elapsed >= SLOW_REQUEST_SECONDS: 

120 logger.warning(f"[req] < {method} {path} {elapsed:.1f}s SLOW") 

121 else: 

122 logger.info(f"[req] < {method} {path} {elapsed:.2f}s")