aherman
/
proxysql
mirror of https://github.com/sysown/proxysql
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

feat: Add structured logging with timing and request IDs

Browse Source 
Add comprehensive structured logging for NL2SQL LLM API calls with
request correlation, timing metrics, and detailed error context.

Changes:
- Add request_id field to NL2SQLRequest with UUID-like auto-generation
- Add structured logging macros:
  * LOG_LLM_REQUEST: Logs URL, model, prompt length with request ID
  * LOG_LLM_RESPONSE: Logs HTTP status, duration_ms, response preview
  * LOG_LLM_ERROR: Logs error phase, message, and status code
- Update call_generic_openai() signature to accept req_id parameter
- Update call_generic_anthropic() signature to accept req_id parameter
- Add timing metrics to both LLM call functions using clock_gettime()
- Replace existing debug logging with structured logging macros
- Update convert() to pass request_id to LLM calls

Request IDs are generated as UUID-like strings (e.g., "12345678-9abc-def0-1234-567890abcdef")
and are included in all log messages for correlation. This allows tracking
a single NL2SQL request through all log lines from request to response.

Timing is measured using CLOCK_MONOTONIC for accurate duration tracking
of LLM API calls, reported in milliseconds.

This provides much better debugging capability when troubleshooting
NL2SQL issues, as administrators can now:
- Correlate all log lines for a single request
- See exact timing of LLM API calls
- Identify which phase of processing failed
- Track request/response metrics

Fixes #2 - Add Structured Logging
pull/5310/head
Rene Cannao 1 month ago
parent 45e592b623
commit d0dc36ac0b
3 changed files with 117 additions and 28 deletions
Show Stats Download Patch File Download Diff File

19
include/NL2SQL_Converter.h
Unescape View File

@ -85,7 +85,18 @@ struct NL2SQLRequest {
bool allow_cache; ///< Enable semantic cache lookup
std::vector<std::string> context_tables; ///< Optional table hints for schema
NL2SQLRequest() : max_latency_ms(0), allow_cache(true) {}
// Request tracking for correlation and debugging
std::string request_id; ///< Unique ID for this request (UUID-like)
NL2SQLRequest() : max_latency_ms(0), allow_cache(true) {
// Generate UUID-like request ID for correlation
char uuid[64];
snprintf(uuid, sizeof(uuid), "%08lx-%04x-%04x-%04x-%012lx",
(unsigned long)rand(), (unsigned)rand() & 0xffff,
(unsigned)rand() & 0xffff, (unsigned)rand() & 0xffff,
(unsigned long)rand() & 0xffffffffffff);
request_id = uuid;
}
};
/**
@ -189,9 +200,11 @@ private:
// Internal methods
std::string build_prompt(const NL2SQLRequest& req, const std::string& schema_context);
std::string call_generic_openai(const std::string& prompt, const std::string& model,
const std::string& url, const char* key);
const std::string& url, const char* key,
const std::string& req_id = "");
std::string call_generic_anthropic(const std::string& prompt, const std::string& model,
const std::string& url, const char* key);
const std::string& url, const char* key,
const std::string& req_id = "");
NL2SQLResult check_vector_cache(const NL2SQLRequest& req);
void store_in_vector_cache(const NL2SQLRequest& req, const NL2SQLResult& result);
std::string get_schema_context(const std::vector<std::string>& tables);

122
lib/LLM_Clients.cpp
Unescape View File

@ -28,9 +28,61 @@
#include "json.hpp"
#include <curl/curl.h>
#include <time.h>
using json = nlohmann::json;
// ============================================================================
// Structured Logging Macros
// ============================================================================
/**
* @brief Logging macros for LLM API calls with request correlation
*
* These macros provide structured logging with:
* - Request ID for correlation across log lines
* - Key parameters (URL, model, prompt length)
* - Response metrics (status code, duration, response preview)
* - Error context (phase, error message, status)
*/
#define LOG_LLM_REQUEST(req_id, url, model, prompt) \
do { \
if (req_id && strlen(req_id) > 0) { \
proxy_debug(PROXY_DEBUG_NL2SQL, 2, \
"NL2SQL [%s]: REQUEST url=%s model=%s prompt_len=%zu\n", \
req_id, url, model, prompt.length()); \
} else { \
proxy_debug(PROXY_DEBUG_NL2SQL, 2, \
"NL2SQL: REQUEST url=%s model=%s prompt_len=%zu\n", \
url, model, prompt.length()); \
} \
} while(0)
#define LOG_LLM_RESPONSE(req_id, status, duration_ms, response_preview) \
do { \
if (req_id && strlen(req_id) > 0) { \
proxy_debug(PROXY_DEBUG_NL2SQL, 3, \
"NL2SQL [%s]: RESPONSE status=%d duration_ms=%ld response=%s\n", \
req_id, status, duration_ms, response_preview.c_str()); \
} else { \
proxy_debug(PROXY_DEBUG_NL2SQL, 3, \
"NL2SQL: RESPONSE status=%d duration_ms=%ld response=%s\n", \
status, duration_ms, response_preview.c_str()); \
} \
} while(0)
#define LOG_LLM_ERROR(req_id, phase, error, status) \
do { \
if (req_id && strlen(req_id) > 0) { \
proxy_error("NL2SQL [%s]: ERROR phase=%s error=%s status=%d\n", \
req_id, phase, error, status); \
} else { \
proxy_error("NL2SQL: ERROR phase=%s error=%s status=%d\n", \
phase, error, status); \
} \
} while(0)
// ============================================================================
// Write callback for curl responses
// ============================================================================
@ -99,15 +151,24 @@ static size_t WriteCallback(void* contents, size_t size, size_t nmemb, void* use
* @param model Model name to use
* @param url Full API endpoint URL
* @param key API key (can be NULL for local endpoints)
* @param req_id Request ID for correlation (optional)
* @return Generated SQL or empty string on error
*/
std::string NL2SQL_Converter::call_generic_openai(const std::string& prompt, const std::string& model,
const std::string& url, const char* key) {
const std::string& url, const char* key,
const std::string& req_id) {
// Start timing
struct timespec start_ts, end_ts;
clock_gettime(CLOCK_MONOTONIC, &start_ts);
// Log request
LOG_LLM_REQUEST(req_id.c_str(), url.c_str(), model.c_str(), prompt);
std::string response_data;
CURL* curl = curl_easy_init();
if (!curl) {
proxy_error("NL2SQL: Failed to initialize curl for OpenAI-compatible provider\n");
LOG_LLM_ERROR(req_id.c_str(), "init", "Failed to initialize curl", 0);
return "";
}
@ -152,14 +213,16 @@ std::string NL2SQL_Converter::call_generic_openai(const std::string& prompt, con
curl_easy_setopt(curl, CURLOPT_HTTPHEADER, headers);
proxy_debug(PROXY_DEBUG_NL2SQL, 2, "NL2SQL: Calling OpenAI-compatible provider: %s (model: %s)\n",
url.c_str(), model.c_str());
// Perform request
CURLcode res = curl_easy_perform(curl);
// Calculate duration
clock_gettime(CLOCK_MONOTONIC, &end_ts);
int64_t duration_ms = (end_ts.tv_sec - start_ts.tv_sec) * 1000 +
(end_ts.tv_nsec - start_ts.tv_nsec) / 1000000;
if (res != CURLE_OK) {
proxy_error("NL2SQL: OpenAI-compatible curl_easy_perform() failed: %s\n", curl_easy_strerror(res));
LOG_LLM_ERROR(req_id.c_str(), "curl", curl_easy_strerror(res), 0);
curl_slist_free_all(headers);
curl_easy_cleanup(curl);
return "";
@ -199,20 +262,21 @@ std::string NL2SQL_Converter::call_generic_openai(const std::string& prompt, con
sql = sql.substr(trim_start, trim_end - trim_start + 1);
}
proxy_debug(PROXY_DEBUG_NL2SQL, 3, "NL2SQL: OpenAI-compatible provider returned SQL: %s\n", sql.c_str());
// Log successful response with timing
std::string preview = sql.length() > 100 ? sql.substr(0, 100) + "..." : sql;
LOG_LLM_RESPONSE(req_id.c_str(), 200, duration_ms, preview);
return sql;
}
}
proxy_error("NL2SQL: OpenAI-compatible response missing expected fields\n");
LOG_LLM_ERROR(req_id.c_str(), "parse", "Response missing expected fields", 0);
return "";
} catch (const json::parse_error& e) {
proxy_error("NL2SQL: Failed to parse OpenAI-compatible response JSON: %s\n", e.what());
proxy_error("NL2SQL: Response was: %s\n", response_data.c_str());
LOG_LLM_ERROR(req_id.c_str(), "parse_json", e.what(), 0);
return "";
} catch (const std::exception& e) {
proxy_error("NL2SQL: Error processing OpenAI-compatible response: %s\n", e.what());
LOG_LLM_ERROR(req_id.c_str(), "process", e.what(), 0);
return "";
}
}
@ -250,20 +314,29 @@ std::string NL2SQL_Converter::call_generic_openai(const std::string& prompt, con
* @param model Model name to use
* @param url Full API endpoint URL
* @param key API key (required for Anthropic)
* @param req_id Request ID for correlation (optional)
* @return Generated SQL or empty string on error
*/
std::string NL2SQL_Converter::call_generic_anthropic(const std::string& prompt, const std::string& model,
const std::string& url, const char* key) {
const std::string& url, const char* key,
const std::string& req_id) {
// Start timing
struct timespec start_ts, end_ts;
clock_gettime(CLOCK_MONOTONIC, &start_ts);
// Log request
LOG_LLM_REQUEST(req_id.c_str(), url.c_str(), model.c_str(), prompt);
std::string response_data;
CURL* curl = curl_easy_init();
if (!curl) {
proxy_error("NL2SQL: Failed to initialize curl for Anthropic-compatible provider\n");
LOG_LLM_ERROR(req_id.c_str(), "init", "Failed to initialize curl", 0);
return "";
}
if (!key || strlen(key) == 0) {
proxy_error("NL2SQL: Anthropic-compatible provider requires API key\n");
LOG_LLM_ERROR(req_id.c_str(), "auth", "API key required", 0);
curl_easy_cleanup(curl);
return "";
}
@ -309,14 +382,16 @@ std::string NL2SQL_Converter::call_generic_anthropic(const std::string& prompt,
curl_easy_setopt(curl, CURLOPT_HTTPHEADER, headers);
proxy_debug(PROXY_DEBUG_NL2SQL, 2, "NL2SQL: Calling Anthropic-compatible provider: %s (model: %s)\n",
url.c_str(), model.c_str());
// Perform request
CURLcode res = curl_easy_perform(curl);
// Calculate duration
clock_gettime(CLOCK_MONOTONIC, &end_ts);
int64_t duration_ms = (end_ts.tv_sec - start_ts.tv_sec) * 1000 +
(end_ts.tv_nsec - start_ts.tv_nsec) / 1000000;
if (res != CURLE_OK) {
proxy_error("NL2SQL: Anthropic-compatible curl_easy_perform() failed: %s\n", curl_easy_strerror(res));
LOG_LLM_ERROR(req_id.c_str(), "curl", curl_easy_strerror(res), 0);
curl_slist_free_all(headers);
curl_easy_cleanup(curl);
return "";
@ -359,20 +434,21 @@ std::string NL2SQL_Converter::call_generic_anthropic(const std::string& prompt,
sql.pop_back();
}
proxy_debug(PROXY_DEBUG_NL2SQL, 3, "NL2SQL: Anthropic-compatible provider returned SQL: %s\n", sql.c_str());
// Log successful response with timing
std::string preview = sql.length() > 100 ? sql.substr(0, 100) + "..." : sql;
LOG_LLM_RESPONSE(req_id.c_str(), 200, duration_ms, preview);
return sql;
}
}
proxy_error("NL2SQL: Anthropic-compatible response missing expected fields\n");
LOG_LLM_ERROR(req_id.c_str(), "parse", "Response missing expected fields", 0);
return "";
} catch (const json::parse_error& e) {
proxy_error("NL2SQL: Failed to parse Anthropic-compatible response JSON: %s\n", e.what());
proxy_error("NL2SQL: Response was: %s\n", response_data.c_str());
LOG_LLM_ERROR(req_id.c_str(), "parse_json", e.what(), 0);
return "";
} catch (const std::exception& e) {
proxy_error("NL2SQL: Error processing Anthropic-compatible response: %s\n", e.what());
LOG_LLM_ERROR(req_id.c_str(), "process", e.what(), 0);
return "";
}
}

4
lib/NL2SQL_Converter.cpp
Unescape View File

@ -677,7 +677,7 @@ NL2SQLResult NL2SQL_Converter::convert(const NL2SQLRequest& req) {
? config.provider_url
: "http://localhost:11434/v1/chat/completions";
model = config.provider_model ? config.provider_model : "llama3.2";
raw_sql = call_generic_openai(prompt, model, url, key);
raw_sql = call_generic_openai(prompt, model, url, key, req.request_id);
result.explanation = "Generated by OpenAI-compatible provider (" + std::string(model) + ")";
result.provider_used = "openai";
break;
@ -687,7 +687,7 @@ NL2SQLResult NL2SQL_Converter::convert(const NL2SQLRequest& req) {
? config.provider_url
: "https://api.anthropic.com/v1/messages";
model = config.provider_model ? config.provider_model : "claude-3-haiku";
raw_sql = call_generic_anthropic(prompt, model, url, key);
raw_sql = call_generic_anthropic(prompt, model, url, key, req.request_id);
result.explanation = "Generated by Anthropic-compatible provider (" + std::string(model) + ")";
result.provider_used = "anthropic";
break;

Write Preview
Loading…
Cancel
Save