test optimizer on rancher and mac

[therealnb]

A customer is running optimizer and launch “thv serve” manually on rancher on a mac and seeing optimizer crash after a minure or two of messages like

1:53PM	ERROR	Failed to forward request: dial tcp 127.0.0.1:37937: connect: connection refused
2025/11/05 13:53:01 http: proxy error: dial tcp 127.0.0.1:37937: connect: connection refused

Find out why.

[therealnb]

I have been using rancher for some time. My logs have a lot of instances of 'Failed to forward request' but they are mostly on instances of servers that are not properly configured (I have a large number of them, they don't need to work, just be there for testing). Sometimes, optimizer's proxy is showing this message, but that looks like where I have been shutting it down and messing with dev.

This message seems appropriate and not specific to optimizer.

First thought was memory issues. I had deviated from the default setup by doubling cpu and memory. I dropped this back, but it seems to be unrelated.

[therealnb]

I ran the latest code using this script

start-local.sh

All seemed good.

[therealnb]

I tried running the latest released version (incorrectly... see below) and I did see a problem in the proxy log

tail -1000f mcp-optimizer.log 
9:34AM  INFO     Loaded configuration from state for mcp-optimizer
9:34AM  INFO     Starting tooling server mcp-optimizer...
9:34AM  INFO     OIDC validation disabled, using local user authentication
9:34AM  INFO     Using local user authentication for user: nigel
9:34AM  INFO     Setting up streamable-http transport...
9:34AM  INFO     Deploying workload mcp-optimizer from image ghcr.io/stackloklabs/mcp-optimizer:0.1.0...
9:34AM  INFO     Container created: mcp-optimizer
9:34AM  INFO     Starting streamable-http transport for mcp-optimizer...
9:34AM  INFO     Setting up transparent proxy to forward from host port 60913 to http://127.0.0.1:46033
9:34AM  INFO     Applied middleware: mcp-parser
9:34AM  INFO     Applied middleware: auth
9:34AM  INFO     HTTP transport started for mcp-optimizer on port 60913
9:34AM  INFO     MCP server mcp-optimizer started successfully
9:34AM  INFO     Server mcp-optimizer belongs to group default, updating 1 registered client(s)
9:34AM  INFO     Updating client configuration: /Users/nigel/.cursor/mcp.json
9:34AM  INFO     Successfully updated the client config file for MCPServer mcp-optimizer
9:34AM  INFO     Successfully updated client configuration: /Users/nigel/.cursor/mcp.json
9:34AM  INFO     Running as detached process (PID: 42278)
9:34AM  INFO     Detected initialize method call for http://127.0.0.1:46033
9:34AM  INFO     Detected initialize method call for http://127.0.0.1:46033
9:34AM  ERROR    Failed to forward request: dial tcp 127.0.0.1:46033: connect: connection refused
2025/11/07 09:34:44 http: proxy error: dial tcp 127.0.0.1:46033: connect: connection refused
9:34AM  ERROR    Failed to forward request: dial tcp 127.0.0.1:46033: connect: connection refused
2025/11/07 09:34:44 http: proxy error: dial tcp 127.0.0.1:46033: connect: connection refused
9:34AM  ERROR    Failed to forward request: dial tcp 127.0.0.1:46033: connect: connection refused
2025/11/07 09:34:44 http: proxy error: dial tcp 127.0.0.1:46033: connect: connection refused
9:34AM  ERROR    Failed to forward request: dial tcp 127.0.0.1:46033: connect: connection refused
2025/11/07 09:34:44 http: proxy error: dial tcp 127.0.0.1:46033: connect: connection refused
9:34AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:35AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:36AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:36AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033
9:36AM  INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:46033

This seems to fit the description of the original problem. The container was exiting because it couldn't find thv serve

docker logs --tail 1000 -f b3c071211d8a3053c03f178ccdb6759b88880557b27e5caf4637e488009a5e26 

source /Users/nigel/code/mcp-optimizer/.venv/bin/activate
2025-11-07 09:38:23 [info     ] Testing write access to database directory: //app/.venv/lib/python3.13/data
2025-11-07 09:38:23 [info     ] Write test successful in //app/.venv/lib/python3.13/data
2025-11-07 09:38:23 [info     ] Testing SQLite database creation at //app/.venv/lib/python3.13/data/.sqlite_test.db
2025-11-07 09:38:23 [info     ] SQLite test successful
2025-11-07 09:38:23 [info     ] Pre-creating database file at //app/.venv/lib/python3.13/data/mcp_optimizer.db
2025-11-07 09:38:23 [info     ] Database file created successfully
2025-11-07 09:38:23 [info     ] Set secure permissions for database file: mcp_optimizer.db at //app/.venv/lib/python3.13/data/mcp_optimizer.db
2025-11-07 09:38:23 [info     ] Configuration loaded and validated successfully config={'runtime_mode': 'docker', 'log_level': 'INFO', 'colored_logs': False, 'rich_tracebacks': False, 'mcp_port': 9900, 'reload_server': False, 'toolhive_host': 'host.docker.internal', 'toolhive_port': 8080, 'toolhive_start_port_scan': 50000, 'toolhive_end_port_scan': 50100, 'k8s_api_server_url': 'http://127.0.0.1:8001', 'k8s_namespace': None, 'k8s_all_namespaces': True, 'workload_polling_interval': 60, 'registry_polling_interval': 86400, 'targeted_polling_max_attempts': 120, 'targeted_polling_interval': 1, 'toolhive_timeout': 10, 'toolhive_max_retries': 100, 'toolhive_initial_backoff': 1.0, 'toolhive_max_backoff': 60.0, 'mcp_timeout': 10, 'async_db_url': 'sqlite+aiosqlite:////app/.venv/lib/python3.13/data/mcp_optimizer.db', 'db_url': 'sqlite:////app/.venv/lib/python3.13/data/mcp_optimizer.db', 'embedding_model_name': 'BAAI/bge-small-en-v1.5', 'embedding_threads': 2, 'encoding': 'cl100k_base', 'max_tools_to_return': 8, 'tool_distance_threshold': 1.0, 'max_servers_to_return': 5, 'hybrid_search_semantic_ratio': 0.5, 'enable_embedding_cache': True, 'registry_ingestion_batch_size': 5, 'workload_ingestion_batch_size': 5, 'max_tool_response_tokens': None, 'allowed_groups': None, 'skipped_workloads': ['inspector', 'mcp-optimizer'], 'enable_dynamic_install': False, 'fastembed_cache_path': '/app/.cache/fastembed', 'tiktoken_cache_dir': '/app/.cache/tiktoken'}
2025-11-07 09:38:23 [info     ] Configuration validation successful cli_options_provided=None config_source=env/default mcp_port=9900 runtime_mode=docker toolhive_port_range=50000-50100
2025-11-07 09:38:23 [warning  ] Invalid semver version string  [mcp_optimizer.toolhive.toolhive_client] error='build-7c3a3077 is not valid SemVer string' version=build-7c3a3077
2025-11-07 09:38:23 [warning  ] ToolHive not available at specified host/port, retrying... [mcp_optimizer.toolhive.toolhive_client] attempt=1 host=host.docker.internal port=8080
2025-11-07 09:38:24 [warning  ] Invalid semver version string  [mcp_optimizer.toolhive.toolhive_client] error='build-7c3a3077 is not valid SemVer string' version=build-7c3a3077
2025-11-07 09:38:24 [warning  ] ToolHive not available at specified host/port, retrying... [mcp_optimizer.toolhive.toolhive_client] attempt=2 host=host.docker.internal port=8080
2025-11-07 09:38:25 [warning  ] Invalid semver version string  [mcp_optimizer.toolhive.toolhive_client] error='build-7c3a3077 is not valid SemVer string' version=build-7c3a3077
2025-11-07 09:38:25 [warning  ] ToolHive not available at specified host/port, retrying... [mcp_optimizer.toolhive.toolhive_client] attempt=3 host=host.docker.internal port=8080
2025-11-07 09:38:26 [info     ] Scanning for ToolHive          [mcp_optimizer.toolhive.toolhive_client] host=host.docker.internal port_range=50000-50100
2025-11-07 09:38:27 [error    ] Error scanning for ToolHive    [mcp_optimizer.toolhive.toolhive_client] error='ToolHive not found on host.docker.internal in port range 50000-50100'
Traceback (most recent call last):
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/toolhive/toolhive_client.py", line 141, in _discover_port
    asyncio.get_running_loop()
    ~~~~~~~~~~~~~~~~~~~~~~~~^^
RuntimeError: no running event loop

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/app/.venv/bin/mcpo", line 10, in <module>
    sys.exit(main())
             ~~~~^^
  File "/app/.venv/lib/python3.13/site-packages/click/core.py", line 1442, in __call__
    return self.main(*args, **kwargs)
           ~~~~~~~~~^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.13/site-packages/click/core.py", line 1363, in main
    rv = self.invoke(ctx)
  File "/app/.venv/lib/python3.13/site-packages/click/core.py", line 1226, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.13/site-packages/click/core.py", line 794, in invoke
    return callback(*args, **kwargs)
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/cli.py", line 199, in main
    toolhive_client = ToolhiveClient(
        host=config.toolhive_host,
    ...<7 lines>...
        skip_port_discovery=(config.runtime_mode == "k8s"),
    )
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/toolhive/toolhive_client.py", line 93, in __init__
    self._discover_port(port)
    ~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/toolhive/toolhive_client.py", line 149, in _discover_port
    asyncio.run(self._discover_port_async(port))
    ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/asyncio/runners.py", line 195, in run
    return runner.run(main)
           ~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/asyncio/base_events.py", line 725, in run_until_complete
    return future.result()
           ~~~~~~~~~~~~~^^
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/toolhive/toolhive_client.py", line 121, in _discover_port_async
    self.thv_port = await self._scan_for_toolhive(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        self.thv_host, self.scan_port_start, self.scan_port_end
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/app/.venv/lib/python3.13/site-packages/mcp_optimizer/toolhive/toolhive_client.py", line 224, in _scan_for_toolhive
    raise ConnectionError(
        f"ToolHive not found on {host} in port range {scan_port_start}-{scan_port_end}"
    )
ConnectionError: ToolHive not found on host.docker.internal in port range 50000-50100

Note particularly

2025-11-07 09:38:23 [warning  ] Invalid semver version string  [mcp_optimizer.toolhive.toolhive_client] error='build-7c3a3077 is not valid SemVer string' version=build-7c3a3077
2025-11-07 09:38:23 [warning  ] ToolHive not available at specified host/port, retrying... [mcp_optimizer.toolhive.toolhive_client] attempt=1 host=host.docker.internal port=8080

due to a path mix up, I was still running my local build

$ thv version
You are running a local build of ToolHive

ToolHive build-7c3a3077
Commit: 7c3a307745a194f749e7f4203307793a4ec7e664
Built: 2025-11-06 15:37:24 UTC
Go version: go1.25.3
Platform: darwin/arm64

so, the thv serve I ran was being rejected.

Note that I have not previously noticed this because although I have been using a locally built thv for running commands, I have also been using studio which starts its own thv serve.

[therealnb]

Using the right version

$ /opt/homebrew/bin/thv version
ToolHive v0.5.2
Commit: 028cc6de474375b574c4f7c9efdae88445539580
Built: 2025-11-03 16:22:21 UTC
Go version: go1.25.3
Platform: darwin/arm64

We can get past the initial connection to thv serve issue

docker logs --tail 1000 -f 71736884ebb707d96b484ca7978643301735970a87f6c6f09a4b83f32f0ec130 

2025-11-07 10:21:18 [info     ] Testing write access to database directory: //app/.venv/lib/python3.13/data
2025-11-07 10:21:18 [info     ] Write test successful in //app/.venv/lib/python3.13/data
2025-11-07 10:21:18 [info     ] Testing SQLite database creation at //app/.venv/lib/python3.13/data/.sqlite_test.db
2025-11-07 10:21:18 [info     ] SQLite test successful
2025-11-07 10:21:18 [info     ] Pre-creating database file at //app/.venv/lib/python3.13/data/mcp_optimizer.db
2025-11-07 10:21:18 [info     ] Database file created successfully
2025-11-07 10:21:18 [info     ] Set secure permissions for database file: mcp_optimizer.db at //app/.venv/lib/python3.13/data/mcp_optimizer.db
2025-11-07 10:21:18 [info     ] Configuration loaded and validated successfully config={'runtime_mode': 'docker', 'log_level': 'INFO', 'colored_logs': False, 'rich_tracebacks': False, 'mcp_port': 9900, 'reload_server': False, 'toolhive_host': '192.168.18.5', 'toolhive_port': 8080, 'toolhive_start_port_scan': 50000, 'toolhive_end_port_scan': 50100, 'k8s_api_server_url': 'http://127.0.0.1:8001', 'k8s_namespace': None, 'k8s_all_namespaces': True, 'workload_polling_interval': 60, 'registry_polling_interval': 86400, 'targeted_polling_max_attempts': 120, 'targeted_polling_interval': 1, 'toolhive_timeout': 10, 'toolhive_max_retries': 100, 'toolhive_initial_backoff': 1.0, 'toolhive_max_backoff': 60.0, 'mcp_timeout': 10, 'async_db_url': 'sqlite+aiosqlite:////app/.venv/lib/python3.13/data/mcp_optimizer.db', 'db_url': 'sqlite:////app/.venv/lib/python3.13/data/mcp_optimizer.db', 'embedding_model_name': 'BAAI/bge-small-en-v1.5', 'embedding_threads': 2, 'encoding': 'cl100k_base', 'max_tools_to_return': 8, 'tool_distance_threshold': 1.0, 'max_servers_to_return': 5, 'hybrid_search_semantic_ratio': 0.5, 'enable_embedding_cache': True, 'registry_ingestion_batch_size': 5, 'workload_ingestion_batch_size': 5, 'max_tool_response_tokens': None, 'allowed_groups': None, 'skipped_workloads': ['inspector', 'mcp-optimizer'], 'enable_dynamic_install': False, 'fastembed_cache_path': '/app/.cache/fastembed', 'tiktoken_cache_dir': '/app/.cache/tiktoken'}
2025-11-07 10:21:18 [info     ] Configuration validation successful cli_options_provided=None config_source=env/default mcp_port=9900 runtime_mode=docker toolhive_port_range=50000-50100
2025-11-07 10:21:19 [info     ] Found ToolHive instance        [mcp_optimizer.toolhive.toolhive_client] host=192.168.18.5 port=8080 version=0.5.2
2025-11-07 10:21:19 [info     ] ToolhiveClient initialized     [mcp_optimizer.toolhive.toolhive_client] host=192.168.18.5 port=8080
2025-11-07 10:21:19 [info     ] Context impl SQLiteImpl.       [alembic.runtime.migration]
2025-11-07 10:21:19 [info     ] Will assume non-transactional DDL. [alembic.runtime.migration]
2025-11-07 10:21:19 [info     ] Running upgrade  -> d2977d4c8c53, create_initial_tables [alembic.runtime.migration]
2025-11-07 10:21:19 [info     ] Database migrations completed successfully. [mcp_optimizer.db.config]
2025-11-07 10:21:19 [info     ] Found ToolHive instance        [mcp_optimizer.toolhive.toolhive_client] host=192.168.18.5 port=8080 version=0.5.2
2025-11-07 10:21:19 [info     ] ToolhiveClient initialized     [mcp_optimizer.toolhive.toolhive_client] host=192.168.18.5 port=8080
2025-11-07 10:21:19 [info     ] Registered core tools only (dynamic installation disabled) [mcp_optimizer.server] runtime_mode=docker tools=['find_tool', 'call_tool', 'list_tools']
2025-11-07 10:21:19 [info     ] Starting initial ingestion process [mcp_optimizer.cli]
2025-11-07 10:21:19 [info     ] Starting registry ingestion    [mcp_optimizer.ingestion] host=192.168.18.5 port=8080
2025-11-07 10:21:19 [info     ] Successfully fetched registry  [mcp_optimizer.toolhive.toolhive_client] remote_servers_count=21 servers_count=68
2025-11-07 10:21:19 [info     ] Successfully fetched registry for server embeddings [mcp_optimizer.ingestion]
2025-11-07 10:21:30 [info     ] Ingested registry servers      [mcp_optimizer.ingestion] registry_servers_count=89
2025-11-07 10:21:30 [info     ] Synchronizing registry vector tables after ingestion [mcp_optimizer.ingestion] registry_servers_ingested=89
2025-11-07 10:21:30 [info     ] Synced all registry_server_vector vectors [mcp_optimizer.db.base_server_ops]
2025-11-07 10:21:30 [info     ] Synced all registry_tool_vectors vectors [mcp_optimizer.db.base_tool_ops]
2025-11-07 10:21:30 [info     ] Synced all registry_tool_fts FTS [mcp_optimizer.db.base_tool_ops]
2025-11-07 10:21:30 [info     ] Registry vector and FTS synchronization completed [mcp_optimizer.ingestion]
2025-11-07 10:21:30 [info     ] Starting workload ingestion with cleanup [mcp_optimizer.ingestion] host=192.168.18.5 port=8080
2025-11-07 10:21:30 [info     ] Using Docker mode to fetch workloads [mcp_optimizer.ingestion]
2025-11-07 10:21:30 [info     ] Successfully fetched workloads [mcp_optimizer.toolhive.toolhive_client] all_workloads=True count=1
2025-11-07 10:21:30 [info     ] Found running workloads from Docker [mcp_optimizer.ingestion] container_names=['mcp-optimizer'] container_workloads=1 remote_names=[] remote_workloads=0 total_workloads=1 workload_details=['mcp-optimizer (url: http://192.168.18.5:48128/mcp)']
2025-11-07 10:21:30 [info     ] Workload ingestion: no changes detected, skipping vector sync [mcp_optimizer.ingestion]
2025-11-07 10:21:30 [info     ] Database engine closed successfully [mcp_optimizer.db.config]
2025-11-07 10:21:30 [info     ] Initial ingestion process completed [mcp_optimizer.cli]
2025-11-07 10:21:30 [info     ] Configuring polling manager    [mcp_optimizer.cli] host=192.168.18.5 port=8080 registry_interval=86400 workload_interval=60
2025-11-07 10:21:30 [info     ] configure_polling called       [mcp_optimizer.polling_manager] host=192.168.18.5 port=8080 registry_interval=86400 workload_interval=60
2025-11-07 10:21:30 [info     ] Polling manager configured successfully [mcp_optimizer.polling_manager] registry_interval_seconds=86400 workload_interval_seconds=60
2025-11-07 10:21:30 [info     ] Background polling thread started [mcp_optimizer.polling_manager]
2025-11-07 10:21:30 [info     ] Starting server                [mcp_optimizer.cli]
2025-11-07 10:21:30 [warning  ] Current configuration will not reload as not all conditions are met, please refer to documentation. [uvicorn.error]
2025-11-07 10:21:30 [info     ] Started server process [1]     [uvicorn.error]
2025-11-07 10:21:30 [info     ] Waiting for application startup. [uvicorn.error]
2025-11-07 10:21:30 [info     ] StreamableHTTP session manager started [mcp.server.streamable_http_manager]
2025-11-07 10:21:30 [info     ] Application startup complete.  [uvicorn.error]
2025-11-07 10:21:30 [info     ] Uvicorn running on http://0.0.0.0:9900 (Press CTRL+C to quit) [uvicorn.error]
2025-11-07 10:21:33 [info     ] Starting polling manager in background thread [mcp_optimizer.polling_manager]
2025-11-07 10:21:33 [info     ] === START POLLING CALLED ===   [mcp_optimizer.polling_manager] registry_interval=86400 workload_interval=60
2025-11-07 10:21:33 [info     ] Delaying polling start to allow server startup [mcp_optimizer.polling_manager] seconds=60
2025-11-07 10:22:16 [info     ] Shutting down                  [uvicorn.error]
2025-11-07 10:22:16 [info     ] Waiting for application shutdown. [uvicorn.error]
2025-11-07 10:22:16 [info     ] StreamableHTTP session manager shutting down [mcp.server.streamable_http_manager]
2025-11-07 10:22:16 [info     ] Application shutdown complete. [uvicorn.error]
2025-11-07 10:22:16 [info     ] Finished server process [1]    [uvicorn.error]
2025-11-07 10:22:16 [info     ] Received signal, initiating graceful shutdown [mcp_optimizer.cli] signal=15
2025-11-07 10:22:16 [info     ] Shutting down polling manager  [mcp_optimizer.polling_manager]
2025-11-07 10:22:16 [info     ] Waiting for polling thread to finish [mcp_optimizer.polling_manager]
2025-11-07 10:22:18 [warning  ] Polling thread did not finish within timeout - forcing exit [mcp_optimizer.polling_manager]
2025-11-07 10:22:18 [info     ] Stopping polling manager       [mcp_optimizer.cli]
2025-11-07 10:22:18 [info     ] Shutting down polling manager  [mcp_optimizer.polling_manager]
2025-11-07 10:22:18 [info     ] Waiting for polling thread to finish [mcp_optimizer.polling_manager]
2025-11-07 10:22:20 [warning  ] Polling thread did not finish within timeout - forcing exit [mcp_optimizer.polling_manager]

and proxy

tail -1000f  mcp-optimizer.log 
10:21AM INFO     Loaded configuration from state for mcp-optimizer
10:21AM INFO     Starting tooling server mcp-optimizer...
10:21AM INFO     OIDC validation disabled, using local user authentication
10:21AM INFO     Using local user authentication for user: nigel
10:21AM INFO     Setting up streamable-http transport...
10:21AM INFO     Deploying workload mcp-optimizer from image ghcr.io/stackloklabs/mcp-optimizer:0.1.0...
10:21AM INFO     Container created: mcp-optimizer
10:21AM INFO     Starting streamable-http transport for mcp-optimizer...
10:21AM INFO     Setting up transparent proxy to forward from host port 48128 to http://127.0.0.1:60116
10:21AM INFO     Applied middleware: mcp-parser
10:21AM INFO     Applied middleware: auth
10:21AM INFO     HTTP transport started for mcp-optimizer on port 48128
10:21AM INFO     MCP server mcp-optimizer started successfully
10:21AM INFO     Server mcp-optimizer belongs to group default, updating 1 registered client(s)
10:21AM INFO     Updating client configuration: /Users/nigel/.cursor/mcp.json
10:21AM INFO     Successfully updated the client config file for MCPServer mcp-optimizer
10:21AM INFO     Successfully updated client configuration: /Users/nigel/.cursor/mcp.json
10:21AM INFO     Running as detached process (PID: 49313)
10:21AM INFO     Detected initialize method call for http://127.0.0.1:60116
10:21AM ERROR    Failed to forward request: dial tcp 127.0.0.1:60116: connect: connection refused
2025/11/07 10:21:16 http: proxy error: dial tcp 127.0.0.1:60116: connect: connection refused
10:21AM ERROR    Failed to forward request: dial tcp 127.0.0.1:60116: connect: connection refused
2025/11/07 10:21:16 http: proxy error: dial tcp 127.0.0.1:60116: connect: connection refused
10:21AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:21AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:21AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:21AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:22AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:22AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:60116
10:22AM INFO     Stopping MCP server: Received signal terminated

We can get round the version issue with a patch like

git diff src/mcp_optimizer/toolhive/toolhive_client.py
diff --git a/src/mcp_optimizer/toolhive/toolhive_client.py b/src/mcp_optimizer/toolhive/toolhive_client.py
index 7d603f3..eef740a 100644
--- a/src/mcp_optimizer/toolhive/toolhive_client.py
+++ b/src/mcp_optimizer/toolhive/toolhive_client.py
@@ -149,13 +149,22 @@ class ToolhiveClient:
             asyncio.run(self._discover_port_async(port))
 
     def _parse_toolhive_version(self, version_str: str) -> Version:
-        """Parse ToolHive version string into a Version object."""
+        """Parse ToolHive version string into a Version object.
+
+        For development/build versions that don't follow SemVer, returns a default version.
+        """
         try:
             version = Version.parse(version_str.replace("v", ""))
             return version
         except (ValueError, TypeError) as e:
-            logger.warning("Invalid semver version string", version=version_str, error=str(e))
-            raise ToolhiveScanError(f"Invalid ToolHive version string: {version_str}") from e
+            # For development builds like "build-7c3a3077", use a default version
+            # This allows the connection to succeed while still logging the issue
+            logger.info(
+                "Using default version for non-semver ToolHive build",
+                version=version_str,
+                default_version="0.0.0-dev"
+            )
+            return Version.parse("0.0.0-dev")
 
     async def _is_toolhive_available(self, host: str, port: int) -> tuple[Version, int]:
         """
@@ -165,7 +174,7 @@ class ToolhiveClient:
             Tuple of (Version object, port) if available, raises ToolhiveScanError otherwise
         """
         try:
-            async with httpx.AsyncClient(timeout=1.0) as client:
+            async with httpx.AsyncClient(timeout=self.timeout) as client:
                 response = await client.get(f"http://{host}:{port}/api/v1beta/version")
                 response.raise_for_status()

That code was inserted as part of #19 so we should consider if the patch above is consistent with that.

There is a PR for that here #52. Merge mindfully!

[therealnb]

The system still does not work end to end. On the proxy there is repeated

10:54AM INFO     MCP server not initialized yet, skipping health check for http://127.0.0.1:48724

until the config on cursor is disabled and re-enabled. Then everything works. The system is waiting for something to call initialise. Then

10:55AM INFO     Detected initialize method call for http://127.0.0.1:48724
10:55AM INFO     Detected Mcp-Session-Id header: 0cdac05084d544fd959f120ecdd1a9c3
10:55AM INFO     Server was initialized successfully for http://127.0.0.1:48724

The client (cursor) has to detect the server, so if we look at its logs

==> MCP user-mcp-optimizer.log <==
2025-11-07 10:53:46.513 [info] Handling CreateClient action
2025-11-07 10:53:46.513 [info] Creating streamableHttp transport
2025-11-07 10:53:46.513 [info] Connecting to streamableHttp server
2025-11-07 10:53:46.517 [info] Handling CreateClient action
2025-11-07 10:53:46.517 [info] Creating streamableHttp transport
2025-11-07 10:53:46.517 [info] Connecting to streamableHttp server
2025-11-07 10:53:46.520 [info] No stored tokens found
2025-11-07 10:53:46.523 [info] No stored tokens found
2025-11-07 10:53:46.532 [error] Client error for command Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.533 [info] Client closed for command
2025-11-07 10:53:46.533 [error] Error connecting to streamableHttp server, falling back to SSE: Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.533 [error] Error connecting to streamableHttp server, falling back to SSE: Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.533 [info] Connecting to SSE server
2025-11-07 10:53:46.535 [error] Client error for command Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.535 [info] Client closed for command
2025-11-07 10:53:46.535 [error] Error connecting to streamableHttp server, falling back to SSE: Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.535 [error] Error connecting to streamableHttp server, falling back to SSE: Error POSTing to endpoint (HTTP 502): 
2025-11-07 10:53:46.535 [info] Connecting to SSE server
2025-11-07 10:53:46.539 [info] No stored tokens found
2025-11-07 10:53:46.546 [error] Client error for command SSE error: Non-200 status code (502)
2025-11-07 10:53:46.546 [error] Error connecting to SSE server after fallback: SSE error: Non-200 status code (502)
2025-11-07 10:53:46.546 [info] Client closed for command
2025-11-07 10:53:46.547 [info] No stored tokens found
2025-11-07 10:53:46.549 [error] Client error for command SSE error: Non-200 status code (502)
2025-11-07 10:53:46.549 [error] Error connecting to SSE server after fallback: SSE error: Non-200 status code (502)
2025-11-07 10:53:46.550 [info] Client closed for command
2025-11-07 10:53:46.576 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.576 [error] No server info found
2025-11-07 10:53:46.577 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.577 [error] No server info found
2025-11-07 10:53:46.577 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.578 [error] No server info found
2025-11-07 10:53:46.578 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.578 [error] No server info found
2025-11-07 10:53:46.595 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.595 [error] No server info found
2025-11-07 10:53:46.597 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.598 [error] No server info found
2025-11-07 10:53:46.599 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.600 [error] No server info found
2025-11-07 10:53:46.601 [info] Handling ListOfferings action, server stored: false
2025-11-07 10:53:46.601 [error] No server info found

We can see it doesn't try very long and gives up before the optimizer is listening

2025-11-07 10:53:48 [info     ] Testing write access to database directory: //app/.venv/lib/python3.13/data
... does some stuff ...
2025-11-07 10:53:59 [info     ] Uvicorn running on http://0.0.0.0:9900 (Press CTRL+C to quit) [uvicorn.error]

On disable - re-enable

2025-11-07 10:55:57.903 [info] Handling DeleteClient action
2025-11-07 10:55:58.857 [info] Handling CreateClient action
2025-11-07 10:55:58.858 [info] Creating streamableHttp transport
2025-11-07 10:55:58.858 [info] Connecting to streamableHttp server
2025-11-07 10:55:58.868 [info] No stored tokens found
2025-11-07 10:55:58.923 [info] No stored tokens found
2025-11-07 10:55:58.934 [info] Successfully connected to streamableHttp server
2025-11-07 10:55:58.934 [info] Storing streamableHttp client
2025-11-07 10:55:58.934 [info] CreateClient completed, server stored: true
2025-11-07 10:55:58.939 [info] No stored tokens found
2025-11-07 10:55:58.950 [info] Handling ListOfferings action, server stored: true
2025-11-07 10:55:58.950 [info] Connected to streamableHttp server, fetching offerings
2025-11-07 10:55:58.953 [info] No stored tokens found
2025-11-07 10:55:58.969 [info] No stored tokens found
2025-11-07 10:55:58.984 [info] No stored tokens found
2025-11-07 10:55:58.989 [info] Found 3 tools, 0 prompts, and 0 resources
2025-11-07 10:58:42.881 [info] SSE stream disconnected, transport will reconnect automatically SSE stream disconnected: TypeError: terminated
2025-11-07 10:58:43.887 [info] No stored tokens found
2025-11-07 10:58:43.897 [error] Client error for command fetch failed
2025-11-07 10:58:43.897 [error] Client error for command Failed to reconnect SSE stream: fetch failed
2025-11-07 10:58:44.972 [info] Handling DeleteClient action
2025-11-07 10:58:44.972 [info] Cleaning up
2025-11-07 10:58:44.980 [info] Handling LogoutServer action
2025-11-07 10:58:44.980 [warning] No stored server URL for logout; proceeding to clear OAuth state using identifier only
2025-11-07 10:58:44.980 [info] Clearing stored OAuth data
2025-11-07 10:58:44.984 [info] Successfully cleared OAuth tokens
2025-11-07 10:58:45.403 [info] No stored tokens found

we find three tools and all is happy in the garden.

The initialise needs to be available directly (<0.1 seconds, at least) after starting the server.

This is also an issue for other servers - e.g. fetch. See here.

This part really looks like a bug in cursor/vscode. It should retry the initialise a little longer.

We do have a pr to run up the http server before we are initialised. It would probably work if we answered the call and it took some time to complete, but returning an error looks like it will break the server configuration.

This is not really related to the initial connection problem.

The MCP spec (or at least the implementation) probably needs better health vs ready semantics.

[therealnb]

We could probably fix this in the toolhive proxy, so I reported this stacklok/toolhive#2499

[therealnb]

There is a proxy fix available here stacklok/toolhive#2504.

[therealnb]

I think the mystery is gone. stacklok/toolhive#2504 is an attempt to fix the initialisation problem and if that PR is not merged, there should be some solution. Discussion here.

#52 should solve the initial connection problem, if I reproduced it correctly. We probably need more customer logs if this is not the case.

[therealnb]

Marking as done.
CC @ptelang. If there is more to do - reopen.