From bcc3643c81130b4a5531d402562c0592d6be6eec Mon Sep 17 00:00:00 2001 From: Deluan Date: Sat, 19 Apr 2025 19:37:32 -0400 Subject: [PATCH] chore: add debug logging to mcp-server Added debug logging throughout the mcp-server components using the standard Go `log` package. All log messages are prefixed with `[MCP]` for easy identification. This includes logging in: main function (startup, CLI execution, registration, serve loop), Tool handlers, Native and WASM fetcher implementations, Wikipedia, Wikidata, and DBpedia data fetching functions Replaced previous `println` statements with `log.Println` or `log.Printf`. --- core/agents/mcp/mcp-server/dbpedia.go | 21 ++++++ core/agents/mcp/mcp-server/fetch_native.go | 12 ++++ core/agents/mcp/mcp-server/fetch_wasm.go | 27 +++++--- core/agents/mcp/mcp-server/main.go | 79 +++++++++++++++++++--- core/agents/mcp/mcp-server/wikidata.go | 44 ++++++++++-- core/agents/mcp/mcp-server/wikipedia.go | 15 +++- 6 files changed, 174 insertions(+), 24 deletions(-) diff --git a/core/agents/mcp/mcp-server/dbpedia.go b/core/agents/mcp/mcp-server/dbpedia.go index 233f92217..a25623a69 100644 --- a/core/agents/mcp/mcp-server/dbpedia.go +++ b/core/agents/mcp/mcp-server/dbpedia.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" // Reusing ErrNotFound from wikidata.go (implicitly via main) "fmt" + "log" "net/http" "net/url" "strings" @@ -20,7 +21,9 @@ const defaultDbpediaTimeout = 20 * time.Second // GetArtistBioFromDBpedia queries DBpedia for an artist's abstract using their name. func GetArtistBioFromDBpedia(fetcher Fetcher, ctx context.Context, name string) (string, error) { + log.Printf("[MCP] Debug: GetArtistBioFromDBpedia called for name: %s", name) if name == "" { + log.Printf("[MCP] Error: GetArtistBioFromDBpedia requires a name.") return "", fmt.Errorf("name is required to query DBpedia by name") } @@ -54,43 +57,53 @@ SELECT DISTINCT ?abstract WHERE { queryValues.Set("format", "application/sparql-results+json") // DBpedia standard format reqURL := fmt.Sprintf("%s?%s", dbpediaEndpoint, queryValues.Encode()) + log.Printf("[MCP] Debug: DBpedia Bio Request URL: %s", reqURL) timeout := defaultDbpediaTimeout if deadline, ok := ctx.Deadline(); ok { timeout = time.Until(deadline) } + log.Printf("[MCP] Debug: Fetching from DBpedia with timeout: %v", timeout) statusCode, bodyBytes, err := fetcher.Fetch(ctx, "GET", reqURL, nil, timeout) if err != nil { + log.Printf("[MCP] Error: Fetcher failed for DBpedia bio request (name: '%s'): %v", name, err) return "", fmt.Errorf("failed to execute DBpedia request: %w", err) } if statusCode != http.StatusOK { + log.Printf("[MCP] Error: DBpedia bio query failed for name '%s' with status %d: %s", name, statusCode, string(bodyBytes)) return "", fmt.Errorf("DBpedia query failed with status %d: %s", statusCode, string(bodyBytes)) } + log.Printf("[MCP] Debug: DBpedia bio query successful (status %d), %d bytes received.", statusCode, len(bodyBytes)) var result SparqlResult if err := json.Unmarshal(bodyBytes, &result); err != nil { // Try reading the raw body for debugging if JSON parsing fails // (Seek back to the beginning might be needed if already read for error) // For simplicity, just return the parsing error now. + log.Printf("[MCP] Error: Failed to decode DBpedia bio response for name '%s': %v", name, err) return "", fmt.Errorf("failed to decode DBpedia response: %w", err) } // Extract the abstract if len(result.Results.Bindings) > 0 { if abstractVal, ok := result.Results.Bindings[0]["abstract"]; ok { + log.Printf("[MCP] Debug: Found DBpedia abstract for '%s'.", name) return abstractVal.Value, nil } } // Use the shared ErrNotFound + log.Printf("[MCP] Warn: No abstract found on DBpedia for name '%s'.", name) return "", ErrNotFound } // GetArtistWikipediaURLFromDBpedia queries DBpedia for an artist's Wikipedia URL using their name. func GetArtistWikipediaURLFromDBpedia(fetcher Fetcher, ctx context.Context, name string) (string, error) { + log.Printf("[MCP] Debug: GetArtistWikipediaURLFromDBpedia called for name: %s", name) if name == "" { + log.Printf("[MCP] Error: GetArtistWikipediaURLFromDBpedia requires a name.") return "", fmt.Errorf("name is required to query DBpedia by name for URL") } @@ -120,32 +133,40 @@ SELECT DISTINCT ?wikiPage WHERE { queryValues.Set("format", "application/sparql-results+json") reqURL := fmt.Sprintf("%s?%s", dbpediaEndpoint, queryValues.Encode()) + log.Printf("[MCP] Debug: DBpedia URL Request URL: %s", reqURL) timeout := defaultDbpediaTimeout if deadline, ok := ctx.Deadline(); ok { timeout = time.Until(deadline) } + log.Printf("[MCP] Debug: Fetching DBpedia URL with timeout: %v", timeout) statusCode, bodyBytes, err := fetcher.Fetch(ctx, "GET", reqURL, nil, timeout) if err != nil { + log.Printf("[MCP] Error: Fetcher failed for DBpedia URL request (name: '%s'): %v", name, err) return "", fmt.Errorf("failed to execute DBpedia URL request: %w", err) } if statusCode != http.StatusOK { + log.Printf("[MCP] Error: DBpedia URL query failed for name '%s' with status %d: %s", name, statusCode, string(bodyBytes)) return "", fmt.Errorf("DBpedia URL query failed with status %d: %s", statusCode, string(bodyBytes)) } + log.Printf("[MCP] Debug: DBpedia URL query successful (status %d), %d bytes received.", statusCode, len(bodyBytes)) var result SparqlResult if err := json.Unmarshal(bodyBytes, &result); err != nil { + log.Printf("[MCP] Error: Failed to decode DBpedia URL response for name '%s': %v", name, err) return "", fmt.Errorf("failed to decode DBpedia URL response: %w", err) } // Extract the URL if len(result.Results.Bindings) > 0 { if pageVal, ok := result.Results.Bindings[0]["wikiPage"]; ok { + log.Printf("[MCP] Debug: Found DBpedia Wikipedia URL for '%s': %s", name, pageVal.Value) return pageVal.Value, nil } } + log.Printf("[MCP] Warn: No Wikipedia URL found on DBpedia for name '%s'.", name) return "", ErrNotFound } diff --git a/core/agents/mcp/mcp-server/fetch_native.go b/core/agents/mcp/mcp-server/fetch_native.go index cb104f0d8..9aa7a3962 100644 --- a/core/agents/mcp/mcp-server/fetch_native.go +++ b/core/agents/mcp/mcp-server/fetch_native.go @@ -7,6 +7,7 @@ import ( "context" "fmt" "io" + "log" "net/http" "time" ) @@ -21,10 +22,12 @@ var _ Fetcher = (*nativeFetcher)(nil) // NewFetcher creates the default native HTTP fetcher. func NewFetcher() Fetcher { + log.Println("[MCP] Debug: Using Native HTTP fetcher") return &nativeFetcher{} } func (nf *nativeFetcher) Fetch(ctx context.Context, method, urlStr string, requestBody []byte, timeout time.Duration) (statusCode int, responseBody []byte, err error) { + log.Printf("[MCP] Debug: Native Fetch: Method=%s, URL=%s, Timeout=%v", method, urlStr, timeout) // Create a client with the specific timeout for this request client := &http.Client{Timeout: timeout} @@ -35,6 +38,7 @@ func (nf *nativeFetcher) Fetch(ctx context.Context, method, urlStr string, reque req, err := http.NewRequestWithContext(ctx, method, urlStr, bodyReader) if err != nil { + log.Printf("[MCP] Error: Native Fetch failed to create request: %v", err) return 0, nil, fmt.Errorf("failed to create native request: %w", err) } @@ -44,28 +48,36 @@ func (nf *nativeFetcher) Fetch(ctx context.Context, method, urlStr string, reque // if different user agents are desired per service. req.Header.Set("User-Agent", "MCPGoServerExample/0.1 (Native Client)") + log.Printf("[MCP] Debug: Native Fetch executing request...") resp, err := client.Do(req) if err != nil { // Let context cancellation errors pass through if ctx.Err() != nil { + log.Printf("[MCP] Debug: Native Fetch context cancelled: %v", ctx.Err()) return 0, nil, ctx.Err() } + log.Printf("[MCP] Error: Native Fetch HTTP request failed: %v", err) return 0, nil, fmt.Errorf("native HTTP request failed: %w", err) } defer resp.Body.Close() statusCode = resp.StatusCode + log.Printf("[MCP] Debug: Native Fetch received status code: %d", statusCode) responseBodyBytes, readErr := io.ReadAll(resp.Body) if readErr != nil { // Still return status code if body read fails + log.Printf("[MCP] Error: Native Fetch failed to read response body: %v", readErr) return statusCode, nil, fmt.Errorf("failed to read native response body: %w", readErr) } responseBody = responseBodyBytes + log.Printf("[MCP] Debug: Native Fetch read %d bytes from response body", len(responseBodyBytes)) // Mimic behavior of returning body even on error status if statusCode < 200 || statusCode >= 300 { + log.Printf("[MCP] Warn: Native Fetch request failed with status %d. Body: %s", statusCode, string(responseBody)) return statusCode, responseBody, fmt.Errorf("native request failed with status %d", statusCode) } + log.Printf("[MCP] Debug: Native Fetch completed successfully.") return statusCode, responseBody, nil } diff --git a/core/agents/mcp/mcp-server/fetch_wasm.go b/core/agents/mcp/mcp-server/fetch_wasm.go index 06fc48bee..27d182e39 100644 --- a/core/agents/mcp/mcp-server/fetch_wasm.go +++ b/core/agents/mcp/mcp-server/fetch_wasm.go @@ -6,6 +6,7 @@ import ( "context" "errors" "fmt" + "log" "time" "unsafe" ) @@ -35,6 +36,7 @@ const ( // callHostHTTPFetch provides a Go-friendly interface to the http_fetch host function. func callHostHTTPFetch(ctx context.Context, method, url string, requestBody []byte, timeout time.Duration) (statusCode int, responseBody []byte, err error) { + log.Printf("[MCP] Debug: WASM Fetch (Host Call): Method=%s, URL=%s, Timeout=%v", method, url, timeout) // --- Prepare Input Pointers --- urlPtr, urlLen := stringToPtr(url) @@ -49,6 +51,7 @@ func callHostHTTPFetch(ctx context.Context, method, url string, requestBody []by // Handle case where context might already be cancelled select { case <-ctx.Done(): + log.Printf("[MCP] Debug: WASM Fetch context cancelled before host call: %v", ctx.Err()) return 0, nil, ctx.Err() default: } @@ -69,6 +72,7 @@ func callHostHTTPFetch(ctx context.Context, method, url string, requestBody []by resultErrorLenPtr := &resultErrorLen // --- Call the Host Function --- + log.Printf("[MCP] Debug: WASM Fetch calling host function http_fetch...") hostReturnCode := http_fetch( urlPtr, urlLen, methodPtr, methodLen, @@ -78,32 +82,42 @@ func callHostHTTPFetch(ctx context.Context, method, url string, requestBody []by resultBodyPtr, resultBodyCapacity, uint32(uintptr(unsafe.Pointer(resultBodyLenPtr))), resultErrorPtr, resultErrorCapacity, uint32(uintptr(unsafe.Pointer(resultErrorLenPtr))), ) + log.Printf("[MCP] Debug: WASM Fetch host function returned code: %d", hostReturnCode) // --- Process Results --- if hostReturnCode != 0 { - return 0, nil, errors.New("host function http_fetch failed internally") + err = errors.New("host function http_fetch failed internally") + log.Printf("[MCP] Error: WASM Fetch host function failed: %v", err) + return 0, nil, err } statusCode = int(resultStatus) + log.Printf("[MCP] Debug: WASM Fetch received status code from host: %d", statusCode) if resultErrorLen > 0 { actualErrorLen := min(resultErrorLen, resultErrorCapacity) errMsg := string(resultErrorBuffer[:actualErrorLen]) - return statusCode, nil, errors.New(errMsg) + err = errors.New(errMsg) + log.Printf("[MCP] Error: WASM Fetch received error from host: %s", errMsg) + return statusCode, nil, err } if resultBodyLen > 0 { actualBodyLen := min(resultBodyLen, resultBodyCapacity) responseBody = make([]byte, actualBodyLen) copy(responseBody, resultBodyBuffer[:actualBodyLen]) + log.Printf("[MCP] Debug: WASM Fetch received %d bytes from host body (reported size: %d)", actualBodyLen, resultBodyLen) if resultBodyLen > resultBodyCapacity { err = fmt.Errorf("response body truncated: received %d bytes, but actual size was %d", actualBodyLen, resultBodyLen) - return statusCode, responseBody, err + log.Printf("[MCP] Warn: WASM Fetch %v", err) + return statusCode, responseBody, err // Return truncated body with error } + log.Printf("[MCP] Debug: WASM Fetch completed successfully.") return statusCode, responseBody, nil } + log.Printf("[MCP] Debug: WASM Fetch completed successfully (no body, no error).") return statusCode, nil, nil } @@ -147,14 +161,11 @@ var _ Fetcher = (*wasmFetcher)(nil) // NewFetcher creates the WASM host function fetcher. func NewFetcher() Fetcher { - println("Using WASM host fetcher") // Add a log for confirmation + log.Println("[MCP] Debug: Using WASM host fetcher") return &wasmFetcher{} } func (wf *wasmFetcher) Fetch(ctx context.Context, method, url string, requestBody []byte, timeout time.Duration) (statusCode int, responseBody []byte, err error) { - // Directly call the wrapper provided by the user - // Note: Headers like Accept/User-Agent are assumed to be handled by the host - // or aren't settable via this interface. If they are critical, the host - // function definition (`http_fetch`) would need to be extended. + // Directly call the wrapper which now contains logging return callHostHTTPFetch(ctx, method, url, requestBody, timeout) } diff --git a/core/agents/mcp/mcp-server/main.go b/core/agents/mcp/mcp-server/main.go index 5502123ac..abc3bde0e 100644 --- a/core/agents/mcp/mcp-server/main.go +++ b/core/agents/mcp/mcp-server/main.go @@ -5,6 +5,7 @@ import ( "errors" "flag" "fmt" + "log" "net/url" "os" @@ -34,11 +35,13 @@ type ArtistURLArgs struct { } func main() { + log.Println("[MCP] Starting mcp-server...") done := make(chan struct{}) // Create the appropriate fetcher (native or WASM based on build tags) - // The context passed here is just background; specific calls might use request-scoped contexts. + log.Printf("[MCP] Debug: Creating fetcher...") fetcher := NewFetcher() + log.Printf("[MCP] Debug: Fetcher created successfully.") // --- Command Line Flag Handling --- nameFlag := flag.String("name", "", "Artist name to query directly") @@ -46,6 +49,7 @@ func main() { flag.Parse() if *nameFlag != "" || *mbidFlag != "" { + log.Printf("[MCP] Debug: Running tools directly via CLI flags (Name: '%s', MBID: '%s')", *nameFlag, *mbidFlag) fmt.Println("--- Running Tools Directly ---") // Call getArtistBiography @@ -54,11 +58,14 @@ func main() { fmt.Println(" Error: --mbid or --name is required for get_artist_biography") } else { // Use context.Background for CLI calls + log.Printf("[MCP] Debug: CLI calling getArtistBiography...") bio, bioErr := getArtistBiography(fetcher, context.Background(), "cli", *nameFlag, *mbidFlag) if bioErr != nil { fmt.Printf(" Error: %v\n", bioErr) + log.Printf("[MCP] Error: CLI getArtistBiography failed: %v", bioErr) } else { fmt.Printf(" Result: %s\n", bio) + log.Printf("[MCP] Debug: CLI getArtistBiography succeeded.") } } @@ -67,155 +74,203 @@ func main() { if *mbidFlag == "" && *nameFlag == "" { fmt.Println(" Error: --mbid or --name is required for get_artist_url") } else { + log.Printf("[MCP] Debug: CLI calling getArtistURL...") urlResult, urlErr := getArtistURL(fetcher, context.Background(), "cli", *nameFlag, *mbidFlag) if urlErr != nil { fmt.Printf(" Error: %v\n", urlErr) + log.Printf("[MCP] Error: CLI getArtistURL failed: %v", urlErr) } else { fmt.Printf(" Result: %s\n", urlResult) + log.Printf("[MCP] Debug: CLI getArtistURL succeeded.") } } fmt.Println("-----------------------------") + log.Printf("[MCP] Debug: CLI execution finished.") return // Exit after direct execution } // --- End Command Line Flag Handling --- + log.Printf("[MCP] Debug: Initializing MCP server...") server := mcp_golang.NewServer(stdio.NewStdioServerTransport()) + + log.Printf("[MCP] Debug: Registering tool 'hello'...") err := server.RegisterTool("hello", "Say hello to a person", func(arguments MyFunctionsArguments) (*mcp_golang.ToolResponse, error) { + log.Printf("[MCP] Debug: Tool 'hello' called with args: %+v", arguments) return mcp_golang.NewToolResponse(mcp_golang.NewTextContent(fmt.Sprintf("Hello, %server!", arguments.Submitter))), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register tool 'hello': %v", err) } + log.Printf("[MCP] Debug: Registering tool 'get_artist_biography'...") err = server.RegisterTool("get_artist_biography", "Get the biography of an artist", func(arguments ArtistBiography) (*mcp_golang.ToolResponse, error) { + log.Printf("[MCP] Debug: Tool 'get_artist_biography' called with args: %+v", arguments) + // Using background context in handlers as request context isn't passed through MCP library currently bio, err := getArtistBiography(fetcher, context.Background(), arguments.ID, arguments.Name, arguments.MBID) if err != nil { - return nil, err + log.Printf("[MCP] Error: getArtistBiography handler failed: %v", err) + return nil, fmt.Errorf("handler returned an error: %w", err) // Return structured error } + log.Printf("[MCP] Debug: Tool 'get_artist_biography' succeeded.") return mcp_golang.NewToolResponse(mcp_golang.NewTextContent(bio)), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register tool 'get_artist_biography': %v", err) } + log.Printf("[MCP] Debug: Registering tool 'get_artist_url'...") err = server.RegisterTool("get_artist_url", "Get the artist's specific Wikipedia URL via MBID, or a search URL using name as fallback", func(arguments ArtistURLArgs) (*mcp_golang.ToolResponse, error) { + log.Printf("[MCP] Debug: Tool 'get_artist_url' called with args: %+v", arguments) urlResult, err := getArtistURL(fetcher, context.Background(), arguments.ID, arguments.Name, arguments.MBID) if err != nil { - return nil, err + log.Printf("[MCP] Error: getArtistURL handler failed: %v", err) + return nil, fmt.Errorf("handler returned an error: %w", err) } + log.Printf("[MCP] Debug: Tool 'get_artist_url' succeeded.") return mcp_golang.NewToolResponse(mcp_golang.NewTextContent(urlResult)), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register tool 'get_artist_url': %v", err) } + log.Printf("[MCP] Debug: Registering prompt 'prompt_test'...") err = server.RegisterPrompt("prompt_test", "This is a test prompt", func(arguments Content) (*mcp_golang.PromptResponse, error) { + log.Printf("[MCP] Debug: Prompt 'prompt_test' called with args: %+v", arguments) return mcp_golang.NewPromptResponse("description", mcp_golang.NewPromptMessage(mcp_golang.NewTextContent(fmt.Sprintf("Hello, %server!", arguments.Title)), mcp_golang.RoleUser)), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register prompt 'prompt_test': %v", err) } + log.Printf("[MCP] Debug: Registering resource 'test://resource'...") err = server.RegisterResource("test://resource", "resource_test", "This is a test resource", "application/json", func() (*mcp_golang.ResourceResponse, error) { + log.Printf("[MCP] Debug: Resource 'test://resource' called") return mcp_golang.NewResourceResponse(mcp_golang.NewTextEmbeddedResource("test://resource", "This is a test resource", "application/json")), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register resource 'test://resource': %v", err) } + log.Printf("[MCP] Debug: Registering resource 'file://app_logs'...") err = server.RegisterResource("file://app_logs", "app_logs", "The app logs", "text/plain", func() (*mcp_golang.ResourceResponse, error) { + log.Printf("[MCP] Debug: Resource 'file://app_logs' called") return mcp_golang.NewResourceResponse(mcp_golang.NewTextEmbeddedResource("file://app_logs", "This is a test resource", "text/plain")), nil }) if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Failed to register resource 'file://app_logs': %v", err) } + log.Println("[MCP] MCP server initialized and starting to serve...") err = server.Serve() if err != nil { - panic(err) + log.Fatalf("[MCP] Fatal: Server exited with error: %v", err) } - <-done + log.Println("[MCP] Server exited cleanly.") + <-done // Keep running until interrupted (though server.Serve() is blocking) } func getArtistBiography(fetcher Fetcher, ctx context.Context, id, name, mbid string) (string, error) { + log.Printf("[MCP] Debug: getArtistBiography called (id: %s, name: %s, mbid: %s)", id, name, mbid) if mbid == "" { fmt.Fprintf(os.Stderr, "MBID not provided, attempting DBpedia lookup by name: %s\n", name) + log.Printf("[MCP] Debug: MBID not provided, attempting DBpedia lookup by name: %s", name) } else { // 1. Attempt Wikidata MBID lookup first + log.Printf("[MCP] Debug: Attempting Wikidata URL lookup for MBID: %s", mbid) wikiURL, err := GetArtistWikipediaURL(fetcher, ctx, mbid) if err == nil { // 1a. Found Wikidata URL, now fetch from Wikipedia API + log.Printf("[MCP] Debug: Found Wikidata URL '%s', fetching bio from Wikipedia API...", wikiURL) bio, errBio := GetBioFromWikipediaAPI(fetcher, ctx, wikiURL) if errBio == nil { + log.Printf("[MCP] Debug: Successfully fetched bio from Wikipedia API for '%s'.", name) return bio, nil // Success via Wikidata/Wikipedia! } else { // Failed to get bio even though URL was found + log.Printf("[MCP] Error: Found Wikipedia URL (%s) via MBID %s, but failed to fetch bio: %v", wikiURL, mbid, errBio) fmt.Fprintf(os.Stderr, "Found Wikipedia URL (%s) via MBID %s, but failed to fetch bio: %v\n", wikiURL, mbid, errBio) // Fall through to try DBpedia by name as a last resort? // Let's fall through for now. } } else if !errors.Is(err, ErrNotFound) { // Wikidata lookup failed for a reason other than not found (e.g., network) + log.Printf("[MCP] Error: Wikidata URL lookup failed for MBID %s (non-NotFound error): %v", mbid, err) fmt.Fprintf(os.Stderr, "Wikidata URL lookup failed for MBID %s (non-NotFound error): %v\n", mbid, err) // Don't proceed to DBpedia name lookup if Wikidata had a technical failure return "", fmt.Errorf("Wikidata lookup failed: %w", err) } else { // Wikidata lookup returned ErrNotFound for MBID + log.Printf("[MCP] Debug: MBID %s not found on Wikidata, attempting DBpedia lookup by name: %s", mbid, name) fmt.Fprintf(os.Stderr, "MBID %s not found on Wikidata, attempting DBpedia lookup by name: %s\n", mbid, name) } } // 2. Attempt DBpedia lookup by name (if MBID was missing or failed with ErrNotFound) if name == "" { + log.Printf("[MCP] Error: Cannot find artist bio: MBID lookup failed/missing, and no name provided.") return "", fmt.Errorf("cannot find artist: MBID lookup failed or MBID not provided, and no name provided for DBpedia fallback") } + log.Printf("[MCP] Debug: Attempting DBpedia bio lookup by name: %s", name) dbpediaBio, errDb := GetArtistBioFromDBpedia(fetcher, ctx, name) if errDb == nil { + log.Printf("[MCP] Debug: Successfully fetched bio from DBpedia for '%s'.", name) return dbpediaBio, nil // Success via DBpedia! } // 3. If both Wikidata (MBID) and DBpedia (Name) failed if errors.Is(errDb, ErrNotFound) { + log.Printf("[MCP] Error: Artist '%s' (MBID: %s) not found via Wikidata or DBpedia name lookup.", name, mbid) return "", fmt.Errorf("artist '%s' (MBID: %s) not found via Wikidata MBID or DBpedia Name lookup", name, mbid) } // Return DBpedia's error if it wasn't ErrNotFound + log.Printf("[MCP] Error: DBpedia lookup failed for name '%s': %v", name, errDb) return "", fmt.Errorf("DBpedia lookup failed for name '%s': %w", name, errDb) } // getArtistURL attempts to find the specific Wikipedia URL using MBID (via Wikidata), // then by Name (via DBpedia), falling back to a search URL using name. func getArtistURL(fetcher Fetcher, ctx context.Context, id, name, mbid string) (string, error) { + log.Printf("[MCP] Debug: getArtistURL called (id: %s, name: %s, mbid: %s)", id, name, mbid) if mbid == "" { fmt.Fprintf(os.Stderr, "getArtistURL: MBID not provided, attempting DBpedia lookup by name: %s\n", name) + log.Printf("[MCP] Debug: getArtistURL: MBID not provided, attempting DBpedia lookup by name: %s", name) } else { // Try to get the specific URL from Wikidata using MBID + log.Printf("[MCP] Debug: getArtistURL: Attempting Wikidata URL lookup for MBID: %s", mbid) wikiURL, err := GetArtistWikipediaURL(fetcher, ctx, mbid) if err == nil && wikiURL != "" { + log.Printf("[MCP] Debug: getArtistURL: Found specific URL '%s' via Wikidata MBID.", wikiURL) return wikiURL, nil // Found specific URL via MBID } // Log error if Wikidata lookup failed for reasons other than not found if err != nil && !errors.Is(err, ErrNotFound) { + log.Printf("[MCP] Error: getArtistURL: Wikidata URL lookup failed for MBID %s (non-NotFound error): %v", mbid, err) fmt.Fprintf(os.Stderr, "getArtistURL: Wikidata URL lookup failed for MBID %s (non-NotFound error): %v\n", mbid, err) // Fall through to try DBpedia if name is available } else if errors.Is(err, ErrNotFound) { + log.Printf("[MCP] Debug: getArtistURL: MBID %s not found on Wikidata, attempting DBpedia lookup by name: %s", mbid, name) fmt.Fprintf(os.Stderr, "getArtistURL: MBID %s not found on Wikidata, attempting DBpedia lookup by name: %s\n", mbid, name) } } // Fallback 1: Try DBpedia lookup by name if name != "" { + log.Printf("[MCP] Debug: getArtistURL: Attempting DBpedia URL lookup by name: %s", name) dbpediaWikiURL, errDb := GetArtistWikipediaURLFromDBpedia(fetcher, ctx, name) if errDb == nil && dbpediaWikiURL != "" { + log.Printf("[MCP] Debug: getArtistURL: Found specific URL '%s' via DBpedia Name lookup.", dbpediaWikiURL) return dbpediaWikiURL, nil // Found specific URL via DBpedia Name lookup } // Log error if DBpedia lookup failed for reasons other than not found if errDb != nil && !errors.Is(errDb, ErrNotFound) { + log.Printf("[MCP] Error: getArtistURL: DBpedia URL lookup failed for name '%s' (non-NotFound error): %v", name, errDb) fmt.Fprintf(os.Stderr, "getArtistURL: DBpedia URL lookup failed for name '%s' (non-NotFound error): %v\n", name, errDb) // Fall through to search URL fallback } else if errors.Is(errDb, ErrNotFound) { + log.Printf("[MCP] Debug: getArtistURL: Name '%s' not found on DBpedia, attempting search fallback", name) fmt.Fprintf(os.Stderr, "getArtistURL: Name '%s' not found on DBpedia, attempting search fallback\n", name) } } @@ -223,10 +278,12 @@ func getArtistURL(fetcher Fetcher, ctx context.Context, id, name, mbid string) ( // Fallback 2: Generate a search URL if name is provided if name != "" { searchURL := fmt.Sprintf("https://en.wikipedia.org/w/index.php?search=%s", url.QueryEscape(name)) + log.Printf("[MCP] Debug: getArtistURL: Falling back to search URL: %s", searchURL) fmt.Fprintf(os.Stderr, "getArtistURL: Falling back to search URL: %s\n", searchURL) return searchURL, nil } // Final error: MBID lookup failed (or no MBID given) AND no name provided for fallback + log.Printf("[MCP] Error: getArtistURL: Cannot generate Wikipedia URL: Lookups failed and no name provided.") return "", fmt.Errorf("cannot generate Wikipedia URL: Wikidata/DBpedia lookups failed and no artist name provided for search fallback") } diff --git a/core/agents/mcp/mcp-server/wikidata.go b/core/agents/mcp/mcp-server/wikidata.go index 0097a9b8a..4d94bc09a 100644 --- a/core/agents/mcp/mcp-server/wikidata.go +++ b/core/agents/mcp/mcp-server/wikidata.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "log" "net/http" "net/url" "os" @@ -33,8 +34,11 @@ type SparqlValue struct { } // GetArtistBioFromWikidata queries Wikidata for an artist's description using their MBID. +// NOTE: This function is currently UNUSED as the main logic prefers Wikipedia/DBpedia. func GetArtistBioFromWikidata(client *http.Client, mbid string) (string, error) { + log.Printf("[MCP] Debug: GetArtistBioFromWikidata called for MBID: %s", mbid) if mbid == "" { + log.Printf("[MCP] Error: GetArtistBioFromWikidata requires an MBID.") return "", fmt.Errorf("MBID is required to query Wikidata") } @@ -56,17 +60,21 @@ LIMIT 1`, mbid) queryValues.Set("format", "json") reqURL := fmt.Sprintf("%s?%s", wikidataEndpoint, queryValues.Encode()) + log.Printf("[MCP] Debug: Wikidata Bio Request URL: %s", reqURL) req, err := http.NewRequest("GET", reqURL, nil) if err != nil { + log.Printf("[MCP] Error: Failed to create Wikidata bio request: %v", err) return "", fmt.Errorf("failed to create Wikidata request: %w", err) } req.Header.Set("Accept", "application/sparql-results+json") req.Header.Set("User-Agent", "MCPGoServerExample/0.1 (https://example.com/contact)") // Good practice to identify your client // Execute the request + log.Printf("[MCP] Debug: Executing Wikidata bio request...") resp, err := client.Do(req) if err != nil { + log.Printf("[MCP] Error: Failed to execute Wikidata bio request: %v", err) return "", fmt.Errorf("failed to execute Wikidata request: %w", err) } defer resp.Body.Close() @@ -78,30 +86,37 @@ LIMIT 1`, mbid) if readErr == nil { errorMsg = string(bodyBytes) } + log.Printf("[MCP] Error: Wikidata bio query failed with status %d: %s", resp.StatusCode, errorMsg) return "", fmt.Errorf("Wikidata query failed with status %d: %s", resp.StatusCode, errorMsg) } + log.Printf("[MCP] Debug: Wikidata bio query successful (status %d).", resp.StatusCode) // Parse the response var result SparqlResult if err := json.NewDecoder(resp.Body).Decode(&result); err != nil { + log.Printf("[MCP] Error: Failed to decode Wikidata bio response: %v", err) return "", fmt.Errorf("failed to decode Wikidata response: %w", err) } // Extract the description if len(result.Results.Bindings) > 0 { if descriptionVal, ok := result.Results.Bindings[0]["artistDescription"]; ok { + log.Printf("[MCP] Debug: Found description for MBID %s", mbid) return descriptionVal.Value, nil } } + log.Printf("[MCP] Warn: No English description found on Wikidata for MBID %s", mbid) return "", fmt.Errorf("no English description found on Wikidata for MBID %s", mbid) } // GetArtistWikipediaURL queries Wikidata for an artist's English Wikipedia page URL using MBID. // It tries searching by MBID first, then falls back to searching by name. func GetArtistWikipediaURL(fetcher Fetcher, ctx context.Context, mbid string) (string, error) { + log.Printf("[MCP] Debug: GetArtistWikipediaURL called for MBID: %s", mbid) // 1. Try finding by MBID if mbid == "" { + log.Printf("[MCP] Error: GetArtistWikipediaURL requires an MBID.") return "", fmt.Errorf("MBID is required to find Wikipedia URL on Wikidata") } else { // SPARQL query to find the enwiki URL for an entity with a specific MusicBrainz ID @@ -113,25 +128,39 @@ SELECT ?article WHERE { } LIMIT 1`, mbid) + log.Printf("[MCP] Debug: Executing Wikidata URL query for MBID: %s", mbid) foundURL, err := executeWikidataURLQuery(fetcher, ctx, sparqlQuery) if err == nil && foundURL != "" { + log.Printf("[MCP] Debug: Found Wikipedia URL '%s' via MBID %s", foundURL, mbid) return foundURL, nil // Found via MBID } - fmt.Fprintf(os.Stderr, "Wikidata URL lookup via MBID %s failed: %v\n", mbid, err) - return "", fmt.Errorf("Wikidata URL lookup via MBID failed: %w", err) + // Use the specific ErrNotFound + if errors.Is(err, ErrNotFound) { + log.Printf("[MCP] Debug: MBID %s not found on Wikidata for URL lookup.", mbid) + return "", ErrNotFound // Explicitly return ErrNotFound + } + // Log other errors + if err != nil { + log.Printf("[MCP] Error: Wikidata URL lookup via MBID %s failed: %v", mbid, err) + fmt.Fprintf(os.Stderr, "Wikidata URL lookup via MBID %s failed: %v\n", mbid, err) + return "", fmt.Errorf("Wikidata URL lookup via MBID failed: %w", err) + } } - // Should not be reached if MBID is provided - return "", fmt.Errorf("internal error: reached end of GetArtistWikipediaURL unexpectedly") + // Should ideally not be reached if MBID is required and lookup failed or was not found + log.Printf("[MCP] Warn: Reached end of GetArtistWikipediaURL unexpectedly for MBID %s", mbid) + return "", ErrNotFound // Return ErrNotFound if somehow reached } // executeWikidataURLQuery is a helper to run SPARQL and extract the first bound URL for '?article'. func executeWikidataURLQuery(fetcher Fetcher, ctx context.Context, sparqlQuery string) (string, error) { + log.Printf("[MCP] Debug: executeWikidataURLQuery called.") queryValues := url.Values{} queryValues.Set("query", sparqlQuery) queryValues.Set("format", "json") reqURL := fmt.Sprintf("%s?%s", wikidataEndpoint, queryValues.Encode()) + log.Printf("[MCP] Debug: Wikidata Sparql Request URL: %s", reqURL) // Directly use the fetcher // Note: Headers (Accept, User-Agent) are now handled by the Fetcher implementation @@ -143,27 +172,34 @@ func executeWikidataURLQuery(fetcher Fetcher, ctx context.Context, sparqlQuery s if deadline, ok := ctx.Deadline(); ok { timeout = time.Until(deadline) } + log.Printf("[MCP] Debug: Fetching from Wikidata with timeout: %v", timeout) statusCode, bodyBytes, err := fetcher.Fetch(ctx, "GET", reqURL, nil, timeout) if err != nil { + log.Printf("[MCP] Error: Fetcher failed for Wikidata SPARQL request: %v", err) return "", fmt.Errorf("failed to execute Wikidata request: %w", err) } // Check status code. Fetcher interface implies body might be returned even on error. if statusCode != http.StatusOK { + log.Printf("[MCP] Error: Wikidata SPARQL query failed with status %d: %s", statusCode, string(bodyBytes)) return "", fmt.Errorf("Wikidata query failed with status %d: %s", statusCode, string(bodyBytes)) } + log.Printf("[MCP] Debug: Wikidata SPARQL query successful (status %d), %d bytes received.", statusCode, len(bodyBytes)) var result SparqlResult if err := json.Unmarshal(bodyBytes, &result); err != nil { // Use Unmarshal for byte slice + log.Printf("[MCP] Error: Failed to decode Wikidata SPARQL response: %v", err) return "", fmt.Errorf("failed to decode Wikidata response: %w", err) } if len(result.Results.Bindings) > 0 { if articleVal, ok := result.Results.Bindings[0]["article"]; ok { + log.Printf("[MCP] Debug: Found Wikidata article URL: %s", articleVal.Value) return articleVal.Value, nil } } + log.Printf("[MCP] Debug: No Wikidata article URL found in SPARQL response.") return "", ErrNotFound } diff --git a/core/agents/mcp/mcp-server/wikipedia.go b/core/agents/mcp/mcp-server/wikipedia.go index a813c0500..955bf9bc9 100644 --- a/core/agents/mcp/mcp-server/wikipedia.go +++ b/core/agents/mcp/mcp-server/wikipedia.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log" "net/http" "net/url" "strings" @@ -33,10 +34,13 @@ const defaultWikipediaTimeout = 15 * time.Second // GetBioFromWikipediaAPI fetches the introductory text of a Wikipedia page. func GetBioFromWikipediaAPI(fetcher Fetcher, ctx context.Context, wikipediaURL string) (string, error) { + log.Printf("[MCP] Debug: GetBioFromWikipediaAPI called for URL: %s", wikipediaURL) pageTitle, err := extractPageTitleFromURL(wikipediaURL) if err != nil { + log.Printf("[MCP] Error: Could not extract title from Wikipedia URL '%s': %v", wikipediaURL, err) return "", fmt.Errorf("could not extract title from Wikipedia URL %s: %w", wikipediaURL, err) } + log.Printf("[MCP] Debug: Extracted Wikipedia page title: %s", pageTitle) // Prepare API request parameters apiParams := url.Values{} @@ -49,35 +53,44 @@ func GetBioFromWikipediaAPI(fetcher Fetcher, ctx context.Context, wikipediaURL s apiParams.Set("redirects", "1") // Follow redirects reqURL := fmt.Sprintf("%s?%s", mediaWikiAPIEndpoint, apiParams.Encode()) + log.Printf("[MCP] Debug: MediaWiki API Request URL: %s", reqURL) timeout := defaultWikipediaTimeout if deadline, ok := ctx.Deadline(); ok { timeout = time.Until(deadline) } + log.Printf("[MCP] Debug: Fetching from MediaWiki with timeout: %v", timeout) statusCode, bodyBytes, err := fetcher.Fetch(ctx, "GET", reqURL, nil, timeout) if err != nil { + log.Printf("[MCP] Error: Fetcher failed for MediaWiki request (title: '%s'): %v", pageTitle, err) return "", fmt.Errorf("failed to execute MediaWiki request for title '%s': %w", pageTitle, err) } if statusCode != http.StatusOK { + log.Printf("[MCP] Error: MediaWiki query for '%s' failed with status %d: %s", pageTitle, statusCode, string(bodyBytes)) return "", fmt.Errorf("MediaWiki query for '%s' failed with status %d: %s", pageTitle, statusCode, string(bodyBytes)) } + log.Printf("[MCP] Debug: MediaWiki query successful (status %d), %d bytes received.", statusCode, len(bodyBytes)) // Parse the response var result MediaWikiQueryResult if err := json.Unmarshal(bodyBytes, &result); err != nil { + log.Printf("[MCP] Error: Failed to decode MediaWiki response for '%s': %v", pageTitle, err) return "", fmt.Errorf("failed to decode MediaWiki response for '%s': %w", pageTitle, err) } // Extract the text - MediaWiki API returns pages keyed by page ID - for _, page := range result.Query.Pages { + for pageID, page := range result.Query.Pages { + log.Printf("[MCP] Debug: Processing MediaWiki page ID: %s, Title: %s", pageID, page.Title) if page.Extract != "" { // Often includes a newline at the end, trim it + log.Printf("[MCP] Debug: Found extract for '%s'. Length: %d", pageTitle, len(page.Extract)) return strings.TrimSpace(page.Extract), nil } } + log.Printf("[MCP] Warn: No extract found in MediaWiki response for title '%s'", pageTitle) return "", fmt.Errorf("no extract found in MediaWiki response for title '%s' (page might not exist or be empty)", pageTitle) }