fix: prevent pcbnew stdout noise from causing sync_schematic_to_board timeouts

The TS<->Python communication channel uses stdout for JSON responses.
pcbnew's C++ SWIG layer can write warnings and diagnostics directly to
C-level stdout (fd 1), corrupting the JSON framing. The TS parser then
never sees valid JSON and the command times out after 30 seconds.

Three changes fix this:

1. Python stdout redirect: In main(), save the original stdout fd for
   exclusive JSON response use, then redirect fd 1 to stderr so all
   pcbnew C++ output goes to logs instead of the response pipe.

2. Robust TS JSON parser: tryParseResponse() now uses newline-delimited
   parsing as a fallback. The Python side writes single-line JSON
   terminated by \n; the parser uses this as the completion signal
   instead of brace-matching, which prevents premature resolution of
   truncated chunked responses. Non-JSON preamble lines are logged
   and stripped.

3. Fix stray print() calls: Converted print() to logger in
   component_schematic.py and library_schematic.py so they don't
   leak to stdout during normal operations.

Also adds sync_schematic_to_board to the longRunningCommands list for
an appropriate timeout value.
This commit is contained in:
William Viana
2026-04-03 11:24:42 -07:00
parent f79a3d6435
commit 0bc00b1451
4 changed files with 137 additions and 50 deletions

View File

@@ -278,13 +278,13 @@ class ComponentManager:
if symbol_to_remove: if symbol_to_remove:
schematic.symbol._elements.remove(symbol_to_remove) schematic.symbol._elements.remove(symbol_to_remove)
print(f"Removed component {component_ref} from schematic.") logger.info(f"Removed component {component_ref} from schematic.")
return True return True
else: else:
print(f"Component with reference {component_ref} not found.") logger.warning(f"Component with reference {component_ref} not found.")
return False return False
except Exception as e: except Exception as e:
print(f"Error removing component {component_ref}: {e}") logger.error(f"Error removing component {component_ref}: {e}")
return False return False
@staticmethod @staticmethod
@@ -302,15 +302,14 @@ class ComponentManager:
if key in symbol_to_update.property: if key in symbol_to_update.property:
symbol_to_update.property[key].value = value symbol_to_update.property[key].value = value
else: else:
# Add as a new property if it doesn't exist
symbol_to_update.property.append(key, value) symbol_to_update.property.append(key, value)
print(f"Updated properties for component {component_ref}.") logger.info(f"Updated properties for component {component_ref}.")
return True return True
else: else:
print(f"Component with reference {component_ref} not found.") logger.warning(f"Component with reference {component_ref} not found.")
return False return False
except Exception as e: except Exception as e:
print(f"Error updating component {component_ref}: {e}") logger.error(f"Error updating component {component_ref}: {e}")
return False return False
@staticmethod @staticmethod
@@ -318,9 +317,9 @@ class ComponentManager:
"""Get a component by reference designator""" """Get a component by reference designator"""
for symbol in schematic.symbol: for symbol in schematic.symbol:
if symbol.reference == component_ref: if symbol.reference == component_ref:
print(f"Found component with reference {component_ref}.") logger.debug(f"Found component with reference {component_ref}.")
return symbol return symbol
print(f"Component with reference {component_ref} not found.") logger.warning(f"Component with reference {component_ref} not found.")
return None return None
@staticmethod @staticmethod
@@ -339,13 +338,13 @@ class ComponentManager:
) )
): ):
matching_components.append(symbol) matching_components.append(symbol)
print(f"Found {len(matching_components)} components matching query '{query}'.") logger.debug(f"Found {len(matching_components)} components matching query '{query}'.")
return matching_components return matching_components
@staticmethod @staticmethod
def get_all_components(schematic: Schematic): def get_all_components(schematic: Schematic):
"""Get all components in schematic""" """Get all components in schematic"""
print(f"Retrieving all {len(schematic.symbol)} components.") logger.debug(f"Retrieving all {len(schematic.symbol)} components.")
return list(schematic.symbol) return list(schematic.symbol)

View File

@@ -1,10 +1,13 @@
import glob import glob
import logging
# Symbol class might not be directly importable in the current version # Symbol class might not be directly importable in the current version
import os import os
from skip import Schematic from skip import Schematic
logger = logging.getLogger(__name__)
class LibraryManager: class LibraryManager:
"""Manage symbol libraries""" """Manage symbol libraries"""
@@ -31,11 +34,11 @@ class LibraryManager:
matching_libs = glob.glob(path_pattern, recursive=True) matching_libs = glob.glob(path_pattern, recursive=True)
libraries.extend(matching_libs) libraries.extend(matching_libs)
except Exception as e: except Exception as e:
print(f"Error searching for libraries at {path_pattern}: {e}") logger.error(f"Error searching for libraries at {path_pattern}: {e}")
# Extract library names from paths # Extract library names from paths
library_names = [os.path.splitext(os.path.basename(lib))[0] for lib in libraries] library_names = [os.path.splitext(os.path.basename(lib))[0] for lib in libraries]
print( logger.info(
f"Found {len(library_names)} libraries: {', '.join(library_names[:10])}{'...' if len(library_names) > 10 else ''}" f"Found {len(library_names)} libraries: {', '.join(library_names[:10])}{'...' if len(library_names) > 10 else ''}"
) )
@@ -54,12 +57,12 @@ class LibraryManager:
# A potential approach would be to load the library file using KiCAD's Python API # A potential approach would be to load the library file using KiCAD's Python API
# or by parsing the library file format. # or by parsing the library file format.
# KiCAD symbol libraries are .kicad_sym files which are S-expression format # KiCAD symbol libraries are .kicad_sym files which are S-expression format
print( logger.warning(
f"Attempted to list symbols in library {library_path}. This requires advanced implementation." f"Attempted to list symbols in library {library_path}. This requires advanced implementation."
) )
return [] return []
except Exception as e: except Exception as e:
print(f"Error listing symbols in library {library_path}: {e}") logger.error(f"Error listing symbols in library {library_path}: {e}")
return [] return []
@staticmethod @staticmethod
@@ -68,12 +71,12 @@ class LibraryManager:
try: try:
# Similar to list_library_symbols, this might require a more direct approach # Similar to list_library_symbols, this might require a more direct approach
# using KiCAD's Python API or by parsing the symbol library. # using KiCAD's Python API or by parsing the symbol library.
print( logger.warning(
f"Attempted to get details for symbol {symbol_name} in library {library_path}. This requires advanced implementation." f"Attempted to get details for symbol {symbol_name} in library {library_path}. This requires advanced implementation."
) )
return {} return {}
except Exception as e: except Exception as e:
print(f"Error getting symbol details for {symbol_name} in {library_path}: {e}") logger.error(f"Error getting symbol details for {symbol_name} in {library_path}: {e}")
return {} return {}
@staticmethod @staticmethod
@@ -89,12 +92,12 @@ class LibraryManager:
libraries = LibraryManager.list_available_libraries(search_paths) libraries = LibraryManager.list_available_libraries(search_paths)
results = [] results = []
print( logger.warning(
f"Searched for symbols matching '{query}'. This requires advanced implementation." f"Searched for symbols matching '{query}'. This requires advanced implementation."
) )
return results return results
except Exception as e: except Exception as e:
print(f"Error searching for symbols matching '{query}': {e}") logger.error(f"Error searching for symbols matching '{query}': {e}")
return [] return []
@staticmethod @staticmethod

View File

@@ -4024,8 +4024,29 @@ print("ok")
} }
def _write_response(response_fd, response):
"""Write a JSON response to the original stdout fd.
All response output goes through this function so that stray C-level
writes from pcbnew (warnings, diagnostics) never corrupt the JSON
framing seen by the TypeScript host.
"""
payload = json.dumps(response) + "\n"
os.write(response_fd, payload.encode("utf-8"))
def main(): def main():
"""Main entry point""" """Main entry point"""
# --- Redirect stdout so pcbnew C++ noise never reaches the TS host ---
# Save the real stdout fd for our exclusive JSON response channel.
_response_fd = os.dup(1)
# Point fd 1 (C-level stdout) at stderr so that any printf / std::cout
# output from pcbnew or other C extensions is visible in logs but does
# NOT corrupt the JSON stream the TypeScript side is parsing.
os.dup2(2, 1)
# Also redirect Python-level stdout to stderr for the same reason.
sys.stdout = sys.stderr
logger.info("Starting KiCAD interface...") logger.info("Starting KiCAD interface...")
interface = KiCADInterface() interface = KiCADInterface()
@@ -4167,10 +4188,9 @@ def main():
# Handle command # Handle command
response = interface.handle_command(command, params) response = interface.handle_command(command, params)
# Send response # Send response via the clean fd (immune to pcbnew stdout noise)
logger.debug(f"Sending response: {response}") logger.debug(f"Sending response: {response}")
print(json.dumps(response)) _write_response(_response_fd, response)
sys.stdout.flush()
except json.JSONDecodeError as e: except json.JSONDecodeError as e:
logger.error(f"Invalid JSON input: {str(e)}") logger.error(f"Invalid JSON input: {str(e)}")
@@ -4179,8 +4199,7 @@ def main():
"message": "Invalid JSON input", "message": "Invalid JSON input",
"errorDetails": str(e), "errorDetails": str(e),
} }
print(json.dumps(response)) _write_response(_response_fd, response)
sys.stdout.flush()
except KeyboardInterrupt: except KeyboardInterrupt:
logger.info("KiCAD interface stopped") logger.info("KiCAD interface stopped")

View File

@@ -516,7 +516,13 @@ export class KiCADMcpServer {
// Determine timeout based on command type // Determine timeout based on command type
// DRC and export operations need longer timeouts for large boards // DRC and export operations need longer timeouts for large boards
let commandTimeout = 30000; // Default 30 seconds let commandTimeout = 30000; // Default 30 seconds
const longRunningCommands = ["run_drc", "export_gerber", "export_pdf", "export_3d"]; const longRunningCommands = [
"run_drc",
"export_gerber",
"export_pdf",
"export_3d",
"sync_schematic_to_board",
];
if (longRunningCommands.includes(command)) { if (longRunningCommands.includes(command)) {
commandTimeout = 600000; // 10 minutes for long operations commandTimeout = 600000; // 10 minutes for long operations
logger.info(`Using extended timeout (${commandTimeout / 1000}s) for command: ${command}`); logger.info(`Using extended timeout (${commandTimeout / 1000}s) for command: ${command}`);
@@ -550,7 +556,21 @@ export class KiCADMcpServer {
} }
/** /**
* Try to parse a complete JSON response from the buffer * Try to parse a complete JSON response from the buffer.
*
* Responses from the Python side are single-line JSON terminated by '\n'
* (written via _write_response). The buffer may also contain non-JSON
* preamble lines (e.g. C-level warnings from pcbnew that leaked to the
* response fd before the redirect took effect).
*
* Strategy:
* 1. Fast path: JSON.parse(buffer) — works for clean, complete responses
* (JSON.parse tolerates trailing whitespace/newlines).
* 2. If that fails and the buffer has no '\n' yet, the response line is
* still arriving in chunks — keep collecting.
* 3. If the buffer has '\n', split into lines and search from the END for
* a parseable JSON line. This avoids prematurely resolving with a
* truncated JSON object when a large response is still chunking in.
*/ */
private tryParseResponse(): void { private tryParseResponse(): void {
if (!this.currentRequestHandler) { if (!this.currentRequestHandler) {
@@ -564,37 +584,83 @@ export class KiCADMcpServer {
return; return;
} }
let result: any;
// Fast path: try to parse the response as JSON. Handles the common
// case of a clean, complete JSON response (possibly with trailing \n).
try { try {
// Try to parse the response as JSON result = JSON.parse(this.responseBuffer);
const result = JSON.parse(this.responseBuffer); } catch {
// Direct parse failed. Either the response is still arriving in
// If we get here, we have a valid JSON response // chunks, or the buffer has non-JSON preamble from pcbnew.
logger.debug( //
`Completed KiCAD command with result: ${result.success ? "success" : "failure"}`, // The Python side writes each response as a single line of JSON
); // terminated by \n. We use the newline as the completion signal:
// if there is no \n in the buffer yet, the JSON line is still
// Clear the timeout since we got a response // being assembled from chunks — keep collecting.
if (this.currentRequestHandler.timeoutHandle) { if (!this.responseBuffer.includes("\n")) {
clearTimeout(this.currentRequestHandler.timeoutHandle); return;
} }
// Get the handler before clearing // Buffer contains newline(s). Split into lines and look for a
const handler = this.currentRequestHandler; // complete JSON object, searching from the END so that preamble
// lines (which may themselves contain '{') are skipped.
const lines = this.responseBuffer.split("\n");
let jsonLineIndex = -1;
// Clear state for (let i = lines.length - 1; i >= 0; i--) {
this.responseBuffer = ""; const line = lines[i].trim();
this.currentRequestHandler = null; if (line.length === 0) continue;
this.processingRequest = false; if (!line.startsWith("{")) continue;
// Resolve the promise with the result try {
handler.resolve(result); result = JSON.parse(line);
jsonLineIndex = i;
break;
} catch {
// Looks like JSON but doesn't parse — could be an incomplete
// final line still being chunked. Keep collecting.
continue;
}
}
// Process next request if any if (jsonLineIndex < 0) {
setTimeout(() => this.processNextRequest(), 0); // No parseable JSON line found yet. Either only preamble has
} catch (e) { // arrived, or the JSON line is split across the last \n boundary
// Not a complete JSON yet, keep collecting data // and is still incomplete. Keep collecting.
// This is normal for large responses that come in chunks return;
}
// Log any preceding non-JSON lines as preamble
const preambleLines = lines.slice(0, jsonLineIndex).filter((l) => l.trim().length > 0);
if (preambleLines.length > 0) {
logger.warn(
`Stripped non-JSON preamble from Python response: ${preambleLines.join(" | ")}`,
);
}
} }
// If we get here, we have a valid JSON response
logger.debug(`Completed KiCAD command with result: ${result.success ? "success" : "failure"}`);
// Clear the timeout since we got a response
if (this.currentRequestHandler.timeoutHandle) {
clearTimeout(this.currentRequestHandler.timeoutHandle);
}
// Get the handler before clearing
const handler = this.currentRequestHandler;
// Clear state
this.responseBuffer = "";
this.currentRequestHandler = null;
this.processingRequest = false;
// Resolve the promise with the result
handler.resolve(result);
// Process next request if any
setTimeout(() => this.processNextRequest(), 0);
} }
/** /**