diff --git a/CHANGELOG.md b/CHANGELOG.md index 2ccecb6..af92329 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,26 @@ Hy Memory and MemHub are versioned and released independently. ## Unreleased +- MemHub turns off the HY pipeline log and trace at every diagnostic level + (hy-memory 2.0.8 `MEMORY_PIPELINE_LOG_ENABLED=false`, + `MEMORY_PIPELINE_TRACE_ENABLED=false`), so the per-step JSONL files under + `hy-memory/governed-v2/logs/` and the `pipeline_logs` rows stop growing. + The Debug panel no longer shows the HY pipeline section. Existing files are + left in place. +- HY SDK text logs are written once, to `hy_memory.log`. They are no longer + copied to `service.log` and `service-error.log` through the SDK's + stdout/stderr streams. SDK warnings and errors also go to `core.log`, so the + Debug panel still shows them. A live switch of the diagnostic level now also + changes the level of `hy_memory.log`. + +- MemHub shows when working and coding experiences were talked about. After + the SDK upgrade every one of them read "时间未知" (time unknown) because the + SDK never stored their conversation time; hy-memory 2.0.7 stores it and + Core now passes it through the memory list, detail, search and home + summary. An experience stored before 2.0.7 shows its write time, labelled + "写入于" / "写入时间", instead of "时间未知". Metadata repair also writes + the conversation time it recovers from the migration bundle into the SDK's + coding/working stores when they already have the column. - The SDK migration no longer fails its first run on a home with legacy vectors: reattaching them left a Chroma instance open with its own settings, and the readback that followed could not open the same store @@ -68,6 +88,44 @@ Hy Memory and MemHub are versioned and released independently. `hy_node_permissions` proof table. Evidence, governed memories, model profiles, SDK stores, and source/host grants are preserved. +## Hy Memory 2.0.8 — 2026-10-28 + +- Published + [`hy-memory==2.0.8`](https://pypi.org/project/hy-memory/2.0.8/). +- New `MEMORY_PIPELINE_LOG_ENABLED` (default `true`) turns the pipeline JSONL + log (`{MEMORY_LOG_DIR}//.log`) off. With `false` no JSONL + file or directory is written. When `MEMORY_PIPELINE_TRACE_ENABLED` is also + `false`, `store_pipeline_log` becomes a no-op that returns `True` at once: + no timing, redaction, background task or database write. The init log line + now states whether the JSONL log is on or off. +- Conversation and memory text no longer appears in INFO or WARNING logs. The + `[add]` input, search queries and rewrites, coding experience tasks, fact + statements and subjects, reconcile op details, extracted info, embedding + inputs and unparsable model output moved to DEBUG. INFO lines keep ids, + counts and character lengths; parse-failure warnings remain but report only + the length of the output, e.g. `failed to parse output (812 chars)`. The + `[embed]` INFO line now carries `request.input_chars` instead of + `request.input`. The `JSON_PARSE_FAILED` error message from extraction no + longer embeds the model output either. + +## Hy Memory 2.0.7 — 2026-10-28 + +- Published + [`hy-memory==2.0.7`](https://pypi.org/project/hy-memory/2.0.7/). +- Coding and working experiences and facts now keep their conversation time. + `add(..., memory_at=...)` reached only the chat path before; the + productivity path dropped it, so every experience had only its write time + and MemHub showed them as "时间未知" (time unknown). `coding_memory_meta` + and `working_fact` gain a nullable `memory_at` column (epoch seconds) in + both the working and coding stores; existing databases get it on open, and + their old rows stay `None`. Without `memory_at` a write uses the time the + request arrived, as chat does. When an experience is updated by a later + conversation it keeps the later of the two times. +- `list_memories` (`scene="coding"`, `"working"` and `"all"`), `get` and + `search` return `memory_at` for experiences and facts in the same field and + format as chat (epoch seconds, `None` when unknown). Experience search + results now also carry `created_at`. + ## Hy Memory 2.0.6 — 2026-10-27 - Published diff --git a/docs/env_reference.md b/docs/env_reference.md index f26caf9..7bd3841 100644 --- a/docs/env_reference.md +++ b/docs/env_reference.md @@ -191,6 +191,7 @@ SDK 不设置 Rerank Search 并发上限。开启后模型在 `HyMemoryClient` | `MEMORY_LOG_FORMAT` | `text` | `text` / `json` | | `MEMORY_LOG_DIR` | — | 统一日志根目录 | | `MEMORY_TRACE_LOG_DIR` | — | JSONL 日志目录的兼容旧名;优先使用 `MEMORY_LOG_DIR` | +| `MEMORY_PIPELINE_LOG_ENABLED` | `true` | 是否写 pipeline JSONL 日志(`{MEMORY_LOG_DIR}//.log`);`false` 完全不写 | | `MEMORY_PIPELINE_TRACE_ENABLED` | `true` | 是否写入 cache 的 pipeline trace 表 | | `MEMORY_MEMORY_OPERATIONS_ENABLED` | `false` | 是否写入 memory operation 审计记录 | | `MEMORY_HISTORY_ENABLE` | `true` | 是否启用历史记录 | diff --git a/hy_memory/agent/extractor.py b/hy_memory/agent/extractor.py index 8861600..5a81f44 100644 --- a/hy_memory/agent/extractor.py +++ b/hy_memory/agent/extractor.py @@ -1177,7 +1177,7 @@ class Extractor: if not tc_id: logger.error( f"[extractor] tool_call_id is empty! " - f"raw tc: {json.dumps(tc_raw, ensure_ascii=False, default=str)[:500]}" + f"raw_keys={list(tc_raw.keys())}" ) try: t_res = await tool_registry.dispatch( @@ -1311,11 +1311,12 @@ class Extractor: if parsed is None: if not all_tool_calls: logger.warning( - f"[extractor] JSON parse failed: {raw_text[:200]}" + f"[extractor] JSON parse failed ({len(raw_text)} chars)" ) + logger.debug(f"[extractor] unparsable output: {raw_text[:200]!r}") return ExtractResult( success=False, - error=f"JSON parse failed: {raw_text[:200]}", + error=f"JSON parse failed ({len(raw_text)} chars)", error_code="JSON_PARSE_FAILED", raw_response=raw_text, tokens_used=total_tokens, diff --git a/hy_memory/agent/llm_provider.py b/hy_memory/agent/llm_provider.py index 52a70b8..289f1ea 100644 --- a/hy_memory/agent/llm_provider.py +++ b/hy_memory/agent/llm_provider.py @@ -129,8 +129,7 @@ def _parse_tool_calls_list(raw_calls: list, _json) -> List[Dict[str, Any]]: tc_id = tc.get("id") or "" if not tc_id: logger.error( - f"[llm] tool_call missing 'id'! raw: " - f"{_json.dumps(tc, ensure_ascii=False, default=str)[:500]}" + f"[llm] tool_call missing 'id'! keys={list(tc.keys())}" ) # 保留原始 tc 完整结构,只规范化 arguments diff --git a/hy_memory/agent/mem_agent.py b/hy_memory/agent/mem_agent.py index 7c8db7b..e9ecb60 100644 --- a/hy_memory/agent/mem_agent.py +++ b/hy_memory/agent/mem_agent.py @@ -234,7 +234,7 @@ class MemAgent: f"identity={len(identity)} facts={len(facts)} " f"basic_info={basic_field_count}fields" ) - logger.info(f"MemAgent: extracted_info={extract_result.info}") + logger.debug(f"MemAgent: extracted_info={extract_result.info}") # 3. 冲突检测(如果有已有记忆) if mode == ProcessMode.FULL and existing_memories: diff --git a/hy_memory/agent/reconciler.py b/hy_memory/agent/reconciler.py index ce676ba..6c67cf0 100644 --- a/hy_memory/agent/reconciler.py +++ b/hy_memory/agent/reconciler.py @@ -50,7 +50,7 @@ def is_canonical_state_node(node: Any) -> bool: def _log_ops_detail(ops: List["ReconcileOp"]) -> None: - """以单条 INFO(JSON list)输出 reconcile 的逐条结果,便于线上 debug。""" + """以单条 DEBUG(JSON list)输出 reconcile 的逐条结果;含记忆正文,不进 INFO。""" if not ops: return view = [ @@ -68,7 +68,7 @@ def _log_ops_detail(ops: List["ReconcileOp"]) -> None: } for o in ops ] - logger.info( + logger.debug( f"[reconciler] ops detail: {json.dumps(view, ensure_ascii=False, default=str)}" ) @@ -1514,9 +1514,10 @@ class MemoryReconciler: logger.warning( f"[reconciler] RECONCILE JSON parse failed " f"(attempt {_attempt+1}/{_MAX_PARSE_ATTEMPTS}), " - f"retrying: raw=" - f"{raw_response[:200] if _log_llm_content_enabled() else ''}" + f"retrying: raw({len(raw_response or '')} chars)" ) + if _log_llm_content_enabled(): + logger.debug(f"[reconciler] unparsable raw={raw_response[:200]!r}") recon_elapsed = (_time.perf_counter() - t_recon) * 1000 @@ -1528,8 +1529,8 @@ class MemoryReconciler: error_code = "LLM_UNAVAILABLE" elif raw_response.strip(): error_msg = ( - f"RECONCILE JSON parse failed after {_n_attempts} attempts: " - f"{raw_response[:200] if _log_llm_content_enabled() else ''}" + f"RECONCILE JSON parse failed after {_n_attempts} attempts " + f"({len(raw_response)} chars)" ) error_code = "JSON_PARSE_FAILED" else: @@ -1806,7 +1807,8 @@ class MemoryReconciler: except Exception as _re: logger.debug(f"[reconciler] json_repair failed: {_re}") if data is None: - logger.warning(f"[reconciler] failed to parse ops JSON: {text[:200]}") + logger.warning(f"[reconciler] failed to parse ops JSON ({len(text)} chars)") + logger.debug(f"[reconciler] unparsable ops output: {text[:200]!r}") return [] if not isinstance(data, list): @@ -2018,11 +2020,11 @@ class MemoryReconciler: if clash is not None: logger.warning( f"[reconciler] memory_id {clash} already touched by '{touched[clash]}', " - f"current op '{op.op} ({op.reason[:60]})' dropped" + f"current op '{op.op}' dropped" ) continue for t in target_ids: - touched[t] = f"{op.op}({op.reason[:40]})" + touched[t] = op.op validated.append(op) return validated diff --git a/hy_memory/agent/tools/base.py b/hy_memory/agent/tools/base.py index 667bfc6..bf457b3 100644 --- a/hy_memory/agent/tools/base.py +++ b/hy_memory/agent/tools/base.py @@ -211,7 +211,9 @@ def parse_tool_calls_from_json(raw: Any) -> List[ToolCall]: try: args = json.loads(args_raw) if args_raw.strip() else {} except json.JSONDecodeError: - logger.warning(f"[tools] failed to parse arguments as JSON: {args_raw[:120]}") + logger.warning( + f"[tools] failed to parse arguments as JSON ({len(args_raw)} chars)" + ) args = {} elif isinstance(args_raw, dict): args = args_raw diff --git a/hy_memory/client.py b/hy_memory/client.py index dd37ed3..8473917 100644 --- a/hy_memory/client.py +++ b/hy_memory/client.py @@ -744,7 +744,7 @@ class HyMemoryClient: def _install_pipeline_observability_hooks(self) -> None: """ 包装 cache.store_pipeline_log: - - Log:JSONL 文件,始终写入(环节级,不依赖 Trace 开关) + - Log:JSONL 文件,由 MEMORY_PIPELINE_LOG_ENABLED 控制(默认开启) - Trace:SQLite pipeline_logs,由 MEMORY_PIPELINE_TRACE_ENABLED 控制(Inspector) - 落盘 fire-and-forget,不阻塞 search/write 热路径 """ @@ -958,7 +958,7 @@ class HyMemoryClient: parsed_tool_calls = json.loads(raw_tool_calls) if raw_tool_calls else [] except Exception: logger.warning( - "tool_calls 是非法 JSON 字符串,已忽略: %r", raw_tool_calls[:200] + "tool_calls 是非法 JSON 字符串,已忽略 (%d chars)", len(raw_tool_calls) ) parsed_tool_calls = [] raw_tool_calls = parsed_tool_calls if isinstance(parsed_tool_calls, list) else [] @@ -1544,6 +1544,7 @@ class HyMemoryClient: # LLM 写的"这个结论一路怎么改成现在这样",直接进提示词; # 没被覆盖过就是空串。不参与检索——召回认的是 statement 的当前值。 "fact_chain_summary": fact.fact_chain_summary, + "memory_at": _epoch_seconds(fact.memory_at), "created_at": fact.created_at.isoformat() if fact.created_at else None, "score": round(float(score), 4), "source": fact.source, @@ -1652,6 +1653,8 @@ class HyMemoryClient: "score": (round(float(score_by_id[d.experience_id]), 4) if d.experience_id in score_by_id else None), "confidence": d.confidence, + "memory_at": _epoch_seconds(d.memory_at), + "created_at": d.created_at.isoformat() if d.created_at else None, "updated_at": d.updated_at.isoformat() if d.updated_at else None, "source": d.source, "extraction_source": d.extraction_source, @@ -1953,6 +1956,7 @@ class HyMemoryClient: "content" chat 正文;经验为 "task\nsolution";事实为 statement "score" RRF 融合分;"lane_score" 为该路原始分;"lane_rank" 为该路名次 "source", "created_at", "updated_at"(秒级 epoch,取不到为 None) + "memory_at" 对话时间(秒级 epoch),各路原有字段,三路同名同格式 chat 路内部名次:normal → schema → proactive 依次排;working/coding 路 内部名次:事实与经验各按原顺序交替(事实在前),两层谁也不压谁。 """ @@ -2144,7 +2148,8 @@ class HyMemoryClient: "limit", "offset", "request_id", "elapsed_ms"} 每条带 "scene"、"kind"(chat | experience)、"memory_id"、"content" (经验为 "task\nsolution")、"source"、"status"、"created_at"、 - "updated_at"(秒级 epoch),以及该路原有字段。 + "updated_at"(秒级 epoch),以及该路原有字段(含对话时间 + "memory_at",秒级 epoch,三路同名同格式)。 """ return self._loop_thread.run( self.async_list_memories( @@ -2967,6 +2972,7 @@ class HyMemoryClient: session_id=session_id, request_id=request_id, source=source, + memory_at=memory_at, ) # Public receipt always identifies the productivity namespace. resp["variant"] = scene_variant @@ -3002,13 +3008,13 @@ class HyMemoryClient: f"[add] writing {preview} user={uid} " f"agent_id={agent_id} session_id={session_id} mode={self._mode}" ) - logger.info(f"[add] messages detail: {[m.to_dict() for m in chat_messages]}") + logger.debug(f"[add] messages detail: {[m.to_dict() for m in chat_messages]}") else: logger.info( f"[add] writing text({len(content)} chars) user={uid} " - f"agent_id={agent_id} session_id={session_id} mode={self._mode} " - f"content={content}" + f"agent_id={agent_id} session_id={session_id} mode={self._mode}" ) + logger.debug(f"[add] text content={content!r}") # mode → agent_mode 映射 # lite: 不调 LLM agent @@ -4028,14 +4034,14 @@ class HyMemoryClient: decided_variant = HyMemoryClient._scene_variant(scene) logger.info( f"[search] scene explicit={decided_scene} (no LLM judge); " - f"target={effective_target_query!r}" + f"target({len(effective_target_query or '')} chars)" ) elif not agentic_enabled and not queries_supplied: # 默认 light search 仅指 query="...":固定 normal,绝不调用 LLM。 decided_scene = "normal" logger.info( f"[search] search_mode=default single-query scene=normal (no LLM); " - f"target={target_query!r}" + f"target({len(target_query or '')} chars)" ) elif agentic_enabled: # agentic:单/多 query 都强制一次 LLM 完成三分类 + rewrite + 时间解析。 @@ -4070,14 +4076,18 @@ class HyMemoryClient: rewrite_created_after = ar.get("created_after") logger.info( f"[search] agentic scene={decided_scene} via rewrite-LLM " - f"(classify={want_classify}); orig={target_query!r} " - f"effective={effective_target_query!r} rewrite_used={rewrite_used} " + f"(classify={want_classify}); rewrite_used={rewrite_used} " f"created_after={rewrite_created_after}" ) + logger.debug( + f"[search] agentic rewrite: orig={target_query!r} " + f"effective={effective_target_query!r}" + ) else: decided_scene = "normal" logger.info( - f"[search] agentic rewrite-LLM fallback=normal; target={target_query!r}" + f"[search] agentic rewrite-LLM fallback=normal; " + f"target({len(target_query or '')} chars)" ) elif rewrite_enabled and not _too_long: # default + queries= 的原逻辑:配置开启时一次 LLM 做 rewrite/time, @@ -4156,7 +4166,7 @@ class HyMemoryClient: decided_scene = "normal" logger.info( f"[search] default multi-query features disabled; no LLM; " - f"target={target_query!r}" + f"target({len(target_query or '')} chars)" ) # ──────────────────────────────────────────────────────────── @@ -4209,7 +4219,7 @@ class HyMemoryClient: else: logger.info( f"[search] routing to PRODUCTIVITY path variant={decided_variant}: " - f"target={effective_target_query!r} " + f"target({len(effective_target_query or '')} chars) " f"workspace_id={workspace_id!r} branch={branch!r}" ) return await self._search_coding( @@ -4237,9 +4247,11 @@ class HyMemoryClient: # Chat 召回链路(原有逻辑) # ──────────────────────────────────────────────────────────── logger.info( - f"[search] query='{effective_target_query}' user_ids={effective_user_ids} " + f"[search] query({len(effective_target_query or '')} chars) " + f"user_ids={effective_user_ids} " f"agent_ids={effective_agent_ids} session_ids={effective_session_ids} limit={limit}" ) + logger.debug(f"[search] query={effective_target_query!r}") # rewrite 抽出的时间下界与用户显式 created_after 取更晚者(更严格) effective_created_after = created_after @@ -5920,6 +5932,7 @@ class HyMemoryClient: "source_fact_ids": list(d.source_fact_ids), "confidence": d.confidence, "status": MemoryStatus.ACTIVE.value, + "memory_at": _epoch_seconds(d.memory_at), "created_at": d.created_at.isoformat() if d.created_at else None, "updated_at": d.updated_at.isoformat() if d.updated_at else None, "source": d.source, diff --git a/hy_memory/coding/extractor.py b/hy_memory/coding/extractor.py index 1d65cff..82afde6 100644 --- a/hy_memory/coding/extractor.py +++ b/hy_memory/coding/extractor.py @@ -1166,7 +1166,10 @@ class CodingMemoryExtractor: obj = None if not isinstance(obj, dict): - logger.warning(f"[coding-extract] failed to parse output: {text!r}") + logger.warning( + f"[coding-extract] failed to parse output ({len(text or '')} chars)" + ) + logger.debug(f"[coding-extract] unparsable output: {text!r}") return [], [] # "memories" 是双层化之前的 key,老 prompt 缓存 / 旧模型可能还这么回 diff --git a/hy_memory/coding/fact_reconciler.py b/hy_memory/coding/fact_reconciler.py index 91da943..9cc946e 100644 --- a/hy_memory/coding/fact_reconciler.py +++ b/hy_memory/coding/fact_reconciler.py @@ -454,9 +454,10 @@ class WorkingFactReconciler: workspace_id: Optional[str] = None, branch: Optional[str] = None, source: str = "default", + memory_at: Optional[datetime] = None, ) -> Tuple[List[WorkingFact], List[FactReconcileOp]]: """ - 执行 reconcile + 持久化。 + 执行 reconcile + 持久化。memory_at 是这段对话的时间,记到新事实上。 Returns: (真正落库的新事实, 执行过的 ops)。LLM 挂掉时退化为全 INSERT 不覆盖, @@ -493,6 +494,7 @@ class WorkingFactReconciler: workspace_id=workspace_id, branch=branch, source=source, + memory_at=memory_at, ) logger.info( f"[fact-reconcile] drafts={len(drafts)} inserted={len(facts)} " @@ -568,9 +570,12 @@ class WorkingFactReconciler: kept.append(fact) if blocked: logger.info( - f"[fact-reconcile] subject gate blocked {len(blocked)} candidate(s) " - f"for subject={draft.subject!r}: " - + ", ".join(f"{f.fact_id}({f.subject!r})" for f in blocked) + f"[fact-reconcile] subject gate blocked {len(blocked)} candidate(s): " + + ", ".join(f.fact_id for f in blocked) + ) + logger.debug( + f"[fact-reconcile] subject gate: draft subject={draft.subject!r} " + f"blocked subjects={[f.subject for f in blocked]!r}" ) result.append(kept) return result @@ -743,7 +748,10 @@ class WorkingFactReconciler: obj = None if not isinstance(obj, dict): - logger.warning(f"[fact-reconcile] failed to parse ops output: {text!r}") + logger.warning( + f"[fact-reconcile] failed to parse ops output ({len(text or '')} chars)" + ) + logger.debug(f"[fact-reconcile] unparsable ops output: {text!r}") return {} ops_raw = obj.get("ops") if not isinstance(ops_raw, list): @@ -781,6 +789,7 @@ class WorkingFactReconciler: workspace_id: Optional[str], branch: Optional[str] = None, source: str = "default", + memory_at: Optional[datetime] = None, ) -> Tuple[List[WorkingFact], List[FactReconcileOp]]: inserted: List[WorkingFact] = [] ops: List[FactReconcileOp] = [] @@ -801,6 +810,7 @@ class WorkingFactReconciler: subject=draft.subject, details=draft.details, status="active", + memory_at=memory_at, ) allowed = {c.fact_id for c in (candidates[idx] if idx < len(candidates) else [])} @@ -831,8 +841,11 @@ class WorkingFactReconciler: # 别的主体的状态不是。闸门关掉时这道复查一并跳过,否则闸门就没关干净。 if self.subject_gate and _subject_conflict(draft.subject, old.subject): logger.warning( - f"[fact-reconcile] refused cross-subject SUPERSEDE: " - f"{old.fact_id}({old.subject!r}) by draft subject {draft.subject!r}" + f"[fact-reconcile] refused cross-subject SUPERSEDE: {old.fact_id}" + ) + logger.debug( + f"[fact-reconcile] cross-subject: old subject={old.subject!r} " + f"draft subject={draft.subject!r}" ) continue try: diff --git a/hy_memory/coding/judge.py b/hy_memory/coding/judge.py index bfa28c1..d005174 100644 --- a/hy_memory/coding/judge.py +++ b/hy_memory/coding/judge.py @@ -195,8 +195,10 @@ async def classify_messages_scene( result = _parse_scene_json(resp.content) if result is None: logger.warning( - f"[coding-judge] failed to parse classify_messages output: {resp.content!r}; defaulting to chat" + f"[coding-judge] failed to parse classify_messages output " + f"({len(resp.content or '')} chars); defaulting to chat" ) + logger.debug(f"[coding-judge] unparsable classify_messages output: {resp.content!r}") await _store_coding_log( cache, request_id=request_id, user_id=user_id, agent_id=agent_id, session_id=session_id, step="CODING_JUDGE", prompt=prompt, @@ -207,9 +209,8 @@ async def classify_messages_scene( return "chat" scene = result["scene"] parsed = {**result, "is_coding": scene != "chat"} - logger.info( - f"[coding-judge] scene={scene} reason={result.get('reason', '')!r}" - ) + logger.info(f"[coding-judge] scene={scene}") + logger.debug(f"[coding-judge] scene={scene} reason={result.get('reason', '')!r}") await _store_coding_log( cache, request_id=request_id, user_id=user_id, agent_id=agent_id, session_id=session_id, step="CODING_JUDGE", prompt=prompt, @@ -295,8 +296,10 @@ async def classify_queries_scene( result = _parse_scene_json(resp.content) if result is None: logger.warning( - f"[coding-judge] failed to parse classify_queries output: {resp.content!r}; defaulting to chat" + f"[coding-judge] failed to parse classify_queries output " + f"({len(resp.content or '')} chars); defaulting to chat" ) + logger.debug(f"[coding-judge] unparsable classify_queries output: {resp.content!r}") return "chat" scene = result["scene"] logger.info(f"[coding-judge] queries scene={scene}") @@ -422,15 +425,18 @@ async def classify_and_rewrite_queries( scene = _parse_scene_label(head) if scene is None: logger.warning( - f"[coding-judge] classify_and_rewrite unrecognized head={head!r}; falling back to chat" + f"[coding-judge] classify_and_rewrite unrecognized head " + f"({len(head)} chars); falling back to chat" ) + logger.debug(f"[coding-judge] classify_and_rewrite unrecognized head={head!r}") return {"scene": "chat", "is_coding": False, "rewrite_query": rewrite, "ok": False} is_coding = scene != "chat" logger.info( f"[coding-judge] classify_and_rewrite scene={scene} " - f"rewrite={rewrite!r}" + f"rewrite({len(rewrite)} chars)" ) + logger.debug(f"[coding-judge] classify_and_rewrite rewrite={rewrite!r}") return {"scene": scene, "is_coding": is_coding, "rewrite_query": rewrite, "ok": True} @@ -569,8 +575,9 @@ async def analyze_queries( parsed_scene = _parse_scene_label(head) if parsed_scene is None: logger.warning( - f"[coding-judge] analyze_queries unrecognized head={head!r}; ok=False" + f"[coding-judge] analyze_queries unrecognized head ({len(head)} chars); ok=False" ) + logger.debug(f"[coding-judge] analyze_queries unrecognized head={head!r}") return {**fallback, "since_raw": ""} scene = parsed_scene idx = 1 @@ -589,9 +596,10 @@ async def analyze_queries( created_after = _since_to_created_after(since_raw, current_time) logger.info( - f"[coding-judge] analyze scene={scene} rewrite={rewrite!r} " + f"[coding-judge] analyze scene={scene} rewrite({len(rewrite)} chars) " f"since={since_raw!r} created_after={created_after}" ) + logger.debug(f"[coding-judge] analyze rewrite={rewrite!r}") return { "scene": scene, "is_coding": scene != "chat", "rewrite_query": rewrite, "created_after": created_after, "since_raw": since_raw, "ok": True, @@ -614,7 +622,10 @@ def _since_to_created_after(since_raw: str, current_time: str) -> Optional[float return dt.timestamp() except (ValueError, TypeError): continue - logger.warning(f"[coding-judge] analyze_queries unparsable SINCE={since_raw!r}") + logger.warning( + f"[coding-judge] analyze_queries unparsable SINCE ({len(since_raw)} chars)" + ) + logger.debug(f"[coding-judge] analyze_queries unparsable SINCE={since_raw!r}") return None diff --git a/hy_memory/coding/reconciler.py b/hy_memory/coding/reconciler.py index ed36dd6..7cfff82 100644 --- a/hy_memory/coding/reconciler.py +++ b/hy_memory/coding/reconciler.py @@ -388,7 +388,10 @@ class CodingMemoryReconciler: obj = None if not obj or not isinstance(obj, dict): - logger.warning(f"[coding-reconcile] failed to parse ops output: {text!r}") + logger.warning( + f"[coding-reconcile] failed to parse ops output ({len(text or '')} chars)" + ) + logger.debug(f"[coding-reconcile] unparsable ops output: {text!r}") return [] ops_raw = obj.get("ops") or [] if not isinstance(ops_raw, list): @@ -441,10 +444,10 @@ class CodingMemoryReconciler: for op in ops: if op.action == "ADD": if op.draft_idx is None or not (0 <= op.draft_idx < len(drafts)): - logger.warning(f"[coding-reconcile] drop invalid ADD: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop invalid ADD: {_op_ref(op)}") continue if op.draft_idx in consumed: - logger.warning(f"[coding-reconcile] drop ADD on consumed draft: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop ADD on consumed draft: {_op_ref(op)}") continue d = drafts[op.draft_idx] memory = self._draft_to_new_memory(d) @@ -458,18 +461,18 @@ class CodingMemoryReconciler: elif op.action == "UPDATE": if op.draft_idx is None or not (0 <= op.draft_idx < len(drafts)): - logger.warning(f"[coding-reconcile] drop invalid UPDATE: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop invalid UPDATE: {_op_ref(op)}") continue if not op.target_experience_id: - logger.warning(f"[coding-reconcile] drop UPDATE missing target: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop UPDATE missing target: {_op_ref(op)}") continue if not self._target_was_offered(op, candidates_per_draft): logger.warning( - f"[coding-reconcile] drop UPDATE outside authority scope: {op.to_dict()}" + f"[coding-reconcile] drop UPDATE outside authority scope: {_op_ref(op)}" ) continue if op.draft_idx in consumed: - logger.warning(f"[coding-reconcile] drop UPDATE on consumed draft: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop UPDATE on consumed draft: {_op_ref(op)}") continue d = drafts[op.draft_idx] memory = self._draft_to_new_memory(d, experience_id=op.target_experience_id) @@ -488,17 +491,17 @@ class CodingMemoryReconciler: elif op.action == "DELETE": if not op.target_experience_id: - logger.warning(f"[coding-reconcile] drop DELETE missing target: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop DELETE missing target: {_op_ref(op)}") continue if not self._target_was_offered(op, candidates_per_draft): logger.warning( - f"[coding-reconcile] drop DELETE outside authority scope: {op.to_dict()}" + f"[coding-reconcile] drop DELETE outside authority scope: {_op_ref(op)}" ) continue # DELETE 需要知道 user_id;通过 draft_idx(如有)或第一个 draft 推断 user_id = self._infer_user_id(op, drafts) if not user_id: - logger.warning(f"[coding-reconcile] drop DELETE no user_id context: {op.to_dict()}") + logger.warning(f"[coding-reconcile] drop DELETE no user_id context: {_op_ref(op)}") continue try: ok = await self.store.delete(op.target_experience_id, user_id=user_id) @@ -577,6 +580,7 @@ class CodingMemoryReconciler: confidence=d.confidence, source=d.source, extraction_source=d.extraction_source, + memory_at=d.memory_at, ) @@ -584,6 +588,14 @@ class CodingMemoryReconciler: # Helpers # ================================================================ +def _op_ref(op: ReconcileOp) -> str: + """op 的日志引用:只带动作与编号,不带 LLM 写的 reason。""" + return ( + f"action={op.action} draft_idx={op.draft_idx} " + f"target={op.target_experience_id}" + ) + + def _truncate(s: str, n: int) -> str: if not s: return "" diff --git a/hy_memory/coding/store.py b/hy_memory/coding/store.py index 5503934..0effea1 100644 --- a/hy_memory/coding/store.py +++ b/hy_memory/coding/store.py @@ -86,6 +86,7 @@ CREATE TABLE IF NOT EXISTS coding_memory_meta ( confidence REAL NOT NULL DEFAULT 0.7, source TEXT NOT NULL DEFAULT 'default', extraction_source TEXT NOT NULL DEFAULT 'auto_extract', + memory_at INTEGER, created_at TEXT NOT NULL, updated_at TEXT NOT NULL ); @@ -109,6 +110,7 @@ CREATE TABLE IF NOT EXISTS working_fact ( derived_experience_ids TEXT NOT NULL DEFAULT '[]', status TEXT NOT NULL DEFAULT 'active', fact_chain_summary TEXT NOT NULL DEFAULT '', + memory_at INTEGER, created_at TEXT NOT NULL ); -- 反查前驱(谁的 fact_link 指向我)走这个索引,写演变总结时要顺着链往回走 @@ -164,6 +166,8 @@ _ADDED_COLUMNS = { "coding_memory_meta": { "source_fact_ids": "TEXT NOT NULL DEFAULT '[]'", "extraction_source": "TEXT NOT NULL DEFAULT 'auto_extract'", + # 对话时间,秒级 epoch(同 chat)。老库里的行是 NULL:那时没存过。 + "memory_at": "INTEGER", }, # 早期版本存过一列 fact_chain(机械累积的历代说法),已废弃:同样的信息顺着 # fact_link 反查就有。老库里那一列留着不管,有默认值不影响插入。 @@ -177,6 +181,7 @@ _ADDED_COLUMNS = { "subject": "TEXT NOT NULL DEFAULT ''", "details": "TEXT NOT NULL DEFAULT ''", "source": "TEXT NOT NULL DEFAULT 'default'", + "memory_at": "INTEGER", }, } @@ -290,6 +295,29 @@ def _parse_dt(s: Optional[str]) -> Optional[datetime]: return None +def _from_epoch(value: Any) -> Optional[datetime]: + """memory_at 列(秒级 epoch)→ datetime;NULL 或坏值返回 None。""" + if value is None: + return None + try: + return datetime.fromtimestamp(int(value)) + except Exception: + return None + + +def _to_epoch(value: Optional[datetime]) -> Optional[int]: + return int(value.timestamp()) if isinstance(value, datetime) else None + + +def _later(a: Optional[datetime], b: Optional[datetime]) -> Optional[datetime]: + """两个对话时间取较晚的;一边缺就取另一边。""" + if a is None: + return b + if b is None: + return a + return a if _to_epoch(a) >= _to_epoch(b) else b + + def _row_to_memory(row: sqlite3.Row) -> CodingMemory: """SQLite row → CodingMemory""" return CodingMemory( @@ -308,6 +336,7 @@ def _row_to_memory(row: sqlite3.Row) -> CodingMemory: confidence=row["confidence"], source=row["source"], extraction_source=row["extraction_source"], + memory_at=_from_epoch(row["memory_at"]), created_at=_parse_dt(row["created_at"]), updated_at=_parse_dt(row["updated_at"]), ) @@ -334,6 +363,7 @@ def _row_to_fact(row: sqlite3.Row) -> WorkingFact: # 老库刚 ADD COLUMN 时可能取不到这一列,用 keys() 兜一下 fact_chain_summary=(row["fact_chain_summary"] or "" if "fact_chain_summary" in row.keys() else ""), + memory_at=_from_epoch(row["memory_at"]), created_at=_parse_dt(row["created_at"]), ) @@ -575,7 +605,11 @@ class CodingMemoryStore: await self._upsert_vec_keys(memory) logger.info( f"[coding-store] inserted experience_id={memory.experience_id} " - f"task={memory.task!r} keys={1 + len(memory.search_keys)}" + f"keys={1 + len(memory.search_keys)}" + ) + logger.debug( + f"[coding-store] inserted experience_id={memory.experience_id} " + f"task={memory.task!r}" ) async def update(self, memory: CodingMemory) -> None: @@ -597,6 +631,8 @@ class CodingMemoryStore: memory.updated_at = datetime.utcnow() if memory.created_at is None: memory.created_at = prev.created_at + # 合并后的经验讲的是两段对话,对话时间取较晚的那段 + memory.memory_at = _later(prev.memory_at, memory.memory_at) await _run_in_pool(self._upsert_sql_sync, memory) # 删旧 VDB await self._delete_vec_keys_by_count(memory.experience_id, prev_key_count) @@ -970,7 +1006,8 @@ class CodingMemoryStore: fact.created_at = datetime.utcnow() await _run_in_pool(self._upsert_fact_sql_sync, fact) await self._upsert_fact_vec(fact) - logger.info( + logger.info(f"[coding-store] inserted fact_id={fact.fact_id}") + logger.debug( f"[coding-store] inserted fact_id={fact.fact_id} " f"statement={fact.statement!r}" ) @@ -1199,8 +1236,8 @@ class CodingMemoryStore: experience_id, user_id, agent_id, task, search_keys, solution, boundary_envs, workspace_id, branch, session_id, files, source_fact_ids, confidence, source, extraction_source, - created_at, updated_at - ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + memory_at, created_at, updated_at + ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) ON CONFLICT(experience_id) DO UPDATE SET user_id = excluded.user_id, agent_id = excluded.agent_id, @@ -1216,6 +1253,7 @@ class CodingMemoryStore: confidence = excluded.confidence, source = excluded.source, extraction_source = excluded.extraction_source, + memory_at = excluded.memory_at, updated_at = excluded.updated_at """, ( @@ -1226,6 +1264,7 @@ class CodingMemoryStore: json.dumps(memory.files, ensure_ascii=False), json.dumps(memory.source_fact_ids, ensure_ascii=False), memory.confidence, memory.source, memory.extraction_source, + _to_epoch(memory.memory_at), (memory.created_at or datetime.utcnow()).isoformat(), (memory.updated_at or datetime.utcnow()).isoformat(), ), @@ -1366,8 +1405,8 @@ class CodingMemoryStore: fact_id, user_id, agent_id, session_id, workspace_id, branch, source, statement, files, subject, details, fact_link, derived_experience_ids, - status, fact_chain_summary, created_at - ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + status, fact_chain_summary, memory_at, created_at + ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) ON CONFLICT(fact_id) DO UPDATE SET user_id = excluded.user_id, agent_id = excluded.agent_id, @@ -1382,7 +1421,8 @@ class CodingMemoryStore: fact_link = excluded.fact_link, derived_experience_ids = excluded.derived_experience_ids, status = excluded.status, - fact_chain_summary = excluded.fact_chain_summary + fact_chain_summary = excluded.fact_chain_summary, + memory_at = excluded.memory_at """, ( fact.fact_id, fact.user_id, fact.agent_id, @@ -1395,6 +1435,7 @@ class CodingMemoryStore: json.dumps(fact.derived_experience_ids, ensure_ascii=False), fact.status, fact.fact_chain_summary or "", + _to_epoch(fact.memory_at), (fact.created_at or datetime.utcnow()).isoformat(), ), ) diff --git a/hy_memory/coding/types.py b/hy_memory/coding/types.py index 295be7a..147ddb6 100644 --- a/hy_memory/coding/types.py +++ b/hy_memory/coding/types.py @@ -25,6 +25,11 @@ FactStatus = Literal["active", "superseded"] MAX_FACT_CHAIN_ENTRIES = 8 +def _epoch(value: Optional[datetime]) -> Optional[int]: + """memory_at 对外是秒级 epoch,与 chat 一致。""" + return int(value.timestamp()) if isinstance(value, datetime) else None + + # ================================================================ # 草稿(LLM extract 阶段输出) # ================================================================ @@ -53,6 +58,8 @@ class CodingMemoryDraft: files: List[str] = field(default_factory=list) source: str = "default" extraction_source: str = "auto_extract" + # 对话时间(SDK 注入,同 chat 的 memory_at) + memory_at: Optional[datetime] = None def __post_init__(self) -> None: from ..utils.source_filter import normalize_source @@ -73,6 +80,7 @@ class CodingMemoryDraft: "files": list(self.files), "source": self.source, "extraction_source": self.extraction_source, + "memory_at": _epoch(self.memory_at), } @@ -111,6 +119,9 @@ class CodingMemory: extraction_source: str = "auto_extract" # 时间 + # memory_at 是对话时间(同 chat),created_at / updated_at 是写库时间。 + # UPDATE 合并时取两者中较晚的那个对话时间,见 store.update。 + memory_at: Optional[datetime] = None created_at: Optional[datetime] = None updated_at: Optional[datetime] = None @@ -135,6 +146,7 @@ class CodingMemory: "confidence": self.confidence, "source": self.source, "extraction_source": self.extraction_source, + "memory_at": _epoch(self.memory_at), "created_at": self.created_at.isoformat() if self.created_at else None, "updated_at": self.updated_at.isoformat() if self.updated_at else None, } @@ -249,6 +261,7 @@ class WorkingFact: fact_chain_summary: str = "" # 时间 + memory_at: Optional[datetime] = None # 对话时间(同 chat),没传时是收到请求的时间 created_at: Optional[datetime] = None # 产生时间,新的优先 def __post_init__(self) -> None: @@ -272,6 +285,7 @@ class WorkingFact: "derived_experience_ids": list(self.derived_experience_ids), "status": self.status, "fact_chain_summary": self.fact_chain_summary, + "memory_at": _epoch(self.memory_at), "created_at": self.created_at.isoformat() if self.created_at else None, } diff --git a/hy_memory/coding/writer.py b/hy_memory/coding/writer.py index c6a8b1e..f4afcd3 100644 --- a/hy_memory/coding/writer.py +++ b/hy_memory/coding/writer.py @@ -18,6 +18,7 @@ CodingWriter - 写入端协调器 import logging import time import uuid +from datetime import datetime from typing import Any, Dict, List, Optional from ..agent.llm_provider import LLMProvider @@ -79,9 +80,11 @@ class CodingWriter: session_id: Optional[str] = None, request_id: Optional[str] = None, source: str = "default", + memory_at: Optional[datetime] = None, ) -> Dict[str, Any]: """ - working/coding 段写入端到端。返回响应 dict(兼容 client.add 返回结构): + working/coding 段写入端到端。memory_at 是对话时间,记到这次写出的经验和 + 事实上;不传则用收到请求的时间(与 chat 链路一致)。返回响应 dict(兼容 client.add 返回结构): { "success": True, "scene": "productivity", @@ -101,6 +104,8 @@ class CodingWriter: """ request_id = request_id or str(uuid.uuid4()) t0 = time.perf_counter() + if memory_at is None: + memory_at = datetime.now() if not messages: return self._empty_response(request_id, t0) @@ -172,6 +177,7 @@ class CodingWriter: # extractor 只负责内容;调用来源由 SDK 入口注入,不能交给 LLM 生成。 for draft in drafts: draft.source = source + draft.memory_at = memory_at # 3. 经验层 reconcile + 持久化 ops: List[ReconcileOp] = ( @@ -197,6 +203,7 @@ class CodingWriter: workspace_id=workspace_id, branch=branch, source=source, + memory_at=memory_at, ) experience_ids = [op.target_experience_id for op in ops diff --git a/hy_memory/core/embed_service.py b/hy_memory/core/embed_service.py index efe7955..96fec8c 100644 --- a/hy_memory/core/embed_service.py +++ b/hy_memory/core/embed_service.py @@ -80,7 +80,7 @@ def _count_tokens(text: str) -> int: try: import tiktoken - return len(tiktoken.get_encoding("cl100k_base").encode(text)) + return len(tiktoken.get_encoding("cl100k_base").encode(text, disallowed_special=())) except Exception: return len(text) // _CHARS_PER_TOKEN_FALLBACK + 1 @@ -98,7 +98,8 @@ def _truncate_for_embedding(text: str, limit: int = _EMBED_MAX_TOKENS) -> str: import tiktoken enc = tiktoken.get_encoding("cl100k_base") - ids = enc.encode(text) + # Input is ordinary user text, not a tokenizer control-token stream. + ids = enc.encode(text, disallowed_special=()) if len(ids) <= limit: return text dropped = len(ids) - limit @@ -753,16 +754,22 @@ class EmbedService: """ 打一条 INFO 级 embedding 请求日志(含 request_id / provider / model / api / 入参 / 出参)。 - 出参只含 vector 维度,不含向量数值。request_id 同时写入 message, + 出参只含 vector 维度,不含向量数值。入参的 input 是待向量化的原文 + (对话 / 记忆 / 查询),INFO 只记每条的字符数(input_chars),原文仅在 + DEBUG 单独输出。request_id 同时写入 message, 并依赖 log formatter 的 %(request_id)s(setup_logging 后生效)。 """ + texts = request_payload.get("input") + info_request = {k: v for k, v in request_payload.items() if k != "input"} + if isinstance(texts, list): + info_request["input_chars"] = [len(str(t)) for t in texts] payload = { "request_id": get_request_id(), "status": status, "provider": self._embed_config.provider, "model": self._embed_config.model, "api": api_url, - "request": request_payload, + "request": info_request, "response": response_payload, } try: @@ -770,6 +777,10 @@ class EmbedService: except Exception: body = str(payload) logger.info(f"[embed] {body}") + if texts is not None and logger.isEnabledFor(logging.DEBUG): + logger.debug( + f"[embed] input: {json.dumps(texts, ensure_ascii=False, default=str)}" + ) async def _embed_openai( self, texts: List[str] diff --git a/hy_memory/pipelines/_retrieval/reconcile_retrieval.py b/hy_memory/pipelines/_retrieval/reconcile_retrieval.py index a5081e1..526aa0d 100644 --- a/hy_memory/pipelines/_retrieval/reconcile_retrieval.py +++ b/hy_memory/pipelines/_retrieval/reconcile_retrieval.py @@ -115,11 +115,16 @@ class ReconcileHybridRetriever: fused_max = max(fused_all) if fused_all else 0.0 base = ( - f"[reconcile-hybrid][{req}] pool={pool_size} q_terms={q_terms!r} " + f"[reconcile-hybrid][{req}] pool={pool_size} q_terms={len(q_terms)} " f"raw_bm25 max={raw_max:.4f} nonzero={raw_nonzero}/{len(raw_bm25)} " f"bm25_norm max={norm_max:.4f} nonzero={norm_nonzero}/{len(bm25_norms)} " f"sem_max={sem_max:.4f} fused_max={fused_max:.4f} " f"kept={kept}/{len(fused_all)} min_score={self._cfg.min_score} " + f"query({len(query_text or '')} chars)" + ) + # query 是待对账的新记忆原文,词项与预览只进 DEBUG + logger.debug( + f"[reconcile-hybrid][{req}] q_terms={q_terms!r} " f"query={q_preview!r} lemmatized={lem_preview!r}" ) diff --git a/hy_memory/pipelines/cross_domain_sweeper.py b/hy_memory/pipelines/cross_domain_sweeper.py index 700423e..8843e40 100644 --- a/hy_memory/pipelines/cross_domain_sweeper.py +++ b/hy_memory/pipelines/cross_domain_sweeper.py @@ -692,9 +692,10 @@ class CrossDomainSweeper: ) logger.info( - f"[sweeper] Created L6 core {core_id[:12]}: '{core_content[:60]}' " + f"[sweeper] Created L6 core {core_id[:12]} " f"from {len(cluster_ids)} basics, evidence_inherited={len(inherited_evidence_ids)}" ) + logger.debug(f"[sweeper] L6 core {core_id[:12]} content={core_content[:60]!r}") return 1, 0, [core_id] except Exception as e: diff --git a/hy_memory/pipelines/reader_base.py b/hy_memory/pipelines/reader_base.py index bc288d4..8bcacef 100644 --- a/hy_memory/pipelines/reader_base.py +++ b/hy_memory/pipelines/reader_base.py @@ -3587,8 +3587,9 @@ class BaseReadPipeline(ReadPipeline): f"hidden_l0={len(hidden_l0_hits)} fwd_l6={len(forward_l6)} rev_l6={len(reverse_l6)} " f"fused_l6={len(fused_l6)} graph_intent={len(graph_intention_hits)} " f"returned={len(final_results)} " - f"query='{request.query[:80]}'" + f"query({len(request.query or '')} chars)" ) + logger.debug(f"[read/{self.VERSION}] query={request.query[:80]!r}") response.success = True diff --git a/hy_memory/pipelines/system2_agent.py b/hy_memory/pipelines/system2_agent.py index d16d242..2ace7a8 100644 --- a/hy_memory/pipelines/system2_agent.py +++ b/hy_memory/pipelines/system2_agent.py @@ -2516,7 +2516,8 @@ def _parse_operations_json(text: str) -> Optional[List[Dict[str, Any]]]: return result return None except json.JSONDecodeError: - logger.warning(f"[S2-agent] JSON parse failed: {json_str[:200]}") + logger.warning(f"[S2-agent] JSON parse failed ({len(json_str)} chars)") + logger.debug(f"[S2-agent] unparsable output: {json_str[:200]!r}") return None diff --git a/hy_memory/utils/async_executor.py b/hy_memory/utils/async_executor.py index 0ab0c7e..28afa74 100644 --- a/hy_memory/utils/async_executor.py +++ b/hy_memory/utils/async_executor.py @@ -4,6 +4,7 @@ from __future__ import annotations import asyncio import concurrent.futures +import contextvars import functools from concurrent.futures import Executor from typing import Any, Callable, Optional @@ -39,7 +40,9 @@ async def run_in_executor_guarded( async def to_thread_guarded(func: Callable[..., Any], *args: Any, **kwargs: Any) -> Any: """Guarded equivalent of ``asyncio.to_thread`` using the default pool.""" - return await run_in_executor_guarded(None, func, *args, **kwargs) + context = contextvars.copy_context() + call = functools.partial(func, *args, **kwargs) + return await run_in_executor_guarded(None, context.run, call) def concurrent_result_guarded( diff --git a/hy_memory/utils/pipeline_log_writer.py b/hy_memory/utils/pipeline_log_writer.py index 20220bb..7b3f1b7 100644 --- a/hy_memory/utils/pipeline_log_writer.py +++ b/hy_memory/utils/pipeline_log_writer.py @@ -1,6 +1,7 @@ # -*- coding: utf-8 -*- """ -Pipeline Log Writer — 环节级 JSONL 日志(始终开启,与 SQLite Trace 分离)。 +Pipeline Log Writer — 环节级 JSONL 日志(默认开启,MEMORY_PIPELINE_LOG_ENABLED=false 关闭; +与 SQLite Trace 分离)。 目录: {log_dir}/{subdir}/{date}.log 每行: request_id, namespace, user_id, agent_id, step, prompt, content, parsed, diff --git a/hy_memory/utils/pipeline_observability.py b/hy_memory/utils/pipeline_observability.py index a7d898e..371dc70 100644 --- a/hy_memory/utils/pipeline_observability.py +++ b/hy_memory/utils/pipeline_observability.py @@ -1,16 +1,20 @@ # -*- coding: utf-8 -*- """ -Pipeline 可观测性:Log(文件 JSONL,始终开启)与 Trace(SQLite pipeline_logs,可关闭)。 +Pipeline 可观测性:Log(文件 JSONL,默认开启,可关闭)与 Trace(SQLite pipeline_logs,可关闭)。 - Log:运维 tail/grep,每个环节即时一行,不依赖后续步骤成功与否。 - Trace:Inspector / 调试,落库 pipeline_logs(需 MEMORY_CACHE_BACKEND=sqlite 等持久化后端)。 环境变量: + MEMORY_PIPELINE_LOG_ENABLED — Log 写 JSONL 文件,默认 true;false 时完全不写 MEMORY_PIPELINE_TRACE_ENABLED — Trace 落库,默认 true;OpenClaw C 端可设 false MEMORY_MEMORY_OPERATIONS_ENABLED — memory_operations 审计表落库,默认 false MEMORY_LOG_DIR — Log 目录(优先) MEMORY_TRACE_LOG_DIR — Log 目录(兼容旧名) +Log 与 Trace 都关闭时不包装 store_pipeline_log,而是换成立即返回 True 的 +空操作:热路径不做任何计时、脱敏或后台任务,也不写库。 + 子目录({log_dir}/{subdir}/{date}.log)由 PipelineLogWriter 从每条记录的 user_id 前缀(第一个 "__" 左侧)切分;无前缀回落 "default"。该前缀是 通用 namespace,可用于项目、部署或数据分桶。 @@ -94,6 +98,16 @@ def is_pipeline_trace_enabled() -> bool: ) +def is_pipeline_log_enabled() -> bool: + """是否把 pipeline step 写成 JSONL 文件({log_dir}//.log)。默认开启。""" + return os.getenv("MEMORY_PIPELINE_LOG_ENABLED", "true").strip().lower() in ( + "true", + "1", + "yes", + "on", + ) + + def is_memory_operations_enabled() -> bool: """是否将知识库变动写入 memory_operations 审计表。默认关闭(false)。""" return os.getenv("MEMORY_MEMORY_OPERATIONS_ENABLED", "false").lower() in ( @@ -125,7 +139,7 @@ def redact_content(value: str) -> str: def resolve_pipeline_log_dir() -> str: """ - JSONL pipeline log 根目录(始终使用,有默认值)。 + JSONL pipeline log 根目录(MEMORY_PIPELINE_LOG_ENABLED 开启时使用,有默认值)。 优先级: MEMORY_LOG_DIR > MEMORY_TRACE_LOG_DIR > {MEMORY_DATA_DIR}/logs/pipeline """ @@ -228,6 +242,7 @@ def wrap_store_pipeline_log( ) -> Callable[..., Any]: """包装 cache.store_pipeline_log:计时同步、JSONL/DB 异步落盘,不堵主请求。 + - log_writer 为 None 时不写 JSONL(MEMORY_PIPELINE_LOG_ENABLED=false) - step-to-step elapsed_ms / event_at_ms 在调用瞬间打点(与业务墙钟对齐) - event_at_ms:调用方传入非 0 值则直接复用(App 已在自己被调用的那一刻 同步打点,比这里更接近真实事件时刻);传 0 / 不传才用本地 time.time() @@ -410,7 +425,8 @@ def wrap_store_pipeline_log( try: loop = asyncio.get_running_loop() # JSONL 用线程池,与 loop 无亲和,留在当前 loop。 - _track_task(loop.create_task(_persist_jsonl())) + if log_writer is not None: + _track_task(loop.create_task(_persist_jsonl())) # DB trace 用 cache pool(可能 aiomysql,绑定 owner_loop)。若当前不在 # owner_loop(如 search 走独立 loop),派发回 owner_loop 执行,避免跨 loop。 if trace_enabled: @@ -446,25 +462,26 @@ def wrap_store_pipeline_log( ) except RuntimeError: # 无 running loop(极少见):退化为同步写,保证不丢日志 - try: - log_writer.write_step( - request_id=request_id, - user_id=user_id, - agent_id=agent_id, - session_id=session_id, - step=step, - prompt=prompt, - response=response, - parsed=parsed, - memory_ids=mem_ids, - elapsed_ms=step_elapsed_ms, - prompt_tokens=prompt_tokens, - completion_tokens=completion_tokens, - total_tokens=total_tokens, - event_at_ms=event_at_ms, - ) - except Exception: - pass + if log_writer is not None: + try: + log_writer.write_step( + request_id=request_id, + user_id=user_id, + agent_id=agent_id, + session_id=session_id, + step=step, + prompt=prompt, + response=response, + parsed=parsed, + memory_ids=mem_ids, + elapsed_ms=step_elapsed_ms, + prompt_tokens=prompt_tokens, + completion_tokens=completion_tokens, + total_tokens=total_tokens, + event_at_ms=event_at_ms, + ) + except Exception: + pass if trace_enabled: try: result = original_store( @@ -496,6 +513,11 @@ def wrap_store_pipeline_log( return _store_pipeline_observability +async def _noop_store_pipeline_log(*args: Any, **kwargs: Any) -> bool: + """Log 与 Trace 都关闭时的 store_pipeline_log:不计时、不写文件、不写库。""" + return True + + def install_pipeline_observability( cache: Any, *, @@ -503,6 +525,9 @@ def install_pipeline_observability( ) -> None: """给 cache 安装 JSONL + Trace 包装(fire-and-forget)。 + MEMORY_PIPELINE_LOG_ENABLED=false 时不写 JSONL;若 Trace 也关闭, + store_pipeline_log 被换成空操作(不包装、不写库)。 + 在 cache 所属 loop(write loop / _LoopThread)上调用,本函数会捕获该 loop 作为 owner_loop 传给包装器:search 走独立 loop 后,从 search loop 触发的 DB 落库会被派发回这个 owner_loop,避免跨 loop 用 aiomysql 污染连接池。 @@ -514,15 +539,31 @@ def install_pipeline_observability( except RuntimeError: owner_loop = None - log_dir = resolve_pipeline_log_dir() - log_writer = PipelineLogWriter(log_dir) + log_enabled = is_pipeline_log_enabled() trace_enabled = is_pipeline_trace_enabled() - logger.info( - f"[{log_label}] Pipeline log (JSONL) enabled: {log_dir}//.log " - f"(subdir from user_id prefix before '__', else default) ; " - f"pipeline trace (DB)={'on' if trace_enabled else 'off'} ; " - f"persist=async(fire-and-forget)" - ) + if not log_enabled and not trace_enabled: + logger.info( + f"[{log_label}] Pipeline log (JSONL) disabled ; pipeline trace (DB)=off ; " + f"store_pipeline_log=no-op" + ) + cache.store_pipeline_log = _noop_store_pipeline_log + return + + log_writer = None + if log_enabled: + log_dir = resolve_pipeline_log_dir() + log_writer = PipelineLogWriter(log_dir) + logger.info( + f"[{log_label}] Pipeline log (JSONL) enabled: {log_dir}//.log " + f"(subdir from user_id prefix before '__', else default) ; " + f"pipeline trace (DB)={'on' if trace_enabled else 'off'} ; " + f"persist=async(fire-and-forget)" + ) + else: + logger.info( + f"[{log_label}] Pipeline log (JSONL) disabled ; " + f"pipeline trace (DB)=on ; persist=async(fire-and-forget)" + ) cache.store_pipeline_log = wrap_store_pipeline_log( cache.store_pipeline_log, log_writer=log_writer, diff --git a/hy_memory/utils/token_count.py b/hy_memory/utils/token_count.py index 10e53ad..afbf09d 100644 --- a/hy_memory/utils/token_count.py +++ b/hy_memory/utils/token_count.py @@ -36,7 +36,8 @@ def count_tokens(text: str) -> int: enc = _get_encoder() if enc: try: - return len(enc.encode(text)) + # Quoted control-token spellings are ordinary input text. + return len(enc.encode(text, disallowed_special=())) except Exception as e: logger.debug(f"[token_count] encode failed, char fallback: {e}") return max(1, len(text) // 4) diff --git a/memhub/PRIVACY.md b/memhub/PRIVACY.md index bae6628..e4616df 100644 --- a/memhub/PRIVACY.md +++ b/memhub/PRIVACY.md @@ -29,10 +29,12 @@ prompt/response、密钥、访问令牌或完整本地路径。结构化日志 文件。详细合同见 [`docs/contracts/diagnostic-logging.md`](docs/contracts/diagnostic-logging.md)。 -用户显式把诊断级别切换为 `debug` 时,Core 会启用 HY pipeline trace,并将 -`MEMORY_LOG_LLM_CONTENT` 设为 `true`。该模式会把完整模型 prompt/response 写入本地调试 -日志,其中可能包含获授权的对话正文和模型输出;它只应用于有意识的故障排查,不应长期 -开启,也不应在未经检查和脱敏时分享相关日志。切回 `info` 会停止后续正文记录,但不会 +HY pipeline 日志与 trace 在任何级别下都关闭。HY SDK 的文本日志只写入 +`hy-memory/governed-v2/logs/hy_memory.log`,其中的 WARNING 及以上同时写入 `core.log`; +SDK 不在 INFO 及以上级别记录对话或记忆正文。用户显式把诊断级别切换为 `debug` 时,Core 将 +`MEMORY_LOG_LLM_CONTENT` 设为 `true`。该模式会把完整模型 prompt/response 写入 +`hy_memory.log` 的 DEBUG 行,其中可能包含获授权的对话正文和模型输出;它只应用于有意识的 +故障排查,不应长期开启,也不应在未经检查和脱敏时分享相关日志。切回 `info` 会停止后续正文记录,但不会 自动删除此前已写入的调试文件。 具体行为以当前源码、网络请求实现和发布说明为准。发现实现与本说明不一致时,请按 diff --git a/memhub/README.md b/memhub/README.md index 0c06ec2..6f609e6 100644 --- a/memhub/README.md +++ b/memhub/README.md @@ -18,7 +18,7 @@ If you run into a problem, please open an Issue with the version, platform,repro ## 发行与平台合同 -源码当前固定使用公开 PyPI 正式版 `hy-memory==2.0.6`。MemHub 源码版本为 `1.0.5` +源码当前固定使用公开 PyPI 正式版 `hy-memory==2.0.8`。MemHub 源码版本为 `1.0.5` (build 14),GitHub 仓库为 [`Tencent-Hunyuan/Hy-Memory`](https://github.com/Tencent-Hunyuan/Hy-Memory),npm 包名为 `memhub-cli`。当前代码架构见 @@ -118,7 +118,7 @@ MemHub 的 SQLite 数据默认位于 `~/.one-memory`,不在 npm 包或 Runtime ## Hy Memory -SDK 依赖固定为公开 PyPI 正式版 `hy-memory==2.0.6`。SDK 配置、权限边界及 search +SDK 依赖固定为公开 PyPI 正式版 `hy-memory==2.0.8`。SDK 配置、权限边界及 search 返回格式见 [`MEMORY.md`](MEMORY.md)。HY search 返回的 `content` 已包含 SDK 统一生成的 逻辑时间和演化上下文;调用方不应再次转换时间戳或重复拼接 `When`。 diff --git a/memhub/SBOM.spdx.json b/memhub/SBOM.spdx.json index f5f91d3..cff821a 100644 --- a/memhub/SBOM.spdx.json +++ b/memhub/SBOM.spdx.json @@ -2352,7 +2352,7 @@ { "SPDXID": "SPDXRef-Package-hy-memory", "name": "hy-memory", - "versionInfo": "2.0.6", + "versionInfo": "2.0.8", "downloadLocation": "NOASSERTION", "filesAnalyzed": false, "licenseConcluded": "Apache-2.0", diff --git a/memhub/THIRD_PARTY_NOTICES.md b/memhub/THIRD_PARTY_NOTICES.md index 58c3ab6..58b9923 100644 --- a/memhub/THIRD_PARTY_NOTICES.md +++ b/memhub/THIRD_PARTY_NOTICES.md @@ -9,7 +9,7 @@ Per-package license texts are not reproduced here yet; the license column is filled in as part of release review, and the SBOM records `NOASSERTION` until then rather than guessing. -## hy-memory 2.0.6 +## hy-memory 2.0.8 License: Apache-2.0 diff --git a/memhub/apps/core/pyproject.toml b/memhub/apps/core/pyproject.toml index ea2dce7..c36f94d 100644 --- a/memhub/apps/core/pyproject.toml +++ b/memhub/apps/core/pyproject.toml @@ -12,7 +12,7 @@ dependencies = [ "fastapi>=0.141.1", "filelock>=3.32.4", # Public SDK version validated against MemHub's permission and recall contracts. - "hy-memory==2.0.6", + "hy-memory==2.0.8", # chromadb arrives through the HY SDK; locked here so an unrelated upgrade # cannot move the SDK's store. Built-in embedding consumes numpy directly. "chromadb==1.5.9", diff --git a/memhub/apps/core/src/one_memory/api.py b/memhub/apps/core/src/one_memory/api.py index 255c353..a674d7e 100644 --- a/memhub/apps/core/src/one_memory/api.py +++ b/memhub/apps/core/src/one_memory/api.py @@ -3175,25 +3175,25 @@ def create_app( raise HTTPException(status_code=422, detail="memory_task_requires_experience") namespace = _namespace_kwargs(request.kind, request.variant) try: - client = await app.state.sdk_write_coordinator.client() - update_kwargs: dict[str, object] = dict(namespace) - if request.task is not None: - update_kwargs["task"] = request.task - result = await asyncio.to_thread( - client.update, memory_id, request.content, **update_kwargs - ) - if not isinstance(result, dict): - raise HySdkError("hy_memory_update_rejected") - if result.get("success") is not True: - if "not found" in str(result.get("error_message") or ""): - raise HTTPException(status_code=404, detail="memory_not_found") - raise HySdkError("hy_memory_update_rejected") - # The SDK names the namespace it wrote; read that one back. - if result.get("kind") in {"experience", "fact"}: - namespace = {"kind": result["kind"]} - if result.get("variant") in {"working", "coding"}: - namespace["variant"] = result["variant"] - raw = await asyncio.to_thread(client.get, memory_id, **namespace) + async with app.state.sdk_write_coordinator.use_client() as client: + update_kwargs: dict[str, object] = dict(namespace) + if request.task is not None: + update_kwargs["task"] = request.task + result = await asyncio.to_thread( + client.update, memory_id, request.content, **update_kwargs + ) + if not isinstance(result, dict): + raise HySdkError("hy_memory_update_rejected") + if result.get("success") is not True: + if "not found" in str(result.get("error_message") or ""): + raise HTTPException(status_code=404, detail="memory_not_found") + raise HySdkError("hy_memory_update_rejected") + # The SDK names the namespace it wrote; read that one back. + if result.get("kind") in {"experience", "fact"}: + namespace = {"kind": result["kind"]} + if result.get("variant") in {"working", "coding"}: + namespace["variant"] = result["variant"] + raw = await asyncio.to_thread(client.get, memory_id, **namespace) memory = None if raw is None else HySdkMemoryRecord.from_sdk(raw) except HTTPException: raise @@ -3222,10 +3222,10 @@ def create_app( ) -> Response: _check_memory_namespace(kind, variant) try: - client = await app.state.sdk_write_coordinator.client() - result = await asyncio.to_thread( - client.delete, memory_id, **_namespace_kwargs(kind, variant) - ) + async with app.state.sdk_write_coordinator.use_client() as client: + result = await asyncio.to_thread( + client.delete, memory_id, **_namespace_kwargs(kind, variant) + ) if not isinstance(result, dict): raise HySdkError("hy_memory_delete_rejected") error_code = result.get("error_code") @@ -3467,9 +3467,9 @@ def create_app( """Retry unknown writes only behind the user's explicit confirmation.""" del request reconciled = await _sdk_memory_runtime(app).reconcile_unknown_outputs() - from one_memory.memory_server.durable_queue import DurableWriteQueue - - queue = DurableWriteQueue(app.state.memory_write_queue_path) + # The startup queue knows the authority. A fresh legacy-mode queue + # would recreate the job-evidence table the SDK cutover dropped. + queue = app.state.memory_write_queue unknown = queue.unknown_jobs(limit=2048) if app.state.memory_authority is MemoryAuthority.LEGACY: for job in unknown: diff --git a/memhub/apps/core/src/one_memory/hy_runtime_config.py b/memhub/apps/core/src/one_memory/hy_runtime_config.py index 097e450..cef9958 100644 --- a/memhub/apps/core/src/one_memory/hy_runtime_config.py +++ b/memhub/apps/core/src/one_memory/hy_runtime_config.py @@ -14,7 +14,7 @@ from pathlib import Path from typing import Literal, cast HY_MEMORY_DISTRIBUTION = "hy-memory" -HY_MEMORY_VERSION = "2.0.6" +HY_MEMORY_VERSION = "2.0.8" HY_MEMORY_NAMESPACE = "governed-v2" DiagnosticLogLevel = Literal["error", "warning", "info", "debug"] @@ -109,11 +109,30 @@ def apply_diagnostic_log_level(level: DiagnosticLogLevel) -> None: if any(name == root or name.startswith(f"{root}.") for root in _NOISY_LIBRARY_LOGGERS): logging.getLogger(name).setLevel(noisy_level) + # HY configures its text log once, on the first client, at the level of + # that moment. Its file handler must follow later changes too, or a live + # switch to debug never reaches hy_memory.log. + for handler in logging.getLogger("hy_memory").handlers: + if isinstance(handler, logging.FileHandler): + handler.setLevel(selected) + os.environ["MEMORY_LOG_LEVEL"] = logging.getLevelName(selected) - os.environ["MEMORY_PIPELINE_TRACE_ENABLED"] = "true" if level == "debug" else "false" + _apply_hy_pipeline_policy() os.environ["MEMORY_LOG_LLM_CONTENT"] = "true" if level == "debug" else "false" +def _apply_hy_pipeline_policy() -> None: + """Keep HY's per-step pipeline log and trace off at every level. + + Nothing in MemHub reads them: Core's own diagnostics carry the step + timing, and the JSONL/SQLite copies only grew on disk. With both off + the SDK skips the per-step bookkeeping altogether. + """ + + os.environ["MEMORY_PIPELINE_LOG_ENABLED"] = "false" + os.environ["MEMORY_PIPELINE_TRACE_ENABLED"] = "false" + + def hy_memory_version() -> str: """Return the installed SDK version, failing if the pinned dist is absent.""" @@ -131,7 +150,9 @@ def configure_hy_runtime_environment(data_dir: Path) -> None: os.environ["MEMORY_LOG_DIR"] = str(log_dir) level = diagnostic_log_level(data_dir) os.environ["MEMORY_LOG_LEVEL"] = level.upper() - os.environ["MEMORY_PIPELINE_TRACE_ENABLED"] = "true" if level == "debug" else "false" + _apply_hy_pipeline_policy() + # Still meaningful with the pipeline log off: it decides whether HY's + # DEBUG lines in hy_memory.log carry full model prompts and responses. os.environ["MEMORY_LOG_LLM_CONTENT"] = "true" if level == "debug" else "false" os.environ["MEMORY_MEMORY_OPERATIONS_ENABLED"] = "false" os.environ["ANONYMIZED_TELEMETRY"] = "False" diff --git a/memhub/apps/core/src/one_memory/hy_sdk_migration.py b/memhub/apps/core/src/one_memory/hy_sdk_migration.py index cf43a29..e111eac 100644 --- a/memhub/apps/core/src/one_memory/hy_sdk_migration.py +++ b/memhub/apps/core/src/one_memory/hy_sdk_migration.py @@ -426,6 +426,7 @@ def _repair_coding( path = root / name if not path.is_file(): continue + _ensure_coding_schema(path) with closing(sqlite3.connect(path)) as database: tables = { str(row[0]) @@ -437,10 +438,14 @@ def _repair_coding( ): if table not in tables: continue + # _ensure_coding_schema added it; an SDK without the column + # (before 2.0.7) leaves the time to the vector repair alone. + has_memory_at = "memory_at" in _columns(database, table) rows = database.execute( - f"SELECT {identifier},source,created_at FROM {table}" + f"SELECT {identifier},source,created_at," + f"{'memory_at' if has_memory_at else 'NULL'} FROM {table}" ).fetchall() - for memory_id, source, created_at in rows: + for memory_id, source, created_at, memory_at in rows: desired = mapping.get(str(memory_id)) if desired is None: continue @@ -449,6 +454,13 @@ def _repair_coding( if desired.source and source in {None, "", "default"}: updates.append("source=?") values.append(desired.source) + if ( + has_memory_at + and desired.memory_at is not None + and memory_at != desired.memory_at + ): + updates.append("memory_at=?") + values.append(desired.memory_at) if desired.created_at is not None: desired_created_at = ( datetime.fromtimestamp(desired.created_at, tz=UTC) @@ -470,6 +482,32 @@ def _repair_coding( return repaired +def _ensure_coding_schema(path: Path) -> None: + """Bring a Coding/Working store to the installed SDK's schema. + + A migrated home's stores were written by an older SDK and may lack columns + the repair writes (``memory_at`` since hy-memory 2.0.7). The repair runs + before any SDK client opens them, so the SDK's own schema step is run here + rather than repeating its DDL. ``CodingMemoryStore`` has no public + schema-only entry point: ``initialize()`` also opens its Chroma + collections, which must stay closed during the offline repair. So only its + SQLite step runs, on a store object that carries nothing but that path. + """ + from hy_memory.coding.store import ( # type: ignore[import-untyped] + CodingMemoryStore, + ) + + # Relies on the pinned SDK's internals (hy-memory==2.0.8 is pinned exactly). + store = CodingMemoryStore.__new__(CodingMemoryStore) + store._db_path = str(path) + store._conn = None + try: + store._init_sqlite_sync() + finally: + if store._conn is not None: + store._conn.close() + + def _batches[T](values: list[T] | tuple[T, ...]) -> Iterator[tuple[T, ...]]: for start in range(0, len(values), _BATCH): yield tuple(values[start : start + _BATCH]) diff --git a/memhub/apps/core/src/one_memory/hy_sdk_runtime.py b/memhub/apps/core/src/one_memory/hy_sdk_runtime.py index 854bb48..3b4f626 100644 --- a/memhub/apps/core/src/one_memory/hy_sdk_runtime.py +++ b/memhub/apps/core/src/one_memory/hy_sdk_runtime.py @@ -36,6 +36,7 @@ from one_memory.hy_graph_admin import ( ) from one_memory.hy_sdk_types import HySdkRuntimeError from one_memory.local_embedding import LocalEmbedder +from one_memory.log_file import confine_hy_sdk_logging from one_memory.model_profiles import ( ModelProfileSnapshot, ProviderKind, @@ -66,6 +67,16 @@ _STORE_GATE = threading.Condition() _OFFLINE_STORES: set[Path] = set() _OPENING: dict[Path, int] = {} +# One client constructs at a time per home, its first-time store setup +# included. The constructor opens Chroma's `PersistentClient`, and two first +# opens on one directory race over that same unlocked System cache. On a +# clean install the write drain's client and a UI read client started in the +# same second; neither reached `VectorStore ready`, and the first write job +# was lost as unknown. Taken inside `acquire_client`, after the offline gate +# and never while `_STORE_GATE` is held, so it cannot deadlock with +# `hold_stores_offline`, which refuses while `_OPENING` counts a client. +_CONSTRUCTING: dict[Path, threading.Lock] = {} + class LocalOnnxEmbeddingService: """Public ``EmbeddingService`` implementation backed by MemHub's ONNX model.""" @@ -381,16 +392,23 @@ def _acquire_client( embedding_service: LocalOnnxEmbeddingService | None = None if (profile.embedding_provider_kind or profile.provider_kind) is ProviderKind.LOCAL_ONNX: embedding_service = LocalOnnxEmbeddingService() + with _STORE_GATE: + constructing = _CONSTRUCTING.setdefault(key, threading.Lock()) try: - client = HyMemoryClient( - config=config, - mode="ultra" if graph_store_enabled() else "pro", - runtime=runtime, - embedding_service=embedding_service, - ) + with constructing: + client = HyMemoryClient( + config=config, + mode="ultra" if graph_store_enabled() else "pro", + runtime=runtime, + embedding_service=embedding_service, + ) except BaseException: _release_runtime(key) raise + finally: + # The constructor's first step configures HY's text log (once per + # process), so by here it exists whether or not construction succeeded. + confine_hy_sdk_logging() return ClientLease(client, key) diff --git a/memhub/apps/core/src/one_memory/hy_sdk_types.py b/memhub/apps/core/src/one_memory/hy_sdk_types.py index 52fd381..d510a79 100644 --- a/memhub/apps/core/src/one_memory/hy_sdk_types.py +++ b/memhub/apps/core/src/one_memory/hy_sdk_types.py @@ -151,6 +151,7 @@ class HySdkMemoryRecord(BaseModel): if not content.strip(): raise HySdkReadError("hy_memory_record_shape_unknown") status = str(raw.get("status") or "active") + memory_at = raw.get("memory_at") created_at = _epoch(raw.get("created_at")) updated_at = _epoch(raw.get("updated_at")) try: @@ -167,6 +168,9 @@ class HySdkMemoryRecord(BaseModel): str(raw["session_id"]) if isinstance(raw.get("session_id"), str) else None ), source=str(raw["source"]) if isinstance(raw.get("source"), str) else None, + # Conversation time; hy-memory 2.0.7 stores it for experiences + # and facts. Older stores leave it unknown. + memory_at=memory_at if isinstance(memory_at, int) else None, gmt_created=created_at, scene=cast(MemoryScene, variant), kind=cast(MemoryKindName, kind), diff --git a/memhub/apps/core/src/one_memory/log_file.py b/memhub/apps/core/src/one_memory/log_file.py index 23be281..27b207b 100644 --- a/memhub/apps/core/src/one_memory/log_file.py +++ b/memhub/apps/core/src/one_memory/log_file.py @@ -20,8 +20,11 @@ def start_logging_to_file(data_dir: Path) -> Path: nowhere. That includes the loop watchdog: the one report that names what stalled the app was unreadable in exactly the situation it exists for. - The active diagnostic collection level controls Core, HY SDK, and provider - client records. Uvicorn keeps its request log on its own non-propagating + The active diagnostic collection level controls Core and provider client + records. The HY SDK keeps its own text log, hy_memory.log under the SDK's + log directory, and stops propagating here once its first client is built; + `confine_hy_sdk_logging` then forwards only its warnings and errors to + this file. Uvicorn keeps its request log on its own non-propagating loggers. """ destination = log_path(data_dir) @@ -49,3 +52,53 @@ def start_logging_to_file(data_dir: Path) -> Path: if root.level > logging.INFO or root.level == logging.NOTSET: root.setLevel(logging.INFO) return destination + + +HY_SDK_LOGGER = "hy_memory" + + +class _CoreLogForwarder(logging.Handler): + """Hands HY warnings to Core's own core.log handler, rotation and format.""" + + def __init__(self, target: logging.Handler) -> None: + super().__init__(level=logging.WARNING) + self.target = target + + def emit(self, record: logging.LogRecord) -> None: + self.target.handle(record) + + +def confine_hy_sdk_logging() -> None: + """Keep HY's text log in hy_memory.log, with only its problems in core.log. + + HY's first client sets up hy_memory.log plus a stdout and a stderr stream + on the "hy_memory" logger, and stops it propagating to the root. Under + launchd those streams are service.log and service-error.log, so every SDK + line was written twice, and none reached core.log. Drop the streams and + forward WARNING and above to core.log, which the Debug panel reads; the + SDK keeps conversation text out of those levels. + + Idempotent. Does nothing until HY has configured its logger, because a + propagating logger already reaches core.log through the root. + """ + sdk = logging.getLogger(HY_SDK_LOGGER) + if sdk.propagate: + return + for handler in list(sdk.handlers): + if isinstance(handler, logging.StreamHandler) and not isinstance( + handler, logging.FileHandler + ): + sdk.removeHandler(handler) + if any(isinstance(handler, _CoreLogForwarder) for handler in sdk.handlers): + return + core = next( + ( + handler + for handler in logging.getLogger().handlers + if isinstance(handler, RotatingFileHandler) + and Path(handler.baseFilename).name == "core.log" + ), + None, + ) + if core is not None: + sdk.addHandler(_CoreLogForwarder(core)) diff --git a/memhub/apps/core/src/one_memory/memory_server/durable_queue.py b/memhub/apps/core/src/one_memory/memory_server/durable_queue.py index b755ba9..5d74014 100644 --- a/memhub/apps/core/src/one_memory/memory_server/durable_queue.py +++ b/memhub/apps/core/src/one_memory/memory_server/durable_queue.py @@ -52,6 +52,7 @@ from one_memory.memory_tasks import ( from one_memory.memory_tasks import ( POLICY_STOPPED_CODES as _TASK_POLICY_STOPPED_CODES, ) +from one_memory.sdk_migration_log import error_chain_text from one_memory.service_levels import ServiceLevel, service_level_context logger = logging.getLogger(__name__) @@ -241,14 +242,16 @@ PERMISSION_REQUIRED_CODES = frozenset( ) #: Model-side codes the SDK write coordinator raises before it can lease a -#: client (no active profile, missing credential, secure storage down). They prove -#: nothing was sent, so the write parks instead of being lost. Transport codes -#: that can arrive after a request was in flight stay `unknown`. +#: client (no active profile, missing credential, secure storage down, or the +#: client failed to construct). They prove nothing was sent, so the write +#: parks instead of being lost. Transport codes that can arrive after a +#: request was in flight stay `unknown`. MODEL_NOT_READY_CODES = frozenset( { "model_profile_not_active", "model_secret_unavailable", "secure_storage_unavailable", + "hy_memory_client_unavailable", } ) @@ -292,6 +295,23 @@ _VALID_JOB_STATES = frozenset( #: A row in one of these states can never be moved back to a live one. _TERMINAL_WRITE_STATES = frozenset({COMPLETED, FAILED, DEAD, CANCELLED}) +#: The legacy task rows a write job can be linked to. The SDK cutover drops +#: them (`target_schema.LEGACY_TABLES_IN_DROP_ORDER`, inputs before tasks), so +#: the job-only paths must not assume any of them. +_LEGACY_TASK_LINK_TABLES = ("memory_tasks", "memory_task_inputs", "memory_write_job_evidence") + + +def _legacy_task_links_present(connection: sqlite3.Connection) -> bool: + present = { + str(row[0]) + for row in connection.execute( + "SELECT name FROM sqlite_master WHERE type='table' AND name IN (?,?,?)", + _LEGACY_TASK_LINK_TABLES, + ) + } + return present == set(_LEGACY_TASK_LINK_TABLES) + + #: Columns a current schema declares but an older `memory_write_jobs` may lack. #: `CREATE TABLE IF NOT EXISTS` is a no-op for an existing table, so without #: this an upgraded install would keep an older queue that every claim/lease @@ -1982,21 +2002,24 @@ class DurableWriteQueue: or str(row["last_error"]) in NON_RETRYABLE_POST_WRITE_CODES ): return 0 - connection.execute( - """ - UPDATE memory_tasks - SET status='pending', runner_token=NULL, attempts=0, - last_error_code='model_content_manual_retry_requested', updated_at=? - WHERE status='unknown' AND task_id IN ( - SELECT inputs.task_id - FROM memory_task_inputs AS inputs, json_each(inputs.refs_json) AS ref - JOIN memory_write_job_evidence AS linked - ON linked.evidence_id=json_extract(ref.value, '$.evidence_id') - WHERE linked.job_id=? + # After the SDK cutover the legacy task tables are gone and the + # job is the only row to reset. + if not self.sdk_authority and _legacy_task_links_present(connection): + connection.execute( + """ + UPDATE memory_tasks + SET status='pending', runner_token=NULL, attempts=0, + last_error_code='model_content_manual_retry_requested', updated_at=? + WHERE status='unknown' AND task_id IN ( + SELECT inputs.task_id + FROM memory_task_inputs AS inputs, json_each(inputs.refs_json) AS ref + JOIN memory_write_job_evidence AS linked + ON linked.evidence_id=json_extract(ref.value, '$.evidence_id') + WHERE linked.job_id=? + ) + """, + (now, job_id), ) - """, - (now, job_id), - ) changed = connection.execute( """ UPDATE memory_write_jobs @@ -2098,9 +2121,7 @@ class DurableWriteQueue: f"WHERE state=? AND job_id IN ({placeholders})", (PENDING, now, UNKNOWN, *job_ids), ) - if connection.execute( - "SELECT 1 FROM sqlite_master WHERE type='table' AND name='memory_tasks'" - ).fetchone(): + if _legacy_task_links_present(connection): connection.execute( f"UPDATE memory_tasks SET status=?, runner_token=NULL, " f"last_error_code='model_content_reconciled_absent_retry', updated_at=? " @@ -2158,9 +2179,7 @@ class DurableWriteQueue: f"WHERE state=? AND attempts=1 AND job_id IN ({placeholders})", (PENDING, now, UNKNOWN, *job_ids), ) - if connection.execute( - "SELECT 1 FROM sqlite_master WHERE type='table' AND name='memory_tasks'" - ).fetchone(): + if _legacy_task_links_present(connection): connection.execute( f"UPDATE memory_tasks SET status=?, runner_token=NULL, " f"last_error_code='model_content_unknown_auto_retry', updated_at=? " @@ -2177,6 +2196,14 @@ class DurableWriteQueue: def resolve_unknown_from_linked_output(self, job_id: str) -> bool: """Close an unknown durable row when local governance output proves success.""" with main_database(self.database_path).read(row_factory=sqlite3.Row) as connection: + if not ( + _legacy_task_links_present(connection) + and connection.execute( + "SELECT 1 FROM sqlite_master WHERE type='table' AND name='memory_task_outputs'" + ).fetchone() + ): + # No legacy governance output survives the SDK cutover. + return False row = connection.execute( """ SELECT 1 @@ -2559,9 +2586,22 @@ async def execute_job( if code == "model_profile_not_active": logger.debug("durable_write_job_parked job_id=%s error_code=%s", job_id, code) elif state in PARKED_STATES: - logger.info("durable_write_job_parked job_id=%s error_code=%s", job_id, code) + logger.info( + "durable_write_job_parked job_id=%s error_code=%s chain=%s", + job_id, + code, + error_chain_text(error), + ) else: - logger.error("durable_write_job_failed job_id=%s error_code=%s", job_id, code) + # Where it failed, as `file:line:function` frames of the exception + # chain, never its message: `error_code=AttributeError` alone + # named no location. + logger.error( + "durable_write_job_failed job_id=%s error_code=%s chain=%s", + job_id, + code, + error_chain_text(error), + ) return await in_the_background( queue.settle, diff --git a/memhub/apps/core/src/one_memory/sdk_memory_runtime.py b/memhub/apps/core/src/one_memory/sdk_memory_runtime.py index fd247e5..4e13689 100644 --- a/memhub/apps/core/src/one_memory/sdk_memory_runtime.py +++ b/memhub/apps/core/src/one_memory/sdk_memory_runtime.py @@ -5,7 +5,8 @@ from __future__ import annotations import asyncio import logging import re -from contextlib import suppress +from collections.abc import AsyncIterator +from contextlib import AsyncExitStack, asynccontextmanager, suppress from datetime import UTC, datetime, timedelta from pathlib import Path from typing import Any @@ -164,44 +165,45 @@ class SdkMemoryRuntime: if str(error) == "model_profile_not_active": return HyGraphSnapshot(consulted=False) raise - try: - client = await self.coordinator.client() - except Exception as error: - raise HySdkError("hy_memory_graph_read_failed") from error - return await asyncio.to_thread( - read_graph_snapshot, - client, - "local", - "*", - limit, - ) + async with AsyncExitStack() as stack: + try: + client = await stack.enter_async_context(self.coordinator.use_client()) + except Exception as error: + raise HySdkError("hy_memory_graph_read_failed") from error + return await asyncio.to_thread( + read_graph_snapshot, + client, + "local", + "*", + limit, + ) async def digest(self) -> dict[str, object]: - client = await self.coordinator.client() - try: - raw = await asyncio.to_thread( - client.list_memories, - user_id="local", - limit=1_000, - offset=0, - ) - agent_ids = _agent_ids(raw) - digests = [ - { - "agent_id": agent_id, - "schemas_recorded": 0, - **dict( - await asyncio.to_thread( - client.evolve, - user_id="local", - agent_id=agent_id, - ) - ), - } - for agent_id in agent_ids - ] - except Exception as error: - raise HySdkError("hy_memory_digest_failed") from error + async with self.coordinator.use_client() as client: + try: + raw = await asyncio.to_thread( + client.list_memories, + user_id="local", + limit=1_000, + offset=0, + ) + agent_ids = _agent_ids(raw) + digests = [ + { + "agent_id": agent_id, + "schemas_recorded": 0, + **dict( + await asyncio.to_thread( + client.evolve, + user_id="local", + agent_id=agent_id, + ) + ), + } + for agent_id in agent_ids + ] + except Exception as error: + raise HySdkError("hy_memory_digest_failed") from error return { "success": all(result.get("success") is not False for result in digests), "scope_count": len(digests), @@ -240,36 +242,39 @@ class SdkMemoryRuntime: decision=decision, ) - async def _mutation_client(self) -> Any: + @asynccontextmanager + async def _mutation_client(self) -> AsyncIterator[Any]: """The write client, with no-model and keychain refusals as SDK codes. Callers record these against the edit or deletion instead of failing the request that already committed it. """ - try: - return await self.coordinator.client() - except RuntimeError as error: - code = str(error) - if not _STABLE_CODE.fullmatch(code): - code = "hy_memory_client_unavailable" - raise HySdkError(code) from error + async with AsyncExitStack() as stack: + try: + client = await stack.enter_async_context(self.coordinator.use_client()) + except RuntimeError as error: + code = str(error) + if not _STABLE_CODE.fullmatch(code): + code = "hy_memory_client_unavailable" + raise HySdkError(code) from error + yield client async def update_hy_memory(self, memory_id: str, content: str) -> dict[str, object]: - client = await self._mutation_client() - try: - result = await asyncio.to_thread(client.update, memory_id, content) - except Exception as error: - raise HySdkError("hy_memory_update_failed") from error + async with self._mutation_client() as client: + try: + result = await asyncio.to_thread(client.update, memory_id, content) + except Exception as error: + raise HySdkError("hy_memory_update_failed") from error if not isinstance(result, dict) or result.get("success") is not True: raise HySdkError("hy_memory_update_rejected") return result async def finish_deletion(self, memory_id: str) -> None: - client = await self._mutation_client() - try: - result = await asyncio.to_thread(client.delete, memory_id) - except Exception as error: - raise HySdkError("hy_memory_delete_failed") from error + async with self._mutation_client() as client: + try: + result = await asyncio.to_thread(client.delete, memory_id) + except Exception as error: + raise HySdkError("hy_memory_delete_failed") from error if not isinstance(result, dict): raise HySdkError("hy_memory_delete_rejected") error_code = result.get("error_code") diff --git a/memhub/apps/core/src/one_memory/sdk_migration_runner.py b/memhub/apps/core/src/one_memory/sdk_migration_runner.py index 203eddc..a98ef46 100644 --- a/memhub/apps/core/src/one_memory/sdk_migration_runner.py +++ b/memhub/apps/core/src/one_memory/sdk_migration_runner.py @@ -35,6 +35,8 @@ from one_memory.memory_server.durable_queue import ( COMPLETED, FAILED, REAPED_PAYLOAD_MARKER, + RUNNING, + UNKNOWN, DurableWriteQueue, ) from one_memory.memory_server.unified_entry import UnifiedWriteIntake @@ -317,11 +319,45 @@ def move_pending_dispatches(database_path: Path) -> int: return len(conversations) +#: Why a pre-cutover write job that may have reached HY was closed. +ABANDONED_AT_CUTOVER = "abandoned_at_cutover" + + +def settle_legacy_unknown_write_jobs(database_path: Path) -> int: + """Close write jobs the legacy pipeline left possibly-sent. Safe to repeat. + + They ran under the legacy pipeline, so the SDK's `get_write_outcome` knows + none of them and the unknown reconcile can never settle them: a migrated + 1.0.4 home showed 1000+ unknown forever. They are not retried, since they + may already have written and the SDK has no idempotency key. `cancelled`, + not `failed`: the upgrade ended them, nothing broke, and a `failed` count + would put the home in the failed state for good. `hy_invoked` is kept, so + no readmission path can pick one up again. + """ + with main_database(database_path).read(row_factory=sqlite3.Row) as database: + if "memory_write_jobs" not in _tables(database): + return 0 + now = datetime.now(UTC).isoformat() + with main_database(database_path).write(autocommit=True) as database: + # A `running` row already marked invoked would be reclaimed to + # `unknown` on the next open, so it is the same case. + return int( + database.execute( + "UPDATE memory_write_jobs SET state=?,lease_owner=NULL," + "lease_expires_at=NULL,last_error=?,updated_at=? " + "WHERE state=? OR (state=? AND hy_invoked=1)", + (CANCELLED, ABANDONED_AT_CUTOVER, now, UNKNOWN, RUNNING), + ).rowcount + ) + + def abandoned_legacy_work(database_path: Path) -> dict[str, int]: """Count legacy work that ends with the cutover instead of blocking it. A task that may have reached the SDK is not replayed: the SDK already holds whatever it committed. Pending user deletions are not carried over. + Settled write jobs are counted by their code, so a repeated preparation + reports the same number. """ abandoned: dict[str, int] = {} with main_database(database_path).read(row_factory=sqlite3.Row) as database: @@ -332,6 +368,11 @@ def abandoned_legacy_work(database_path: Path) -> dict[str, int]: "memory_tasks", "status='unknown' OR (status='running' AND hy_invocation_count > 0)", ), + ( + "unknown_write_jobs", + "memory_write_jobs", + f"state='{CANCELLED}' AND last_error='{ABANDONED_AT_CUTOVER}'", + ), ("deletions", "memory_deletions", "status IN ('pending','running')"), ) for name, table, where in checks: @@ -354,6 +395,10 @@ def prepare_legacy_work_for_cutover( running, so a failure names it. """ trace = {} if trace is None else trace + # First: a possibly-sent job never runs again, so its input is not + # frozen, and input released since must not block the cutover. + trace["sub_step"] = "unknown_write_jobs" + settle_legacy_unknown_write_jobs(database_path) trace["sub_step"] = "write_queue" frozen, moved = prepare_legacy_write_queue_for_cutover(database_path) trace["sub_step"] = "pending_dispatches" diff --git a/memhub/apps/core/src/one_memory/sdk_write_processor.py b/memhub/apps/core/src/one_memory/sdk_write_processor.py index f6e4d98..dd5d94a 100644 --- a/memhub/apps/core/src/one_memory/sdk_write_processor.py +++ b/memhub/apps/core/src/one_memory/sdk_write_processor.py @@ -3,7 +3,8 @@ from __future__ import annotations import asyncio -from collections.abc import Awaitable, Callable, Mapping, Sequence +from collections.abc import AsyncIterator, Awaitable, Callable, Mapping, Sequence +from contextlib import asynccontextmanager from dataclasses import dataclass from datetime import datetime from typing import Any @@ -56,7 +57,12 @@ class SdkWriteProcessor: scope = _write_scope(records) metadata = _write_metadata(records, scope) - client = await self._client_handle.client() + try: + client = await self._client_handle.client() + except Exception as error: + # Before `before_hy_invocation`: nothing was sent, so the job + # waits and retries instead of being left `unknown`. + raise RuntimeError("hy_memory_client_unavailable") from error if extracted: contents = [sanitize_model_input(record.verbatim) for record in records] @@ -125,7 +131,14 @@ class SdkWriteProcessor: class SdkWriteCoordinator: - """Resolve the active model profile, then execute one public SDK write.""" + """Resolve the active model profile, then execute one public SDK write. + + A model profile change retires the previous profile's handle, but only + closes it once nothing uses it. Closing it at once tore the client out + from under a write still running on it: the SDK cleared its stores and + the SharedRuntime closed mid-`add`, the job failed with AttributeError + after HY was invoked, and it was left `unknown`. + """ def __init__( self, @@ -142,6 +155,9 @@ class SdkWriteCoordinator: self.transport_factory = transport_factory self.sedimentation_enabled = sedimentation_enabled self._handles: dict[tuple[str, int], SdkClientHandle] = {} + #: Uses in flight per handle; a retired handle closes at zero. + self._uses: dict[SdkClientHandle, int] = {} + self._retired: set[SdkClientHandle] = set() self._lock = asyncio.Lock() async def process_sdk_job( @@ -153,28 +169,30 @@ class SdkWriteCoordinator: ) -> SdkWriteReceipt: if not self.sedimentation_enabled(): raise RuntimeError("model_sedimentation_disabled") - handle = await self._active_handle() - return await SdkWriteProcessor(handle).process_sdk_job( - records, - request_id=request_id, - before_hy_invocation=before_hy_invocation, - ) + async with self._active_handle() as handle: + return await SdkWriteProcessor(handle).process_sdk_job( + records, + request_id=request_id, + before_hy_invocation=before_hy_invocation, + ) async def inquire_write_outcome( self, request_id: str ) -> SdkWriteReceipt | None: - return await SdkWriteProcessor( - await self._active_handle() - ).inquire_write_outcome(request_id) + async with self._active_handle() as handle: + return await SdkWriteProcessor(handle).inquire_write_outcome(request_id) async def close(self) -> None: async with self._lock: - handles, self._handles = tuple(self._handles.values()), {} + handles = (*self._handles.values(), *self._retired) + self._handles, self._retired, self._uses = {}, set(), {} await asyncio.gather(*(handle.close() for handle in handles)) - async def client(self) -> Any: - """Return the public SDK client selected by the active write profile.""" - return await (await self._active_handle()).client() + @asynccontextmanager + async def use_client(self) -> AsyncIterator[Any]: + """The public SDK client of the active write profile, kept open while used.""" + async with self._active_handle() as handle: + yield await handle.client() async def active_profile_credentials( self, @@ -183,7 +201,9 @@ class SdkWriteCoordinator: _identity, profile, secret = await asyncio.to_thread(self._read_active_credentials) return profile, secret - async def _active_handle(self) -> SdkClientHandle: + @asynccontextmanager + async def _active_handle(self) -> AsyncIterator[SdkClientHandle]: + """Use the active profile's handle; retire the others, closing the unused.""" identity, profile, secret = await asyncio.to_thread( self._read_active_credentials ) @@ -197,14 +217,25 @@ class SdkWriteCoordinator: http_transport_factory=self.transport_factory(profile), ) self._handles[identity] = handle - stale = [ - value - for key, value in self._handles.items() - if key != identity - ] + self._retired.update(value for key, value in self._handles.items() if key != identity) self._handles = {identity: handle} - await asyncio.gather(*(value.close() for value in stale)) - return handle + self._uses[handle] = self._uses.get(handle, 0) + 1 + unused = {value for value in self._retired if not self._uses.get(value)} + self._retired -= unused + await asyncio.gather(*(value.close() for value in unused)) + try: + yield handle + finally: + # Bookkeeping without an await, so a cancelled caller still + # releases its use. + remaining = self._uses.get(handle, 0) - 1 + if remaining > 0: + self._uses[handle] = remaining + else: + self._uses.pop(handle, None) + if remaining <= 0 and handle in self._retired: + self._retired.discard(handle) + await handle.close() def _read_active_credentials( self, diff --git a/memhub/apps/core/tests/TEST_INDEX.md b/memhub/apps/core/tests/TEST_INDEX.md index fd2f457..b38c5bb 100644 --- a/memhub/apps/core/tests/TEST_INDEX.md +++ b/memhub/apps/core/tests/TEST_INDEX.md @@ -79,7 +79,7 @@ | `test_database_file_permissions.py` | `contract` | 覆盖 a new main database is readable by its owner alone、the wal sidecars are not left world readable、a database from an older build is tightened on open 场景。 | | `test_db_session_utc.py` | `contract` | The MySQL session must be pinned to UTC. | | `test_derived_echo.py` | `contract` | A host that saves our injection back must not mint a new user decision. | -| `test_detailed_logging.py` | `contract` | 覆盖 detailed pipeline logging defaults off and survives restart、live log level applies to full hy and provider call chain、info collects hy info without enabling debug pipeline content 等 7 个场景。 | +| `test_detailed_logging.py` | `contract` | 覆盖 detailed logging defaults off and survives restart、hy pipeline log and trace stay off at every level、live level change reaches the hy text log file 等 7 个场景。 | | `test_diagnostic_log.py` | `contract` | 覆盖 high frequency success events are summarized but warnings are not、structured log is private correlated and owner only、arbitrary detail and absolute stack are rejected 等 14 个场景。 | | `test_diagnostic_log_durability.py` | `contract` | 写线程报告的「已落盘」必须是真的。 | | `test_diagnostic_log_off_loop.py` | `contract` | 诊断日志不得在调用线程上做磁盘 I/O。 | @@ -112,6 +112,7 @@ | `test_hy_log_privacy.py` | `contract` | HY SDK records are not rewritten by One Memory's logging setup. | | `test_hy_network_egress.py` | `contract` | Where a real HY client is allowed to send bytes, and where it is not. | | `test_hy_runtime_config.py` | `contract` | MEMORY.md is the audited record of what we send HY; keep it answerable. | +| `test_hy_sdk_log_routing.py` | `contract` | HY SDK text logs go to hy_memory.log only, with warnings also in core.log. | | `test_hy_step_trace_switch.py` | `contract` | Rule 15: the per-step HY trace is off unless the debug tier asks for it. | | `test_import_api.py` | `integration` | 覆盖 resume during cleanup returns conflict without internal error、authorize detect import and revoke api flow、protected api rejects missing token and foreign origin 等 5 个场景。 | | `test_import_control_races_review.py` | `contract` | Read-only review repro: real runner/store, synthetic delayed adapter cleanup. | @@ -245,6 +246,7 @@ | `test_schema_gate.py` | `contract` | 覆盖 fresh database records the build schema、future schema refuses to open、legacy database without a ledger is left untouched 场景。 | | `test_schema_migrations.py` | `contract` | 覆盖 evidence store adds source ordinal to previous schema、import store migrates previous job and error schema、old active job index lets a sync sit beside paused history 等 4 个场景。 | | `test_schema_ownership_gate.py` | `contract` | A1-03/A1-04: schema ownership, and the hard part of telling DDL from reads. | +| `test_sdk_client_construction.py` | `contract` | SDK clients of one home are constructed one at a time. | | `test_sdk_data_plane_migration.py` | `contract` | SDK-authority migration ledger, aliases and atomic cutover marker. | | `test_sdk_memory_qa.py` | `contract` | 覆盖 sdk ask propagates sdk search failure without legacy fallback、sdk ask revalidates memory before returning extract、sdk ask uses native sdk memory without governance fields 场景。 | | `test_sdk_migration_bundle.py` | `contract` | SDK-authority cutover requires a verified management + SDK data-plane bundle. | @@ -307,4 +309,4 @@ | `test_workspace_recall.py` | `contract` | Workspace memories were unreachable from every host; these pin the way in. | | `test_write_queue_lease_renewal.py` | `contract` | Rule 8: a lease must outlive the work it covers, and be renewed while it runs. | -共 302 个测试文件。 +共 304 个测试文件。 diff --git a/memhub/apps/core/tests/core_test_classification.py b/memhub/apps/core/tests/core_test_classification.py index 5f362a3..7c0b208 100644 --- a/memhub/apps/core/tests/core_test_classification.py +++ b/memhub/apps/core/tests/core_test_classification.py @@ -14,8 +14,8 @@ from pathlib import Path import pytest PRIMARY_MARKERS = ("unit", "contract", "integration", "performance", "live") -EXPECTED_TEST_FILE_COUNT = 302 -EXPECTED_TEST_FILES_SHA256 = "07707528025ac134e46c93ebef12335e852df1ed0f52f8beb62abb3b4d1b0e97" +EXPECTED_TEST_FILE_COUNT = 304 +EXPECTED_TEST_FILES_SHA256 = "b28f022b9688c96ca563c59de63e95d344d2f01ba3b6020b422bf4dfb27520d6" # Pure transformations, validation models, parity checks and state machines. # This list is intentionally small: uncertain files default to contract. diff --git a/memhub/apps/core/tests/test_detailed_logging.py b/memhub/apps/core/tests/test_detailed_logging.py index 6bcdf44..dd61599 100644 --- a/memhub/apps/core/tests/test_detailed_logging.py +++ b/memhub/apps/core/tests/test_detailed_logging.py @@ -1,6 +1,5 @@ import json import logging -from importlib import import_module from pathlib import Path from one_memory.hy_runtime_config import ( @@ -12,20 +11,50 @@ from one_memory.hy_runtime_config import ( ) -def test_detailed_pipeline_logging_defaults_off_and_survives_restart( - tmp_path: Path, monkeypatch -) -> None: - monkeypatch.delenv("MEMORY_PIPELINE_TRACE_ENABLED", raising=False) +def test_detailed_logging_defaults_off_and_survives_restart(tmp_path: Path, monkeypatch) -> None: + monkeypatch.delenv("MEMORY_LOG_LEVEL", raising=False) assert detailed_logging_enabled(tmp_path) is False configure_hy_runtime_environment(tmp_path) - assert __import__("os").environ["MEMORY_PIPELINE_TRACE_ENABLED"] == "false" + assert __import__("os").environ["MEMORY_LOG_LEVEL"] == "INFO" assert diagnostic_log_level(tmp_path) == "info" assert set_detailed_logging(tmp_path, True) is True assert detailed_logging_enabled(tmp_path) is True - monkeypatch.delenv("MEMORY_PIPELINE_TRACE_ENABLED", raising=False) + monkeypatch.delenv("MEMORY_LOG_LEVEL", raising=False) configure_hy_runtime_environment(tmp_path) - assert __import__("os").environ["MEMORY_PIPELINE_TRACE_ENABLED"] == "true" + assert __import__("os").environ["MEMORY_LOG_LEVEL"] == "DEBUG" + + +def test_hy_pipeline_log_and_trace_stay_off_at_every_level(tmp_path: Path, monkeypatch) -> None: + environment = __import__("os").environ + for level in ("error", "warning", "info", "debug"): + for name in ("MEMORY_PIPELINE_LOG_ENABLED", "MEMORY_PIPELINE_TRACE_ENABLED"): + monkeypatch.setenv(name, "true") + set_diagnostic_log_level(tmp_path, level) + assert environment["MEMORY_PIPELINE_LOG_ENABLED"] == "false" + assert environment["MEMORY_PIPELINE_TRACE_ENABLED"] == "false" + + for name in ("MEMORY_PIPELINE_LOG_ENABLED", "MEMORY_PIPELINE_TRACE_ENABLED"): + monkeypatch.setenv(name, "true") + configure_hy_runtime_environment(tmp_path) + assert environment["MEMORY_PIPELINE_LOG_ENABLED"] == "false" + assert environment["MEMORY_PIPELINE_TRACE_ENABLED"] == "false" + + +def test_live_level_change_reaches_the_hy_text_log_file(tmp_path: Path) -> None: + sdk = logging.getLogger("hy_memory") + text_log = logging.FileHandler(tmp_path / "hy_memory.log", encoding="utf-8") + text_log.setLevel(logging.INFO) + sdk.addHandler(text_log) + try: + set_diagnostic_log_level(tmp_path, "debug") + assert text_log.level == logging.DEBUG + set_diagnostic_log_level(tmp_path, "warning") + assert text_log.level == logging.WARNING + finally: + sdk.removeHandler(text_log) + text_log.close() + set_diagnostic_log_level(tmp_path, "info") def test_live_log_level_applies_to_full_hy_and_provider_call_chain( @@ -60,43 +89,9 @@ def test_info_collects_hy_info_without_enabling_debug_pipeline_content( assert logging.getLogger("openai._base_client").isEnabledFor(logging.INFO) assert not logging.getLogger("openai._base_client").isEnabledFor(logging.DEBUG) assert __import__("os").environ["MEMORY_LOG_LEVEL"] == "INFO" - assert __import__("os").environ["MEMORY_PIPELINE_TRACE_ENABLED"] == "false" assert __import__("os").environ["MEMORY_LOG_LLM_CONTENT"] == "false" -def test_live_debug_switch_makes_sdk_pipeline_writer_keep_original_content( - tmp_path: Path, -) -> None: - writer_type = import_module("hy_memory.utils.pipeline_log_writer").PipelineLogWriter - writer = writer_type(str(tmp_path / "pipeline")) - - set_diagnostic_log_level(tmp_path, "info") - writer.write_step( - request_id="info", - step="EXTRACT", - prompt="info prompt", - response="info response", - ) - set_diagnostic_log_level(tmp_path, "debug") - writer.write_step( - request_id="debug", - step="EXTRACT", - prompt="debug prompt", - response="debug response", - ) - - lines = [ - json.loads(line) - for target in (tmp_path / "pipeline").rglob("*.log") - for line in target.read_text(encoding="utf-8").splitlines() - ] - info, debug = lines - assert info["prompt"].startswith(" None: target = tmp_path / "settings" / "diagnostic-logging.json" target.parent.mkdir(parents=True) @@ -117,6 +112,7 @@ def test_configure_environment_passes_debug_content_settings_to_sdk( "MEMORY_DATA_DIR", "MEMORY_LOG_DIR", "MEMORY_LOG_LEVEL", + "MEMORY_PIPELINE_LOG_ENABLED", "MEMORY_PIPELINE_TRACE_ENABLED", "MEMORY_LOG_LLM_CONTENT", ): @@ -129,5 +125,6 @@ def test_configure_environment_passes_debug_content_settings_to_sdk( assert environment["MEMORY_DATA_DIR"] == str(memory_root) assert environment["MEMORY_LOG_DIR"] == str(memory_root / "logs") assert environment["MEMORY_LOG_LEVEL"] == "DEBUG" - assert environment["MEMORY_PIPELINE_TRACE_ENABLED"] == "true" + assert environment["MEMORY_PIPELINE_LOG_ENABLED"] == "false" + assert environment["MEMORY_PIPELINE_TRACE_ENABLED"] == "false" assert environment["MEMORY_LOG_LLM_CONTENT"] == "true" diff --git a/memhub/apps/core/tests/test_hy_sdk_log_routing.py b/memhub/apps/core/tests/test_hy_sdk_log_routing.py new file mode 100644 index 0000000..4e8cb55 --- /dev/null +++ b/memhub/apps/core/tests/test_hy_sdk_log_routing.py @@ -0,0 +1,146 @@ +"""HY SDK text logs go to hy_memory.log only, with warnings also in core.log. + +The SDK's first client adds a stdout and a stderr stream to the "hy_memory" +logger and stops it propagating. Under launchd those streams are +service.log and service-error.log, so each SDK line used to be written +twice and none reached core.log. +""" + +import logging +import sys +from logging.handlers import RotatingFileHandler +from pathlib import Path +from types import SimpleNamespace + +import pytest + +from one_memory import hy_sdk_runtime +from one_memory.log_file import ( + HY_SDK_LOGGER, + confine_hy_sdk_logging, + log_path, + start_logging_to_file, +) + + +@pytest.fixture +def sdk_logger(): + """The "hy_memory" logger as HY's setup_logging leaves it, restored after.""" + sdk = logging.getLogger(HY_SDK_LOGGER) + root = logging.getLogger() + saved = (list(sdk.handlers), sdk.propagate, sdk.level, list(root.handlers), root.level) + yield sdk + for handler in sdk.handlers: + if handler not in saved[0]: + handler.close() + for handler in root.handlers: + if handler not in saved[3]: + handler.close() + sdk.handlers, sdk.propagate, root.handlers = saved[0], saved[1], saved[3] + sdk.setLevel(saved[2]) + root.setLevel(saved[4]) + + +def _configure_like_hy(sdk: logging.Logger, log_dir: Path) -> logging.FileHandler: + log_dir.mkdir(parents=True, exist_ok=True) + text_log = logging.FileHandler(log_dir / "hy_memory.log", encoding="utf-8") + stdout = logging.StreamHandler(sys.stdout) + stderr = logging.StreamHandler(sys.stderr) + stderr.setLevel(logging.WARNING) + sdk.handlers = [text_log, stdout, stderr] + sdk.propagate = False + sdk.setLevel(logging.INFO) + return text_log + + +def test_sdk_lines_stay_in_hy_memory_log_and_warnings_reach_core_log( + tmp_path: Path, sdk_logger: logging.Logger +) -> None: + start_logging_to_file(tmp_path) + text_log = _configure_like_hy(sdk_logger, tmp_path / "hy") + + confine_hy_sdk_logging() + confine_hy_sdk_logging() + + assert not [ + handler + for handler in sdk_logger.handlers + if isinstance(handler, logging.StreamHandler) + and not isinstance(handler, logging.FileHandler) + ] + assert text_log in sdk_logger.handlers + assert len(sdk_logger.handlers) == 2, "the core.log forwarder is added once" + + child = logging.getLogger("hy_memory.client") + child.info("[add] routine sdk line") + child.warning("[add] sdk problem") + for handler in logging.getLogger().handlers: + handler.flush() + text_log.flush() + + hy_text = (tmp_path / "hy" / "hy_memory.log").read_text(encoding="utf-8") + core_text = log_path(tmp_path).read_text(encoding="utf-8") + assert "routine sdk line" in hy_text and "sdk problem" in hy_text + assert "sdk problem" in core_text + assert "routine sdk line" not in core_text + assert core_text.count("sdk problem") == 1 + + +def test_nothing_changes_before_hy_has_configured_its_logger( + tmp_path: Path, sdk_logger: logging.Logger +) -> None: + start_logging_to_file(tmp_path) + sdk_logger.handlers = [] + sdk_logger.propagate = True + + confine_hy_sdk_logging() + + assert sdk_logger.handlers == [] + + +def test_without_core_log_the_streams_are_still_dropped( + tmp_path: Path, sdk_logger: logging.Logger +) -> None: + logging.getLogger().handlers = [ + handler + for handler in logging.getLogger().handlers + if not isinstance(handler, RotatingFileHandler) + ] + text_log = _configure_like_hy(sdk_logger, tmp_path / "hy") + + confine_hy_sdk_logging() + + assert sdk_logger.handlers == [text_log] + + +@pytest.mark.parametrize("fails", [False, True]) +def test_every_client_construction_confines_the_sdk_log( + tmp_path: Path, monkeypatch, fails: bool +) -> None: + order: list[str] = [] + + class Client: + def __init__(self, **_options): + order.append("client") + if fails: + raise RuntimeError("construction failed") + + monkeypatch.setattr(hy_sdk_runtime, "HyMemoryClient", Client) + monkeypatch.setattr(hy_sdk_runtime, "build_sdk_config", lambda *_a, **_k: SimpleNamespace()) + monkeypatch.setattr(hy_sdk_runtime, "inspect_graph_width_mismatch", lambda _c: None) + monkeypatch.setattr(hy_sdk_runtime, "_acquire_runtime", lambda _c, _k: object()) + monkeypatch.setattr(hy_sdk_runtime, "_release_runtime", lambda _k: None) + monkeypatch.setattr(hy_sdk_runtime, "confine_hy_sdk_logging", lambda: order.append("confine")) + profile = SimpleNamespace(embedding_provider_kind=None, provider_kind=None) + + if fails: + with pytest.raises(RuntimeError): + hy_sdk_runtime._acquire_client( + profile, api_key=None, data_dir=tmp_path, http_transport_factory=None + ) + else: + hy_sdk_runtime._acquire_client( + profile, api_key=None, data_dir=tmp_path, http_transport_factory=None + ) + + assert order == ["client", "confine"] diff --git a/memhub/apps/core/tests/test_memory_library_all_scenes.py b/memhub/apps/core/tests/test_memory_library_all_scenes.py index 439aa18..d53dd41 100644 --- a/memhub/apps/core/tests/test_memory_library_all_scenes.py +++ b/memhub/apps/core/tests/test_memory_library_all_scenes.py @@ -6,6 +6,7 @@ and delete pass the memory's kind/variant through to the SDK. """ import asyncio +from contextlib import asynccontextmanager import pytest from httpx import ASGITransport, AsyncClient @@ -55,6 +56,9 @@ def chat_row(memory_id, content, *, source="cursor"): } +EXPERIENCE_MEMORY_AT = 1_789_990_000 + + def experience_row(memory_id, task, solution, *, variant="working", source="codebuddy"): return { "experience_id": memory_id, @@ -63,6 +67,8 @@ def experience_row(memory_id, task, solution, *, variant="working", source="code "task": task, "solution": solution, "source": source, + # Conversation time, epoch seconds like chat (hy-memory 2.0.7). + "memory_at": EXPERIENCE_MEMORY_AT, "created_at": "2026-10-01T08:00:00", "updated_at": "2026-10-02T08:00:00", "_variant": variant, @@ -305,12 +311,13 @@ def run_with_sdk(tmp_path, monkeypatch, scenario): async def close(self): return None + @asynccontextmanager async def write_client(): - return sdk + yield sdk async with app.router.lifespan_context(app): app.state.sdk_client_handle = Handle() - monkeypatch.setattr(app.state.sdk_write_coordinator, "client", write_client) + monkeypatch.setattr(app.state.sdk_write_coordinator, "use_client", write_client) async with client_for(app) as client: await scenario(app, sdk, client) @@ -446,6 +453,7 @@ def test_keyword_filter_reads_experience_and_fact_text(tmp_path, monkeypatch): assert experience["content"] == "Fix flaky tests\nPin the pytest seed" assert experience["status"] == "active" assert experience["updated_at"] > experience["created_at"] + assert experience["memory_at"] == EXPERIENCE_MEMORY_AT fact = by_id["fact-1"] assert (fact["scene"], fact["kind"], fact["variant"]) == ("coding", "fact", "coding") assert fact["content"] == "The pytest suite runs in CI" @@ -488,6 +496,10 @@ def test_empty_query_lists_all_scenes_with_source_filter_and_totals(tmp_path, mo "chat", "chat", ] + assert [item["memory_at"] for item in body["memories"][:2]] == [ + EXPERIENCE_MEMORY_AT, + EXPERIENCE_MEMORY_AT, + ] call = sdk.list_calls[0] assert call["scene"] == "all" assert call["include_sources"] is None @@ -527,6 +539,7 @@ def test_detail_edit_delete_pass_kind_and_variant(tmp_path, monkeypatch): assert record["task"] == "Old task" assert record["solution"] == "Old solution" assert record["content"] == "Old task\nOld solution" + assert record["memory_at"] == EXPERIENCE_MEMORY_AT assert sdk.get_calls[-1] == ("exp-1", "experience", "working") # Chat detail with no namespace keeps the plain SDK call. @@ -692,5 +705,6 @@ def test_home_summary_counts_what_the_memory_page_lists(tmp_path, monkeypatch): assert (home_list["offset"], home_list["limit"], home_list["order"]) == (0, 1, "desc") assert body["latest"]["memory_id"] == "exp-w" assert body["latest"]["scene"] == "working" + assert body["latest"]["memory_at"] == EXPERIENCE_MEMORY_AT run_with_sdk(tmp_path, monkeypatch, scenario) diff --git a/memhub/apps/core/tests/test_memory_server_durable_queue.py b/memhub/apps/core/tests/test_memory_server_durable_queue.py index df5d410..062accc 100644 --- a/memhub/apps/core/tests/test_memory_server_durable_queue.py +++ b/memhub/apps/core/tests/test_memory_server_durable_queue.py @@ -1187,6 +1187,167 @@ def test_the_drain_tick_writes_a_quiet_live_conversation(tmp_path, monkeypatch) assert flushed +class _SwitchableProfiles: + """Active profile identity that a test can change mid-write.""" + + def __init__(self) -> None: + self.identity = ("profile-a", 1) + + def active_identity(self): + return self.identity + + def snapshot(self, profile_id, revision): + return type( + "Snapshot", (), {"profile_id": profile_id, "revision": revision, "has_api_key": False} + )() + + def resolve_snapshot_secret(self, *_args): + return None + + +class _TrackedHandle: + def __init__(self, profile, **_kwargs) -> None: + self.profile_id = profile.profile_id + self.closed = False + + async def client(self): + return self + + async def close(self): + self.closed = True + + +def _coordinator(monkeypatch, opened: list[_TrackedHandle]): + from one_memory import sdk_write_processor + + def handle(profile, **kwargs): + value = _TrackedHandle(profile, **kwargs) + opened.append(value) + return value + + monkeypatch.setattr(sdk_write_processor, "SdkClientHandle", handle) + profiles = _SwitchableProfiles() + coordinator = sdk_write_processor.SdkWriteCoordinator( + profiles=profiles, # type: ignore[arg-type] + secrets=None, # type: ignore[arg-type] + data_dir=None, + transport_factory=lambda _profile: None, + sedimentation_enabled=lambda: True, + ) + return coordinator, profiles + + +def test_a_profile_change_does_not_close_the_client_of_a_write_in_flight(monkeypatch) -> None: + """Build 35 lost a clean install's first write as unknown (AttributeError). + + Saving a model profile changed the active identity while the write ran on + the old profile's client. The next coordinator call closed that client at + once: the SDK cleared its stores and the SharedRuntime closed mid-`add`. + """ + from one_memory import sdk_write_processor + + opened: list[_TrackedHandle] = [] + coordinator, profiles = _coordinator(monkeypatch, opened) + seen: list[tuple[str, bool]] = [] + writing = asyncio.Event() + + async def process(self, records, *, request_id, before_hy_invocation): + client = await self._client_handle.client() + await before_hy_invocation() + seen.append((client.profile_id, client.closed)) + if client.profile_id == "profile-a": + await writing.wait() + # Still open while its own write runs. + seen.append((client.profile_id, client.closed)) + return sdk_write_processor.SdkWriteReceipt() + + monkeypatch.setattr(sdk_write_processor.SdkWriteProcessor, "process_sdk_job", process) + + async def noop(): + return None + + async def scenario(): + first = asyncio.create_task( + coordinator.process_sdk_job((), request_id="a", before_hy_invocation=noop) + ) + while not seen: + await asyncio.sleep(0) + profiles.identity = ("profile-b", 2) + # A second job and an inquiry under the new profile. + await coordinator.process_sdk_job((), request_id="b", before_hy_invocation=noop) + assert [handle.closed for handle in opened] == [False, False] + writing.set() + await first + old, new = opened + # Retired after its last use, and new work used the new profile. + assert old.closed is True and new.closed is False + await coordinator.close() + assert new.closed is True + + asyncio.run(scenario()) + assert seen == [ + ("profile-a", False), + ("profile-b", False), + ("profile-b", False), + ("profile-a", False), + ] + + +def test_an_unused_stale_handle_still_closes_at_once(monkeypatch) -> None: + opened: list[_TrackedHandle] = [] + coordinator, profiles = _coordinator(monkeypatch, opened) + + async def scenario(): + async with coordinator.use_client() as client: + assert client.profile_id == "profile-a" + assert opened[0].closed is False + profiles.identity = ("profile-b", 2) + async with coordinator.use_client() as client: + assert client.profile_id == "profile-b" + assert opened[0].closed is True + assert opened[1].closed is False + await coordinator.close() + assert opened[1].closed is True + + asyncio.run(scenario()) + + +def test_a_client_that_fails_to_construct_parks_the_job_instead_of_unknown(tmp_path) -> None: + """Nothing was sent when the client could not be built, so it retries on its own.""" + from one_memory.sdk_write_processor import SdkWriteProcessor + + class _BrokenHandle: + async def client(self): + raise AttributeError("'RustBindingsAPI' object has no attribute 'bindings'") + + path = tmp_path / "one-memory.sqlite3" + queue = DurableWriteQueue(path) + record = queue.submit(_request()) + _claim_through_drain(queue, record.job_id) + + class _Supervisor: + async def process_sdk_job(self, _records, **kwargs): + return await SdkWriteProcessor(_BrokenHandle()).process_sdk_job( # type: ignore[arg-type] + (_sdk_evidence("e1"),), **kwargs + ) + + asyncio.run( + execute_job( + record.job_id, + queue=queue, + supervisor=_Supervisor(), + evidence=_EvidenceStore({"e1"}), + ) + ) + + [row] = _rows(path) + assert (row["state"], row["hy_invoked"]) == (WAITING_FOR_MODEL, 0) + assert row["last_error"] == "hy_memory_client_unavailable" + later = datetime.now(UTC) + timedelta(minutes=5) + assert queue.readmit_model_waiters(now=later) == 1 + assert _state(path, record.job_id) == PENDING + + def test_sdk_unknown_outcome_inquiry_uses_only_public_receipt() -> None: from one_memory.sdk_write_processor import SdkWriteProcessor, SdkWriteReceipt @@ -1699,6 +1860,46 @@ def test_a_raw_provider_message_is_never_stored_as_the_error(tmp_path) -> None: assert stored == "RuntimeError" +def test_a_failed_job_logs_where_it_failed_but_never_the_message(tmp_path, caplog) -> None: + """`error_code=AttributeError` alone named no location; frames, never the message.""" + path = tmp_path / "one-memory.sqlite3" + queue = DurableWriteQueue(path) + record = queue.submit(_request()) + _claim_through_drain(queue, record.job_id) + + def closed_store(client): + return client.private_store_name.write + + class _Failing: + async def process_sdk_job(self, _records, **kwargs): + await kwargs["before_hy_invocation"]() + try: + closed_store(type("Client", (), {"private_store_name": None})()) + except AttributeError as error: + raise RuntimeError("quoting 'my secret diary'") from error + + with caplog.at_level(logging.ERROR, logger="one_memory.memory_server.durable_queue"): + asyncio.run( + execute_job( + record.job_id, + queue=queue, + supervisor=_Failing(), + evidence=_EvidenceStore({"e1"}), + ) + ) + + [line] = [ + message.getMessage() + for message in caplog.records + if "durable_write_job_failed" in message.getMessage() + ] + assert f"job_id={record.job_id} error_code=RuntimeError chain=RuntimeError@" in line + assert ";AttributeError@" in line + assert "test_memory_server_durable_queue.py:" in line and ":closed_store" in line + assert "secret diary" not in line + assert "private_store_name" not in line + + def test_a_machine_error_code_is_preserved(tmp_path) -> None: """Recognised codes survive; only free-form text is dropped.""" from one_memory.memory_server.durable_queue import safe_error_code diff --git a/memhub/apps/core/tests/test_sdk_client_construction.py b/memhub/apps/core/tests/test_sdk_client_construction.py new file mode 100644 index 0000000..93f828a --- /dev/null +++ b/memhub/apps/core/tests/test_sdk_client_construction.py @@ -0,0 +1,61 @@ +"""SDK clients of one home are constructed one at a time. + +Build 35, clean install: right after the model was activated, the write +drain's client and a UI read client started in the same second. Each opened +Chroma on the same empty vector directory, Chroma's shared System cache has +no lock around that first open, and neither client reached `VectorStore +ready`. The first write job was lost as unknown. +""" + +import threading +import time + +from one_memory import hy_sdk_runtime +from one_memory.hy_sdk_runtime import acquire_client, builtin_retrieval_snapshot + + +def test_two_clients_on_a_fresh_home_are_constructed_one_at_a_time(tmp_path, monkeypatch): + real = hy_sdk_runtime.HyMemoryClient + state = {"inside": 0, "most": 0} + count = threading.Lock() + + def recording_client(**options): + with count: + state["inside"] += 1 + state["most"] = max(state["most"], state["inside"]) + try: + # Widen the window two unserialized constructors would share. + time.sleep(0.2) + return real(**options) + finally: + with count: + state["inside"] -= 1 + + monkeypatch.setattr(hy_sdk_runtime, "HyMemoryClient", recording_client) + start = threading.Barrier(2) + leases: list[hy_sdk_runtime.ClientLease] = [] + failures: list[BaseException] = [] + + def open_client(): + start.wait() + try: + leases.append( + acquire_client(builtin_retrieval_snapshot(), api_key=None, data_dir=tmp_path) + ) + except BaseException as error: # noqa: BLE001 - reported below + failures.append(error) + + threads = [threading.Thread(target=open_client) for _ in range(2)] + for thread in threads: + thread.start() + for thread in threads: + thread.join(120) + try: + assert failures == [] + assert len(leases) == 2 + assert state["most"] == 1 + for lease in leases: + assert lease.client.memory_stats(user_id="local") is not None + finally: + for lease in leases: + lease.close() diff --git a/memhub/apps/core/tests/test_sdk_data_plane_migration.py b/memhub/apps/core/tests/test_sdk_data_plane_migration.py index b0fb64e..e098376 100644 --- a/memhub/apps/core/tests/test_sdk_data_plane_migration.py +++ b/memhub/apps/core/tests/test_sdk_data_plane_migration.py @@ -37,6 +37,7 @@ from one_memory.sdk_migration_runner import ( abandoned_legacy_work, commit_sdk_cutover, move_pending_dispatches, + prepare_legacy_work_for_cutover, prepare_legacy_write_queue_for_cutover, recover_abandoned_staging, resume_legacy_cleanup, @@ -137,19 +138,38 @@ def test_post_cutover_metadata_repair_restores_source_and_original_times(store): ) coding = data_dir / "hy-memory" / "governed-v2" / "coding_cv.sqlite3" with sqlite3.connect(coding) as database: - database.execute( - "CREATE TABLE coding_memory_meta (" - "experience_id TEXT,user_id TEXT,agent_id TEXT,solution TEXT," - "source TEXT,created_at TEXT,updated_at TEXT)" + # A store written by hy-memory 2.0.6, before the conversation time + # column: the repair must add it through the SDK and then fill it. + database.executescript( + """ + CREATE TABLE coding_memory_meta ( + experience_id TEXT PRIMARY KEY, user_id TEXT NOT NULL, + agent_id TEXT NOT NULL DEFAULT 'default_agent', task TEXT NOT NULL, + search_keys TEXT NOT NULL DEFAULT '[]', solution TEXT NOT NULL, + boundary_envs TEXT NOT NULL DEFAULT '', workspace_id TEXT, + branch TEXT, session_id TEXT, files TEXT NOT NULL DEFAULT '[]', + source_fact_ids TEXT NOT NULL DEFAULT '[]', + confidence REAL NOT NULL DEFAULT 0.7, + source TEXT NOT NULL DEFAULT 'default', + extraction_source TEXT NOT NULL DEFAULT 'auto_extract', + created_at TEXT NOT NULL, updated_at TEXT NOT NULL + ); + CREATE TABLE working_fact ( + fact_id TEXT PRIMARY KEY, user_id TEXT NOT NULL, + agent_id TEXT NOT NULL DEFAULT 'default_agent', session_id TEXT, + workspace_id TEXT, branch TEXT, source TEXT NOT NULL DEFAULT 'default', + statement TEXT NOT NULL, files TEXT NOT NULL DEFAULT '[]', + subject TEXT NOT NULL DEFAULT '', details TEXT NOT NULL DEFAULT '', + fact_link TEXT, derived_experience_ids TEXT NOT NULL DEFAULT '[]', + status TEXT NOT NULL DEFAULT 'active', + fact_chain_summary TEXT NOT NULL DEFAULT '', created_at TEXT NOT NULL + ); + """ ) database.execute( - "CREATE TABLE working_fact (" - "fact_id TEXT,user_id TEXT,agent_id TEXT,statement TEXT," - "source TEXT,created_at TEXT)" - ) - database.execute( - "INSERT INTO coding_memory_meta VALUES " - "('sdk-1','local','scope','remember','default','now','now')" + "INSERT INTO coding_memory_meta " + "(experience_id,user_id,agent_id,task,solution,source,created_at,updated_at) " + "VALUES ('sdk-1','local','scope','remember','remember','default','now','now')" ) result = repair_sdk_metadata_from_bundle( @@ -168,10 +188,11 @@ def test_post_cutover_metadata_repair_restores_source_and_original_times(store): 2026, 10, 18, tzinfo=UTC ) with sqlite3.connect(coding) as database: - source, created_at = database.execute( - "SELECT source,created_at FROM coding_memory_meta WHERE experience_id='sdk-1'" + source, memory_at, created_at = database.execute( + "SELECT source,memory_at,created_at FROM coding_memory_meta WHERE experience_id='sdk-1'" ).fetchone() assert source == "workbuddy" + assert datetime.fromtimestamp(memory_at, tz=UTC) == datetime(2026, 10, 17, tzinfo=UTC) assert created_at.startswith("2026-10-18T00:00:00") repeated = repair_sdk_metadata_from_bundle( @@ -876,6 +897,116 @@ def test_legacy_work_that_may_have_reached_the_sdk_does_not_block_cutover(tmp_pa assert store.authority() is MemoryAuthority.SDK +def test_pre_upgrade_unknown_writes_are_settled_at_cutover_not_retried(store): + """A migrated 1.0.4 home kept 1000+ jobs unknown forever. + + The legacy pipeline invoked them, so the SDK's write-outcome inquiry knows + none of them and the automatic reconcile could never settle one. + """ + from one_memory.memory_server.durable_queue import ( + CANCELLED, + PENDING, + RUNNING, + UNKNOWN, + ) + + queue = DurableWriteQueue(store.database_path) + + def job(key: str, state: str, *, invoked: bool) -> str: + identifier = queue.submit( + WriteRequest( + internal_session_id="session-1", + source_id="cursor", + batch_identity=BatchIdentity( + internal_session_id="session-1", first_round=1, last_round=1 + ), + evidence_ids=["gone"], + idempotency_key=key, + ) + ).job_id + with main_database(store.database_path).write() as database, database: + database.execute( + "UPDATE memory_write_jobs SET state=?,hy_invoked=?," + "last_error='model_content_outcome_unknown' WHERE job_id=?", + (state, int(invoked), identifier), + ) + return identifier + + # Their Evidence is gone too, which must not block the cutover. + unknown = [job(f"unknown-{index}", UNKNOWN, invoked=True) for index in range(3)] + sent_running = job("sent-running", RUNNING, invoked=True) + finished = job("finished", "completed", invoked=True) + + first = prepare_legacy_work_for_cutover(store.database_path) + assert first.abandoned == {"unknown_write_jobs": 4} + # Resumed after an interruption: nothing changes, the count is the same. + again = prepare_legacy_work_for_cutover(store.database_path) + assert again.as_document() == first.as_document() + + with main_database(store.database_path).read() as database: + rows = dict( + (str(row[0]), (str(row[1]), str(row[2]), int(row[3]))) + for row in database.execute( + "SELECT job_id,state,last_error,hy_invoked FROM memory_write_jobs" + ) + ) + for identifier in (*unknown, sent_running): + assert rows[identifier] == (CANCELLED, "abandoned_at_cutover", 1) + assert rows[finished][0] == "completed" + surviving = DurableWriteQueue(store.database_path, sdk_authority=True) + assert surviving.unknown_jobs() == () + # Never requeued: they may already have written. + assert surviving.retry_unknown_confirmed(unknown[0]) == 0 + assert surviving.readmit_parked() == 0 + assert PENDING not in {state for state, _, _ in rows.values()} + + +def test_retrying_unknown_writes_works_after_the_legacy_tables_are_dropped(store): + """The retry button raised `no such table: memory_tasks` after an upgrade.""" + from one_memory.memory_server.durable_queue import PENDING, UNKNOWN + from one_memory.target_schema import drop_legacy_tables + + queue = DurableWriteQueue(store.database_path) + identifier = queue.submit( + WriteRequest( + internal_session_id="session-1", + source_id="cursor", + batch_identity=BatchIdentity( + internal_session_id="session-1", first_round=1, last_round=1 + ), + evidence_ids=["e1"], + idempotency_key="after-upgrade", + ) + ).job_id + drop_legacy_tables(store.database_path) + assert legacy_tables_present(store.database_path) == () + old = datetime(2000, 1, 1, tzinfo=UTC).isoformat() + + def make_unknown(code: str, attempts: int) -> None: + with main_database(store.database_path).write() as database, database: + database.execute( + "UPDATE memory_write_jobs SET state=?,hy_invoked=1,last_error=?," + "attempts=?,updated_at=? WHERE job_id=?", + (UNKNOWN, code, attempts, old, identifier), + ) + + for sdk_authority in (True, False): + surviving = DurableWriteQueue(store.database_path, sdk_authority=sdk_authority) + make_unknown("model_content_outcome_unknown", 1) + assert surviving.resolve_unknown_from_linked_output(identifier) is False + assert surviving.retry_unknown_confirmed(identifier) == 1 + assert surviving.get("after-upgrade").state == PENDING + + make_unknown("hy_memory_timeout", 1) + since = datetime.now(UTC) + assert surviving.retry_timed_out_unknown_after_reconcile(older_than=since) == 1 + make_unknown("model_content_outcome_unknown", 1) + assert surviving.retry_first_unknown_after_reconcile(older_than=since) == 1 + if sdk_authority: + # The SDK-authority queue never brings a dropped table back. + assert legacy_tables_present(store.database_path) == () + + def _protective(home: Path) -> Path: return home / "hy-memory" / ".governed-v2.pre-migration-0123456789abcdef" diff --git a/memhub/apps/core/tests/test_sdk_migration_bundle.py b/memhub/apps/core/tests/test_sdk_migration_bundle.py index 19381b4..5f06d89 100644 --- a/memhub/apps/core/tests/test_sdk_migration_bundle.py +++ b/memhub/apps/core/tests/test_sdk_migration_bundle.py @@ -91,7 +91,7 @@ def test_bundle_contains_management_sdk_config_and_verified_manifest(tmp_path): assert manifest["bundle_id"] == "migration-1" assert manifest["sdk_namespace"] == "governed-v2" assert manifest["runtime_build"] == "build-13" - assert manifest["snapshot_sdk_version"] == "2.0.6" + assert manifest["snapshot_sdk_version"] == "2.0.8" paths = {item["path"]: item for item in manifest["files"]} assert { "management/one-memory.sqlite3", diff --git a/memhub/apps/core/uv.lock b/memhub/apps/core/uv.lock index 83e11dd..64584a9 100644 --- a/memhub/apps/core/uv.lock +++ b/memhub/apps/core/uv.lock @@ -991,7 +991,7 @@ wheels = [ [[package]] name = "hy-memory" -version = "2.0.6" +version = "2.0.8" source = { registry = "https://pypi.org/simple" } dependencies = [ { name = "chromadb" }, @@ -1008,9 +1008,9 @@ dependencies = [ { name = "scikit-learn" }, { name = "tiktoken" }, ] -sdist = { url = "https://files.pythonhosted.org/packages/18/98/312ac8bcbe41e63200a93d296300b2e6748e1a532dad01f009dad57ba408/hy_memory-2.0.6.tar.gz", hash = "sha256:d0f54d54867ee7e722a8dd1a88a00c0576904435f15ae7899fe640840bff74bc", size = 855200, upload-time = "2026-10-27T07:53:10.022Z" } +sdist = { url = "https://files.pythonhosted.org/packages/21/15/83ca83b649ead238f186fdb33efdc73615fbba279efbbdca3857c1a86beb/hy_memory-2.0.8.tar.gz", hash = "sha256:0fa0ed1a1160b389a3d7c13a9fb6528b140d7ec23cf49e65f1be5974820a576b", size = 856025, upload-time = "2026-10-28T07:35:47.783Z" } wheels = [ - { url = "https://files.pythonhosted.org/packages/27/f1/d4866cffe426d77b857168cc694b15df866f3d9f45152c17c148e1595db4/hy_memory-2.0.6-py3-none-any.whl", hash = "sha256:b0e666f8e89d1763bb31c0e67502df74434134a638ff6fd1912de9e936be2483", size = 918955, upload-time = "2026-10-27T07:53:07.686Z" }, + { url = "https://files.pythonhosted.org/packages/11/6a/c699cac0ff06bd089fceeff90446130763d8187e649dbdb0313014491a10/hy_memory-2.0.8-py3-none-any.whl", hash = "sha256:68bd789df24e51e64bb231e97a8d24ee89b4aa5f9ba14c3e0824589e9213bf7c", size = 921119, upload-time = "2026-10-28T07:35:45.571Z" }, ] [[package]] @@ -1837,7 +1837,7 @@ requires-dist = [ { name = "fastapi", specifier = ">=0.141.1" }, { name = "filelock", specifier = ">=3.32.4" }, { name = "httpx", specifier = ">=0.28.1" }, - { name = "hy-memory", specifier = "==2.0.6" }, + { name = "hy-memory", specifier = "==2.0.8" }, { name = "keyring", specifier = ">=25.7.0" }, { name = "numpy", specifier = "==2.5.2" }, { name = "onnxruntime", specifier = "==1.23.2" }, diff --git a/memhub/apps/desktop/src/diagnostics-ipc.test.ts b/memhub/apps/desktop/src/diagnostics-ipc.test.ts index 3364a75..c84b856 100644 --- a/memhub/apps/desktop/src/diagnostics-ipc.test.ts +++ b/memhub/apps/desktop/src/diagnostics-ipc.test.ts @@ -230,39 +230,21 @@ it("filters raw Core INFO and DEBUG while preserving warnings and errors", async ).toBe(true); }); -it("shows HY pipeline metrics without exposing model content", async () => { - const dataDir = await mkdtemp( - path.join(os.tmpdir(), "om-debug-hy-pipeline-"), - ); +it("does not read HY's own log directory", async () => { + // MemHub turns the HY pipeline log off; files left by older builds and + // HY's text log stay on disk but are not part of the Debug panel. + const dataDir = await mkdtemp(path.join(os.tmpdir(), "om-debug-hy-logs-")); roots.push(dataDir); - const pipelineDir = path.join( - dataDir, - "hy-memory", - "governed-v2", - "logs", - "default", - ); - await mkdir(pipelineDir, { recursive: true }); - const target = path.join(pipelineDir, "2026-10-14.log"); - await writeFile(target, ""); + const hyLogs = path.join(dataDir, "hy-memory", "governed-v2", "logs"); + await mkdir(path.join(hyLogs, "default"), { recursive: true }); const cursor = await captureDebugLogCursor(dataDir); - const pipelineEntry = { - request_id: "request-safe-1", - user_id: "private-user", - agent_id: "private-agent", - session_id: "private-session", - step: "EXTRACT", - prompt: "private prompt", - content: "private response", - parsed: "private parsed output", - tokens: 42, - elapsed_ms: 123.5, - timestamp: "2026-10-14T10:01:00.000", - }; - await appendFile(target, `${JSON.stringify(pipelineEntry)}\n`); await writeFile( - path.join(dataDir, "hy-memory", "governed-v2", "logs", "hy_memory.log"), - `${JSON.stringify({ ...pipelineEntry, request_id: "must-not-appear" })}\n`, + path.join(hyLogs, "default", "2026-10-14.log"), + `${JSON.stringify({ request_id: "old-pipeline", step: "EXTRACT" })}\n`, + ); + await writeFile( + path.join(hyLogs, "hy_memory.log"), + "2026-10-14 10:01:00 [WARNING] [-] hy_memory.client: hy text log\n", ); const snapshot = await readDebugLogSnapshot( @@ -271,29 +253,11 @@ it("shows HY pipeline metrics without exposing model content", async () => { cursor, ); - expect(snapshot.entries).toEqual([ - expect.objectContaining({ - service: "hy-memory", - component: "hy.pipeline", - event: "hy.pipeline.extract", - message: "EXTRACT · 42 tokens · 124 ms", - duration_ms: 123.5, - trace_id: "request-safe-1", - details: { phase: "EXTRACT", count: 42 }, - source: "pipeline", - }), - ]); - const serialized = JSON.stringify(snapshot); - for (const secret of [ - "private prompt", - "private response", - "private parsed output", - "private-user", - "private-agent", - "private-session", - ]) { - expect(serialized).not.toContain(secret); - } + expect(snapshot.entries).toEqual([]); + expect(cursor).toEqual({ + diagnosticLogs: [], + serviceLogs: expect.any(Array), + }); }); it("logs a renderer ui-action with action, page, phase and the shared trace id", async () => { diff --git a/memhub/apps/desktop/src/diagnostics-ipc.ts b/memhub/apps/desktop/src/diagnostics-ipc.ts index e84295b..a11ca9b 100644 --- a/memhub/apps/desktop/src/diagnostics-ipc.ts +++ b/memhub/apps/desktop/src/diagnostics-ipc.ts @@ -18,7 +18,6 @@ const UI_TRACE = "one-memory:log-ui-trace"; const DEBUG_LOGS = "one-memory:get-debug-logs"; const DEBUG_LOG_NAME = /^diagnostic-(runtime|core|host-bridge|desktop|cli)\.jsonl(?:\.\d+)?$/; -const PIPELINE_LOG_NAME = /^\d{4}-\d{2}-\d{2}\.log$/; const SERVICE_LOG_NAMES = [ "service.log", "service-error.log", @@ -30,24 +29,16 @@ interface ServiceLogCursor { files: Array<{ device: number; inode: number; offset: number }>; } -interface PipelineLogCursor { - relativePath: string; - device: number; - inode: number; - offset: number; -} - export interface DebugLogCursor { diagnosticLogs: Array<{ device: number; inode: number; offset: number }>; serviceLogs: ServiceLogCursor[]; - pipelineLogs: PipelineLogCursor[]; } export interface DebugLogEntry { id: string; timestamp: string; level: "debug" | "info" | "warn" | "error"; - service: "runtime" | "core" | "host-bridge" | "desktop" | "cli" | "hy-memory"; + service: "runtime" | "core" | "host-bridge" | "desktop" | "cli"; component: string; event: string; outcome: string; @@ -57,7 +48,7 @@ export interface DebugLogEntry { trace_id?: string; details?: Record; message?: string; - source: "diagnostic" | "stdout" | "stderr" | "pipeline"; + source: "diagnostic" | "stdout" | "stderr"; } export interface DebugLogSnapshot { @@ -259,7 +250,6 @@ export async function readDebugLogSnapshot( cursor: DebugLogCursor = { diagnosticLogs: [], serviceLogs: [], - pipelineLogs: [], }, ): Promise { const started = Number.isFinite(startedAt) ? startedAt : Date.now(); @@ -300,7 +290,6 @@ export async function readDebugLogSnapshot( ); } } - entries.push(...(await readPipelineLogEntries(dataDir, cursor, started))); entries.sort((left, right) => left.timestamp === right.timestamp ? left.id.localeCompare(right.id) @@ -319,7 +308,6 @@ export async function captureDebugLogCursor( ): Promise { const directory = path.join(dataDir, "logs"); const names = await readdir(directory).catch(() => []); - const pipelineRoot = path.join(dataDir, "hy-memory", "governed-v2", "logs"); return { diagnosticLogs: ( await Promise.all( @@ -355,7 +343,6 @@ export async function captureDebugLogCursor( }; }), ), - pipelineLogs: await pipelineLogFiles(pipelineRoot), }; } @@ -462,8 +449,8 @@ async function readServiceLogEntries( if (!message) continue; const level = serviceLogLevel(message, cursor.name); // Raw stdout is an implementation trace, not a product event. Core's - // structured diagnostics and HY pipeline logs already carry meaningful - // successful work with request/task identity. Showing raw INFO/DEBUG + // structured diagnostics already carry meaningful successful work with + // request/task identity. Showing raw INFO/DEBUG // here duplicated those events and turned polling access logs, file // watchers and library initialization into thousands of fake "useful" // rows. Keep raw output only when it needs attention. @@ -543,135 +530,6 @@ function logLineTimestamp( return new Date(Math.max(startedAt, fallback)).toISOString(); } -async function pipelineLogFiles(root: string): Promise { - const rootInfo = await lstat(root).catch(() => null); - if (!rootInfo?.isDirectory() || rootInfo.isSymbolicLink()) return []; - const files: PipelineLogCursor[] = []; - const visit = async (directory: string): Promise => { - for (const entry of await readdir(directory, { withFileTypes: true })) { - const target = path.join(directory, entry.name); - if (entry.isSymbolicLink()) continue; - if (entry.isDirectory()) { - await visit(target); - continue; - } - // The same root also contains HY's human-readable hy_memory.log. - // Pipeline files are date-named JSONL; accepting every .log file makes - // the Debug poller repeatedly parse unrelated text and still display no - // HY entries. - if (!entry.isFile() || !PIPELINE_LOG_NAME.test(entry.name)) continue; - const info = await safeRegularFile(target); - if (!info) continue; - files.push({ - relativePath: path.relative(root, target), - device: info.dev, - inode: info.ino, - offset: info.size, - }); - } - }; - await visit(root); - return files; -} - -async function readPipelineLogEntries( - dataDir: string, - cursor: DebugLogCursor, - startedAt: number, -): Promise { - const root = path.join(dataDir, "hy-memory", "governed-v2", "logs"); - const current = await pipelineLogFiles(root); - const baseline = new Map( - cursor.pipelineLogs.map((file) => [ - `${file.device}:${file.inode}`, - file.offset, - ]), - ); - const entries: DebugLogEntry[] = []; - for (const file of current) { - const target = path.join(root, file.relativePath); - const offset = baseline.get(`${file.device}:${file.inode}`) ?? 0; - const info = await safeRegularFile(target); - if (!info || info.size <= offset) continue; - const content = await readFileFromOffset(target, offset).catch(() => ""); - let lineNumber = 0; - for (const line of content.split("\n")) { - lineNumber += 1; - if (!line.trim()) continue; - const entry = pipelineLogEntry( - line, - file, - lineNumber, - offset, - startedAt, - info.mtimeMs, - ); - if (entry) entries.push(entry); - } - } - return entries; -} - -function pipelineLogEntry( - line: string, - file: PipelineLogCursor, - lineNumber: number, - offset: number, - startedAt: number, - fallbackTime: number, -): DebugLogEntry | null { - let value: Record; - try { - value = JSON.parse(line) as Record; - } catch { - return null; - } - const step = typeof value.step === "string" ? value.step.trim() : ""; - if (!step || !/^[A-Za-z0-9_-]{1,80}$/.test(step)) return null; - const rawTimestamp = - typeof value.timestamp === "string" ? value.timestamp : ""; - const parsedTimestamp = Date.parse(rawTimestamp); - const timestamp = new Date( - Math.max( - startedAt, - Number.isFinite(parsedTimestamp) ? parsedTimestamp : fallbackTime, - ), - ).toISOString(); - const elapsed = safeFiniteNumber(value.elapsed_ms); - const tokens = safeFiniteNumber(value.tokens); - const requestId = - typeof value.request_id === "string" && value.request_id.length <= 256 - ? value.request_id - : undefined; - return { - id: `hy-pipeline:${file.device}:${file.inode}:${offset}:${lineNumber}`, - timestamp, - level: "info", - service: "hy-memory", - component: "hy.pipeline", - event: `hy.pipeline.${step.toLowerCase().replaceAll("_", "-")}`, - outcome: "observed", - ...(elapsed === undefined ? {} : { duration_ms: elapsed }), - ...(requestId ? { trace_id: requestId } : {}), - details: { - phase: step, - ...(tokens === undefined ? {} : { count: tokens }), - }, - message: [ - step, - ...(tokens === undefined ? [] : [`${Math.round(tokens)} tokens`]), - ...(elapsed === undefined ? [] : [`${Math.round(elapsed)} ms`]), - ].join(" · "), - source: "pipeline", - }; -} - -function safeFiniteNumber(value: unknown): number | undefined { - return typeof value === "number" && Number.isFinite(value) - ? value - : undefined; -} - export function installDiagnosticsIpc( options: DiagnosticIpcOptions, ): () => void { diff --git a/memhub/apps/desktop/src/host-control-ownership.test.ts b/memhub/apps/desktop/src/host-control-ownership.test.ts index 67b6be5..993fd5f 100644 --- a/memhub/apps/desktop/src/host-control-ownership.test.ts +++ b/memhub/apps/desktop/src/host-control-ownership.test.ts @@ -15,6 +15,7 @@ const fake = vi.hoisted(() => ({ missingBroker: false, hostCapability: true, open: vi.fn(), + refreshHosts: vi.fn(async (_layouts: unknown, _options: unknown) => ({})), host: vi.fn< (input: { hostId: string; @@ -274,7 +275,9 @@ beforeEach(async () => { fake.open.mockResolvedValue({ hostGrantStore: {}, repairInstalledCommand: vi.fn(async () => []), + refreshInstalledHosts: fake.refreshHosts, }); + fake.refreshHosts.mockClear(); fake.host.mockResolvedValue({ state: "synthetic-remote-result" }); Object.defineProperty(process, "resourcesPath", { configurable: true, @@ -590,5 +593,11 @@ describe("packaged Desktop host-control ownership", () => { expect(fake.ensureRuntime).not.toHaveBeenCalled(); expect(fake.createClient).not.toHaveBeenCalled(); expect(fake.windows).toHaveLength(1); + // The embedded Runtime is this process, so Desktop refreshes the hosts + // it installed once the Runtime is up, as a standalone one would itself. + expect(fake.refreshHosts).toHaveBeenCalledTimes(1); + expect(fake.refreshHosts.mock.calls[0]?.[1]).toMatchObject({ + diagnostics: expect.anything(), + }); }); }); diff --git a/memhub/apps/desktop/src/host-permissions.test.ts b/memhub/apps/desktop/src/host-permissions.test.ts index 6593032..f2be754 100644 --- a/memhub/apps/desktop/src/host-permissions.test.ts +++ b/memhub/apps/desktop/src/host-permissions.test.ts @@ -21,6 +21,8 @@ import { claudeCodeLayout, codexLayout, cursorLayout, + MCP_TOOLSET_KEY, + MCP_TOOLSET_VERSION, mcpConfigPath, piLayout, planRecallInstall, @@ -29,6 +31,7 @@ import { workbuddyLayout, workbuddyScatteredLayout, } from "@one-memory/host-bridge/installer"; +import type { DiagnosticInput } from "@one-memory/runtime-control"; import { afterEach, describe, expect, it, vi } from "vitest"; import { probeRecallInstall } from "../../../packages/host-bridge/src/recall-probe.js"; import { skillFilePath } from "../../../packages/host-bridge/src/skill-drift.js"; @@ -1384,3 +1387,197 @@ describe("upgrading installs left by an earlier release", () => { ); }); }); + +describe("refreshing installed hosts after an upgrade", () => { + function recorder() { + const events: DiagnosticInput[] = []; + return { + events, + sink: { + log: async (event: DiagnosticInput) => { + events.push(event); + }, + }, + }; + } + + async function linkedWorkbuddy(context: Awaited>) { + const layout = workbuddyLayout(path.join(context.root, "workbuddy")); + const preview = await context.permissions.previewInstall(layout); + const result = await context.permissions.install( + layout, + preview.fingerprint, + ); + await context.permissions.setPermission( + layout, + approval(required(result.permission.receipt)), + ); + return layout; + } + + /** Put back the skill an earlier release wrote, journaled as ours. */ + async function ageSkill(layout: ReturnType) { + const skillPath = required(skillFilePath(layout)); + const aged = (await readFile(skillPath, "utf8")) + .replace(/skill-version=\d+/, "skill-version=15") + .replace("`MemHub_recall`", "`MemHub_ask`"); + await writeFile(skillPath, aged); + const journal = JSON.parse(await readFile(layout.journalPath, "utf8")); + journal.installed_skill_hash = createHash("sha256") + .update(aged) + .digest("hex"); + await writeFile(layout.journalPath, JSON.stringify(journal)); + return aged; + } + + it("rewrites an old skill on the first start of a build, and only once per build", async () => { + const context = await fixture(); + const layout = await linkedWorkbuddy(context); + const current = await readFile(required(skillFilePath(layout)), "utf8"); + await ageSkill(layout); + const { events, sink } = recorder(); + + const first = await context.permissions.refreshInstalledHosts([layout], { + build: "34", + diagnostics: sink, + }); + expect(first).toMatchObject({ + state: "refreshed", + synced: ["workbuddy"], + failed: [], + }); + expect(await readFile(required(skillFilePath(layout)), "utf8")).toBe( + current, + ); + + // Same build again: one file read, nothing rewritten, even if stale. + const aged = await ageSkill(layout); + expect( + await context.permissions.refreshInstalledHosts([layout], { + build: "34", + diagnostics: sink, + }), + ).toMatchObject({ state: "already_refreshed", synced: [] }); + expect(await readFile(required(skillFilePath(layout)), "utf8")).toBe(aged); + + // The next build refreshes again. + expect( + await context.permissions.refreshInstalledHosts([layout], { + build: "35", + }), + ).toMatchObject({ state: "refreshed", synced: ["workbuddy"] }); + expect(await readFile(required(skillFilePath(layout)), "utf8")).toBe( + current, + ); + + // Diagnostics carry host ids and counts only, never file content. + expect(events.map((event) => event.event)).toEqual([ + "host_refresh.host_updated", + "host_refresh.completed", + "host_refresh.skipped", + ]); + expect(events[0].details).toEqual({ source_id: "workbuddy" }); + expect(events[1].details).toEqual({ + count: 1, + updated_count: 1, + error_count: 0, + }); + expect(JSON.stringify(events)).not.toContain("MemHub_"); + expect(JSON.stringify(events)).not.toContain(context.root); + }); + + it("leaves a skill the user edited untouched", async () => { + const context = await fixture(); + const layout = await linkedWorkbuddy(context); + const edited = `${await ageSkill(layout)}\nUser addition\n`; + await writeFile(required(skillFilePath(layout)), edited); + + expect( + await context.permissions.refreshInstalledHosts([layout], { + build: "34", + }), + ).toMatchObject({ state: "refreshed", synced: [], failed: [] }); + expect(await readFile(required(skillFilePath(layout)), "utf8")).toBe( + edited, + ); + }); + + it("rewrites an MCP entry without the tool set stamp, in the plugin manifest too", async () => { + const context = await fixture(); + const layout = await linkedWorkbuddy(context); + const plugin = required(layout.plugin); + const manifests = [ + path.join(plugin.installRoot, ".codebuddy-plugin", "plugin.json"), + path.join( + plugin.marketplaceRoot, + "plugins", + plugin.pluginName, + ".codebuddy-plugin", + "plugin.json", + ), + ]; + // What an earlier release wrote: the same entry with no stamp, journaled. + const journal = JSON.parse(await readFile(layout.journalPath, "utf8")); + for (const manifestPath of manifests) { + const manifest = JSON.parse(await readFile(manifestPath, "utf8")); + expect(manifest.mcpServers["one-memory"].env[MCP_TOOLSET_KEY]).toBe( + MCP_TOOLSET_VERSION, + ); + delete manifest.mcpServers["one-memory"].env[MCP_TOOLSET_KEY]; + const text = `${JSON.stringify(manifest, null, 2)}\n`; + await writeFile(manifestPath, text); + const entry = journal.plugin_files.find( + (file: { path: string }) => file.path === manifestPath, + ); + entry.hash = createHash("sha256").update(text).digest("hex"); + journal.installed_server_hash = createHash("sha256") + .update(JSON.stringify(manifest.mcpServers["one-memory"])) + .digest("hex"); + } + await writeFile(layout.journalPath, JSON.stringify(journal)); + const granted = await context.permissions.getPermission(layout); + expect(granted.state).toBe("approved"); + expect( + (await readInstalledRecallCommand(layout))?.env[MCP_TOOLSET_KEY], + ).toBeUndefined(); + + expect( + await context.permissions.refreshInstalledHosts([layout], { + build: "34", + }), + ).toMatchObject({ synced: ["workbuddy"], failed: [] }); + for (const manifestPath of manifests) { + const manifest = JSON.parse(await readFile(manifestPath, "utf8")); + expect(manifest.mcpServers["one-memory"].env[MCP_TOOLSET_KEY]).toBe( + MCP_TOOLSET_VERSION, + ); + } + // Rewriting our own entry keeps the user's authorization. + expect(await context.permissions.getPermission(layout)).toEqual(granted); + }); + + it("rewrites a config-file MCP entry without the stamp", async () => { + const context = await fixture(); + await install(context); + const configPath = mcpConfigPath(context.layout); + const config = JSON.parse(await readFile(configPath, "utf8")); + delete config.mcpServers["one-memory"].env[MCP_TOOLSET_KEY]; + await writeFile(configPath, `${JSON.stringify(config, null, 2)}\n`); + const journal = JSON.parse( + await readFile(context.layout.journalPath, "utf8"), + ); + journal.installed_server_hash = createHash("sha256") + .update(JSON.stringify(config.mcpServers["one-memory"])) + .digest("hex"); + await writeFile(context.layout.journalPath, JSON.stringify(journal)); + + expect( + await context.permissions.refreshInstalledHosts([context.layout]), + ).toMatchObject({ state: "refreshed", synced: ["cursor"], failed: [] }); + const refreshed = JSON.parse(await readFile(configPath, "utf8")); + expect(refreshed.mcpServers["one-memory"].env[MCP_TOOLSET_KEY]).toBe( + MCP_TOOLSET_VERSION, + ); + expect(refreshed.mcpServers.neighbor).toEqual({ command: "keep" }); + }); +}); diff --git a/memhub/apps/desktop/src/main.ts b/memhub/apps/desktop/src/main.ts index 48b3dfe..791a82a 100644 --- a/memhub/apps/desktop/src/main.ts +++ b/memhub/apps/desktop/src/main.ts @@ -1369,6 +1369,24 @@ async function initialize(isQuitting: () => boolean): Promise { }); await runtimeSupervisor.start(); if (isQuitting()) return; + // A standalone Runtime refreshes the hosts it installed as it starts, so + // an upgrade through the App or `memhub upgrade` is covered there. An + // embedded one is this process: do the same here, now it is up. Only a + // packaged build, so a source checkout never repoints real hosts at itself. + if (localPermissions && app.isPackaged) { + void localPermissions + .refreshInstalledHosts( + hosts.map((host) => host.layout), + { + build: + packagedBuildNumber === undefined + ? undefined + : String(packagedBuildNumber), + diagnostics: hostDiagnostics, + }, + ) + .catch(() => undefined); + } if ( app.isPackaged && process.platform === "darwin" && diff --git a/memhub/apps/web/src/DebugLogPanel.tsx b/memhub/apps/web/src/DebugLogPanel.tsx index 6f6b904..5173afa 100644 --- a/memhub/apps/web/src/DebugLogPanel.tsx +++ b/memhub/apps/web/src/DebugLogPanel.tsx @@ -50,7 +50,6 @@ const SERVICE_LABELS: Record = { core: "Core", "host-bridge": "Host Bridge", cli: "CLI", - "hy-memory": "HY Memory", }; export function DebugLogPanel() { diff --git a/memhub/apps/web/src/MemoryMap.test.tsx b/memhub/apps/web/src/MemoryMap.test.tsx index 6cd12a3..5feaf65 100644 --- a/memhub/apps/web/src/MemoryMap.test.tsx +++ b/memhub/apps/web/src/MemoryMap.test.tsx @@ -5,7 +5,6 @@ import type { MemoryGraphNode, MemoryGraphResponse, MemoryProcessingSummary, - SourceImportReceipt as Receipt, SourceResponse, } from "@one-memory/contracts"; import { @@ -40,12 +39,6 @@ import { afterEach, expect, it, vi } from "vitest"; import { MemoryMap } from "./MemoryMap"; import type { MemoryArrival } from "./memory-arrival-state"; -const { sourceReceipt } = vi.hoisted(() => ({ - sourceReceipt: vi.fn(), -})); -vi.mock("./api", () => ({ - getSourceImportReceipt: sourceReceipt, -})); vi.mock("./MemoryGraph3D", () => ({ MemoryGraph3D: ({ graph, @@ -680,7 +673,7 @@ it("D96: the memory page has no raw-dialogue tab and never loads the dialogue li it("D96: lists a memory by when its conversation happened, not when it was generated", () => { const today = new Date().toISOString(); const thisYear = new Date().getFullYear(); - const items = ["第一条", "第二条", "第三条"].map((content, i) => ({ + const items = ["第一条", "第二条", "第三条", "第四条"].map((content, i) => ({ ...memories[0], memory_id: `t${i}`, content, @@ -695,10 +688,11 @@ it("D96: lists a memory by when its conversation happened, not when it was gener total: 519, offset: 100, limit: 100, - source_ids_by_memory: { t0: [], t1: [], t2: [] }, + source_ids_by_memory: { t0: [], t1: [], t2: [], t3: [] }, source_time_by_memory: { t0: { at: `${thisYear}-10-02T10:54:00`, basis: "conversation" }, t1: { at: `${thisYear}-09-30T08:00:00`, basis: "import" }, + t3: { at: `${thisYear}-09-29T08:00:00`, basis: "write" }, }, })} />, @@ -710,6 +704,10 @@ it("D96: lists a memory by when its conversation happened, not when it was gener expect( within(list).getByRole("button", { name: /第二条/ }).textContent, ).toContain("导入于 9月30日"); + // An experience stored without a conversation time names its write time. + expect( + within(list).getByRole("button", { name: /第四条/ }).textContent, + ).toContain("写入于 9月29日"); // D99: the generated day keeps its own line, so a memory made today from an // old conversation still reads as new rather than looking misplaced. expect( @@ -1145,35 +1143,6 @@ const importedSources = [ imported_conversations: 1, }, ] as SourceResponse[]; -const importedReceipt: Receipt = { - source_id: "codex", - measured_at: "2026-09-14T00:00:00Z", - messages: 5, - conversations: 2, - person_messages: 2, - agent_messages: 2, - tool_messages: 0, - unknown_author_messages: 1, - unknown_time_messages: 1, - examples: [ - { - evidence_id: "raw-codex", - role: "user", - written_by: "person", - created_at: null, - excerpt: "合成来源原文,不是治理记忆。", - truncated: false, - }, - ], -}; -async function openSourceReceipt() { - await userEvent.click( - screen.getByRole("button", { name: "图中选择 Codex · 2 段" }), - ); - await userEvent.click(screen.getByText("查看已读内容")); - await waitFor(() => expect(sourceReceipt).toHaveBeenCalledWith("codex")); -} - it("REV09: selecting an imported source retains the canvas and only its authorized node", async () => { render(); const canvas = screen.getByTestId("canvas"); @@ -1188,7 +1157,8 @@ it("REV09: selecting an imported source retains the canvas and only its authoriz expect( screen.getByRole("list", { name: "地图记忆列表" }).children, ).toHaveLength(0); - expect(sourceReceipt).not.toHaveBeenCalled(); + expect(screen.getByRole("heading", { name: "记忆详情" })).toBeTruthy(); + expect(screen.getByText("还没有已生成的记忆")).toBeTruthy(); await userEvent.click(screen.getByRole("button", { name: /全部记忆/ })); expect(within(canvas).getAllByRole("button")).toHaveLength(2); expect(canvas.dataset.selected ?? "").toBe(""); @@ -1210,83 +1180,248 @@ it("REV09: fallback search matches source names and IDs without bypassing the se ); await userEvent.type(search, "cOdEx"); expect(screen.getByTestId("canvas").dataset.selected).toBe("source:codex"); - expect(screen.getByText("查看已读内容")).toBeTruthy(); + expect(screen.getByText("还没有已生成的记忆")).toBeTruthy(); await userEvent.clear(search); await userEvent.type(search, "Cursor"); expect(screen.queryByTestId("canvas")).toBeNull(); - expect(screen.queryByText("查看已读内容")).toBeNull(); + expect(screen.queryByText("正在读取记忆详情…")).toBeNull(); await userEvent.clear(search); expect(screen.getByTestId("canvas").dataset.selected ?? "").toBe(""); - expect(screen.queryByText("查看已读内容")).toBeNull(); + expect(screen.queryByText("正在读取记忆详情…")).toBeNull(); }); -it("REV09: source selection uses the actual permission-checked receipt API", async () => { - sourceReceipt.mockResolvedValue(importedReceipt); - render(); - await openSourceReceipt(); - expect( - await screen.findByText(importedReceipt.examples[0].excerpt), - ).toBeTruthy(); - expect(screen.getByText("用户 · 时间未知")).toBeTruthy(); - expect(screen.getByText("原始消息").nextElementSibling?.textContent).toBe( - "5", +it("selecting a source node waits for its settled page, then opens the first memory", async () => { + const onQuery = vi.fn(); + const onSource = vi.fn(); + const resetPage = vi.fn(); + const oldPage = { + items: memories, + total: 2, + offset: 0, + limit: 20, + source_ids_by_memory: { m0: ["codex"], m1: ["codex"] }, + }; + const view = render( + , ); - // No raw conversation is read by id on the SDK data plane. - expect(screen.queryByRole("button", { name: "查看完整对话" })).toBeNull(); + await act(async () => {}); + await userEvent.click(screen.getByRole("button", { name: "图中选择 Codex" })); + expect(onQuery).toHaveBeenCalledWith(""); + expect(onSource).toHaveBeenCalledWith("codex"); + expect(resetPage).toHaveBeenCalledOnce(); + + view.rerender( + , + ); + expect( + screen + .getAllByRole("status") + .some((node) => node.textContent === "正在读取记忆详情…"), + ).toBe(true); + + const settledItems = [memories[1], memories[0]]; + view.rerender( + , + ); + expect(await screen.findByRole("heading", { name: "第二条" })).toBeTruthy(); + expect(screen.queryByText("查看已读内容")).toBeNull(); + expect(document.querySelector(".source-import-receipt")).toBeNull(); }); -it.each(["revoked", "removed", "revoked-hidden"])( - "REV09: %s source drops fallback, preview and a late receipt without reopening on reauthorization", - async (state) => { - let finish: (value: Receipt) => void = () => {}; - sourceReceipt.mockImplementation( - () => - new Promise((resolve) => { - finish = resolve; - }), - ); - const view = render(); - await openSourceReceipt(); - view.rerender( -