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 Flask 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. It is wired up by app_factory ONLY when CI or 

13TESTING is set, so production logging is unaffected. 

14 

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

16 [req] > GET /chat/ 

17 [req] < GET /chat/ 0.04s 

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

19log-grep surfaces. 

20 

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

22-------------------------------------- 

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

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

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

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

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

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

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

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

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

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

33""" 

34 

35import faulthandler 

36import sys 

37import time 

38 

39from loguru import logger 

40 

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

42SLOW_REQUEST_SECONDS = 2.0 

43 

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

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

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

47FREEZE_DUMP_SECONDS = 20.0 

48 

49 

50def _should_arm_freeze_dump(): 

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

52 

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

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

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

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

57 """ 

58 return "pytest" not in sys.modules 

59 

60 

61def _arm_freeze_dump(): 

62 if not _should_arm_freeze_dump(): 

63 return 

64 try: 

65 faulthandler.enable() 

66 faulthandler.dump_traceback_later( 

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

68 ) 

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

70 # Diagnostics must never take the server down. 

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

72 

73 

74class RequestTimingMiddleware: 

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

76 

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

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

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

80 never reached the WSGI layer. 

81 """ 

82 

83 def __init__(self, wsgi_app): 

84 self.wsgi_app = wsgi_app 

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

86 _arm_freeze_dump() 

87 

88 def __call__(self, environ, start_response): 

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

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

91 # capture the stuck thread stacks. 

92 _arm_freeze_dump() 

93 

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

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

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

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

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

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

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

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

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

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

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

105 start = time.monotonic() 

106 try: 

107 return self.wsgi_app(environ, start_response) 

108 finally: 

109 elapsed = time.monotonic() - start 

110 if elapsed >= SLOW_REQUEST_SECONDS: 

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

112 else: 

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