Log node request processing so operators can see live activity in the console.

This commit is contained in:
Dobromir Popov
2026-07-07 18:12:57 +02:00
parent 1eb1e0baa2
commit aba5fb12fa
4 changed files with 65 additions and 6 deletions

View File

@@ -164,6 +164,9 @@ class RelayHttpBridge:
path = str(payload.get("path") or "/") path = str(payload.get("path") or "/")
headers = payload.get("headers") if isinstance(payload.get("headers"), dict) else {} headers = payload.get("headers") if isinstance(payload.get("headers"), dict) else {}
req_suffix = f" request_id={request_id}" if request_id else ""
print(f" [node] relay {method} {path}{req_suffix}", flush=True)
# body_base64 carries binary data (e.g. bfloat16 activation tensors) safely. # body_base64 carries binary data (e.g. bfloat16 activation tensors) safely.
# Fallback to text "body" for backward-compat with non-binary requests. # Fallback to text "body" for backward-compat with non-binary requests.
body_b64 = payload.get("body_base64") body_b64 = payload.get("body_base64")

View File

@@ -113,6 +113,10 @@ class _TorchHandler(http.server.BaseHTTPRequestHandler):
def log_message(self, fmt, *args): # noqa: suppress request logs in tests def log_message(self, fmt, *args): # noqa: suppress request logs in tests
pass pass
def _request_log_suffix(self) -> str:
req_id = self.headers.get("X-Meshnet-Request-Id") or self.headers.get("X-Request-Id")
return f" request_id={req_id}" if req_id else ""
def do_POST(self): def do_POST(self):
server: _TorchHTTPServer = self.server # type: ignore[assignment] server: _TorchHTTPServer = self.server # type: ignore[assignment]
if self.path == "/forward": if self.path == "/forward":
@@ -199,8 +203,18 @@ class _TorchHandler(http.server.BaseHTTPRequestHandler):
return return
server.forward_chunk_count += 1 server.forward_chunk_count += 1
if int(self.headers.get("X-Meshnet-Hop-Index", "0")) > 0: hop_index = int(self.headers.get("X-Meshnet-Hop-Index", "0"))
if hop_index > 0:
server.received_activations = True server.received_activations = True
if chunk_index_value == 0:
shard_start = getattr(server.backend, "shard_start", "?")
shard_end = getattr(server.backend, "shard_end", "?")
print(
f" [node] forward hop={hop_index} "
f"layers={shard_start}-{shard_end} "
f"session={session[:8]}{self._request_log_suffix()}",
flush=True,
)
start_layer_header = self.headers.get("X-Meshnet-Start-Layer") start_layer_header = self.headers.get("X-Meshnet-Start-Layer")
start_layer = int(start_layer_header) if start_layer_header else None start_layer = int(start_layer_header) if start_layer_header else None
@@ -311,20 +325,53 @@ class _TorchHandler(http.server.BaseHTTPRequestHandler):
temperature = float(body.get("temperature") or 1.0) temperature = float(body.get("temperature") or 1.0)
top_p = float(body.get("top_p") or 1.0) top_p = float(body.get("top_p") or 1.0)
print(
f" [node] processing chat model={model_name!r} stream={stream} "
f"max_tokens={max_tokens}{self._request_log_suffix()}",
flush=True,
)
# Fast path: this node owns the complete model — use HF generate() with KV cache. # Fast path: this node owns the complete model — use HF generate() with KV cache.
# Avoids the single-token-per-forward-pass limitation of the distributed path. # Avoids the single-token-per-forward-pass limitation of the distributed path.
if backend.is_head and backend.is_tail: if backend.is_head and backend.is_tail:
gen_started = time.monotonic()
try: try:
if stream: if stream:
self._stream_openai_response( token_count = 0
backend.generate_text_streaming(messages, max_tokens, temperature, top_p),
model_name, def _counting_stream():
nonlocal token_count
for token_text in backend.generate_text_streaming(
messages, max_tokens, temperature, top_p,
):
if token_text:
token_count += 1
yield token_text
self._stream_openai_response(_counting_stream(), model_name)
print(
f" [node] chat complete (stream) tokens={token_count} "
f"elapsed_s={time.monotonic() - gen_started:.1f}{self._request_log_suffix()}",
flush=True,
) )
else: else:
text = backend.generate_text(messages, max_tokens, temperature, top_p) text = backend.generate_text(messages, max_tokens, temperature, top_p)
completion_tokens = _backend_token_count(
backend, "count_text_tokens", text, fallback=len(text.split()) or 1,
)
print(
f" [node] chat complete tokens={completion_tokens} "
f"elapsed_s={time.monotonic() - gen_started:.1f}{self._request_log_suffix()}",
flush=True,
)
self._send_openai_response(text, model_name, False, messages, backend=backend) self._send_openai_response(text, model_name, False, messages, backend=backend)
except Exception as exc: except Exception as exc:
self._record_failed_request() self._record_failed_request()
print(
f" [node] chat failed after {time.monotonic() - gen_started:.1f}s: {exc}"
f"{self._request_log_suffix()}",
flush=True,
)
self._send_json(500, {"error": f"generation failed: {exc}"}) self._send_json(500, {"error": f"generation failed: {exc}"})
return return

View File

@@ -3035,6 +3035,7 @@ class _TrackerHandler(http.server.BaseHTTPRequestHandler):
headers={ headers={
"Content-Type": "application/json", "Content-Type": "application/json",
"X-Meshnet-Route": downstream_urls, "X-Meshnet-Route": downstream_urls,
"X-Meshnet-Request-Id": request_id,
}, },
method="POST", method="POST",
) )
@@ -3046,6 +3047,7 @@ class _TrackerHandler(http.server.BaseHTTPRequestHandler):
relay_headers = { relay_headers = {
"Content-Type": "application/json", "Content-Type": "application/json",
"X-Meshnet-Route": downstream_urls, "X-Meshnet-Route": downstream_urls,
"X-Meshnet-Request-Id": request_id,
**({"Authorization": auth} if auth else {}), **({"Authorization": auth} if auth else {}),
} }

View File

@@ -225,7 +225,7 @@ def test_tail_forward_returns_text_completion_from_binary_activations():
node.stop() node.stop()
def test_full_model_chat_completion_uses_generation_not_single_token_decode(): def test_full_model_chat_completion_uses_generation_not_single_token_decode(capsys):
node = TorchNodeServer(backend=_FakeFullBackend()) node = TorchNodeServer(backend=_FakeFullBackend())
port = node.start() port = node.start()
try: try:
@@ -237,7 +237,10 @@ def test_full_model_chat_completion_uses_generation_not_single_token_decode():
req = urllib.request.Request( req = urllib.request.Request(
f"http://127.0.0.1:{port}/v1/chat/completions", f"http://127.0.0.1:{port}/v1/chat/completions",
data=payload, data=payload,
headers={"Content-Type": "application/json"}, headers={
"Content-Type": "application/json",
"X-Meshnet-Request-Id": "req-test-123",
},
method="POST", method="POST",
) )
with urllib.request.urlopen(req, timeout=5) as resp: with urllib.request.urlopen(req, timeout=5) as resp:
@@ -248,6 +251,10 @@ def test_full_model_chat_completion_uses_generation_not_single_token_decode():
finally: finally:
node.stop() node.stop()
out = capsys.readouterr().out
assert " [node] processing chat model='fake-model' stream=False max_tokens=7 request_id=req-test-123" in out
assert " [node] chat complete tokens=1 elapsed_s=" in out
def test_pipeline_hop_logs_are_suppressed_without_debug(capsys): def test_pipeline_hop_logs_are_suppressed_without_debug(capsys):
tail_backend = _FakePipelineTailBackend() tail_backend = _FakePipelineTailBackend()