From 376cac564421b56a0b3482981c475527cdb74d46 Mon Sep 17 00:00:00 2001 From: danischm Date: Fri, 31 Oct 2025 19:34:49 +0100 Subject: [PATCH 1/3] Client log enhancements --- client.go | 112 ++++++++++++++++++++++++++++++++++++++---------------- 1 file changed, 79 insertions(+), 33 deletions(-) diff --git a/client.go b/client.go index a184fdf..03e3ea4 100644 --- a/client.go +++ b/client.go @@ -198,6 +198,7 @@ func NewClient(host string, opts ...func(*Client)) (*Client, error) { options.WithAuthPassword(client.password), options.WithPort(client.Port), options.WithTimeoutSocket(client.ConnectTimeout), + options.WithTimeoutOps(client.OperationTimeout), } // Only disable host key verification if explicitly requested @@ -1094,6 +1095,7 @@ func (c *Client) reconnect() error { options.WithAuthPassword(c.password), options.WithPort(c.Port), options.WithTimeoutSocket(c.ConnectTimeout), + options.WithTimeoutOps(c.OperationTimeout), } if c.InsecureSkipVerify { @@ -1280,12 +1282,21 @@ func (c *Client) sendRPC(ctx context.Context, req *Req) (Res, error) { // Not transient or max retries reached if !isTransient || attempt >= c.MaxRetries { - // Log operation failure - c.logger.Error(ctx, "NETCONF operation failed", - "operation", req.Operation, - "retries", attempt, - "transient", isTransient, - "errorCount", len(res.Errors)) + // Log operation failure with error details + if err != nil { + c.logger.Error(ctx, "NETCONF operation failed", + "operation", req.Operation, + "retries", attempt, + "transient", isTransient, + "errorCount", len(res.Errors), + "error", err.Error()) + } else { + c.logger.Error(ctx, "NETCONF operation failed", + "operation", req.Operation, + "retries", attempt, + "transient", isTransient, + "errorCount", len(res.Errors)) + } // Log each RPC error for i, rpcErr := range res.Errors { @@ -1370,6 +1381,61 @@ func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { return Res{}, fmt.Errorf("operation %s failed: driver is nil (connection closed)", req.Operation) } + // DIAGNOSTIC: Log session state before operation to help diagnose Terraform plugin issues + c.logger.Debug(ctx, "NETCONF RPC request", + "operation", req.Operation, + "target", req.Target, + "sessionID", c.SessionID()) + + // Log request XML BEFORE sending to catch operations that timeout at transport layer + // Determine what XML content to log based on operation type + var xmlToLog string + switch req.Operation { + case "edit-config": + // For edit-config, ensure wrapper is present (matching what will be sent) + // Note: xmldot.Get returns the *content* of the element, not including the element itself + // So we check if exists, and if not, we add it + if !xmldot.Get(req.Config, "config").Exists() { + // No wrapper, add it + xmlToLog = "" + req.Config + "" + } else { + // Has wrapper already, use as-is + xmlToLog = req.Config + } + case "get-config", "get": + xmlToLog = req.Filter.Content + case "lock", "unlock", "commit", "discard", "validate": + // Simple operations have no XML content, just log metadata + c.logger.Debug(ctx, "NETCONF RPC request", + "operation", req.Operation, + "target", req.Target) + default: + // For other operations (rpc, copy-config, etc.) + xmlToLog = req.Config + } + + // Log XML content if present (reusing post-send logging logic) + if xmlToLog != "" { + if len(xmlToLog) <= MaxXMLSizeForLogging { + if !utf8.ValidString(xmlToLog) { + c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF request XML", + "operation", req.Operation, + "size", len(xmlToLog)) + } else { + requestXML := c.prepareXMLForLogging(xmlToLog) + c.logger.Debug(ctx, "NETCONF RPC request XML", + "operation", req.Operation, + "xml", requestXML) + } + } else { + c.logger.Debug(ctx, "NETCONF RPC request XML (truncated)", + "operation", req.Operation, + "size", len(xmlToLog), + "limit", MaxXMLSizeForLogging, + "xml", "[XML TOO LARGE FOR LOGGING]") + } + } + switch req.Operation { case "get": // Get method signature: Get(filter string, opts ...util.Option) @@ -1465,7 +1531,13 @@ func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { } if err != nil { - return Res{}, fmt.Errorf("operation %s failed: %w", req.Operation, err) + // Add context about what was being sent when timeout/error occurred + if req.Operation == "edit-config" { + configSize := len(req.Config) + return Res{}, fmt.Errorf("operation %s failed (target=%s, configSize=%d): %w", + req.Operation, req.Target, configSize, err) + } + return Res{}, fmt.Errorf("operation %s failed (target=%s): %w", req.Operation, req.Target, err) } // Check for nil response @@ -1473,32 +1545,6 @@ func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { return Res{}, fmt.Errorf("operation %s: received nil response from driver", req.Operation) } - // Log request XML content (Debug level only) - // Pre-check size and level to avoid expensive processing when not needed - if len(scrapligoRes.Input) > 0 { - // Pre-check size limit before string conversion (avoid allocation) - if len(scrapligoRes.Input) <= MaxXMLSizeForLogging { - // Validate UTF-8 encoding - if !utf8.Valid(scrapligoRes.Input) { - c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF request XML", - "operation", req.Operation, - "size", len(scrapligoRes.Input)) - } else { - requestXML := c.prepareXMLForLogging(string(scrapligoRes.Input)) - c.logger.Debug(ctx, "NETCONF RPC request XML", - "operation", req.Operation, - "xml", requestXML) - } - } else { - // Log truncation message only (cheap operation) - c.logger.Debug(ctx, "NETCONF RPC request XML (truncated)", - "operation", req.Operation, - "size", len(scrapligoRes.Input), - "limit", MaxXMLSizeForLogging, - "xml", "[XML TOO LARGE FOR LOGGING]") - } - } - // Log response XML content (Debug level only) if scrapligoRes.Result != "" { // Pre-check size limit before processing From 04b31e95ace203aecbac67b0ca019abb9a83b2a5 Mon Sep 17 00:00:00 2001 From: danischm Date: Sat, 1 Nov 2025 12:03:34 +0100 Subject: [PATCH 2/3] Remove redundant logs --- client.go | 11 +---------- 1 file changed, 1 insertion(+), 10 deletions(-) diff --git a/client.go b/client.go index 03e3ea4..cd47cf4 100644 --- a/client.go +++ b/client.go @@ -1381,12 +1381,6 @@ func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { return Res{}, fmt.Errorf("operation %s failed: driver is nil (connection closed)", req.Operation) } - // DIAGNOSTIC: Log session state before operation to help diagnose Terraform plugin issues - c.logger.Debug(ctx, "NETCONF RPC request", - "operation", req.Operation, - "target", req.Target, - "sessionID", c.SessionID()) - // Log request XML BEFORE sending to catch operations that timeout at transport layer // Determine what XML content to log based on operation type var xmlToLog string @@ -1405,10 +1399,7 @@ func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { case "get-config", "get": xmlToLog = req.Filter.Content case "lock", "unlock", "commit", "discard", "validate": - // Simple operations have no XML content, just log metadata - c.logger.Debug(ctx, "NETCONF RPC request", - "operation", req.Operation, - "target", req.Target) + // Simple operations have no XML content (already logged at line 1385) default: // For other operations (rpc, copy-config, etc.) xmlToLog = req.Config From e2a9f14d59e92f6a262d31fe3abfee718a9754ef Mon Sep 17 00:00:00 2001 From: danischm Date: Sat, 1 Nov 2025 12:11:33 +0100 Subject: [PATCH 3/3] Refactor to satisfy linters --- client.go | 329 ++++++++++++++++++++++++++-------------------------- req_test.go | 17 +-- 2 files changed, 177 insertions(+), 169 deletions(-) diff --git a/client.go b/client.go index cd47cf4..2c69723 100644 --- a/client.go +++ b/client.go @@ -30,6 +30,21 @@ const ( filterTypeXPath = "xpath" ) +// NETCONF operation names +const ( + opGet = "get" + opGetConfig = "get-config" + opEditConfig = "edit-config" + opCopyConfig = "copy-config" + opDeleteConfig = "delete-config" + opLock = "lock" + opUnlock = "unlock" + opCommit = "commit" + opDiscard = "discard" + opValidate = "validate" + opRPC = "rpc" +) + // Default client configuration values const ( DefaultPort = 830 @@ -1372,197 +1387,187 @@ func (c *Client) sendRPC(ctx context.Context, req *Req) (Res, error) { func (c *Client) executeRPC(ctx context.Context, req *Req) (Res, error) { _ = ctx // Accepted for future compatibility, timeout enforced by caller - // Delegate to scrapligo driver based on operation - var scrapligoRes *response.NetconfResponse - var err error - // Check for nil driver before operation if c.driver == nil { return Res{}, fmt.Errorf("operation %s failed: driver is nil (connection closed)", req.Operation) } - // Log request XML BEFORE sending to catch operations that timeout at transport layer - // Determine what XML content to log based on operation type - var xmlToLog string + // Log request XML before sending + c.logRequestXML(ctx, req) + + // Dispatch operation to scrapligo driver + scrapligoRes, err := c.dispatchOperation(req) + + // Handle operation error + if err != nil { + return Res{}, c.formatOperationError(req, err) + } + + // Check for nil response + if scrapligoRes == nil { + return Res{}, fmt.Errorf("operation %s: received nil response from driver", req.Operation) + } + + // Log response XML + c.logResponseXML(ctx, req.Operation, scrapligoRes.Result) + + // Parse response XML + return c.parseResponse(scrapligoRes) +} + +// getRequestXMLForLogging determines what XML content to log based on operation type. +func (c *Client) getRequestXMLForLogging(req *Req) string { switch req.Operation { - case "edit-config": + case opEditConfig: // For edit-config, ensure wrapper is present (matching what will be sent) - // Note: xmldot.Get returns the *content* of the element, not including the element itself - // So we check if exists, and if not, we add it if !xmldot.Get(req.Config, "config").Exists() { - // No wrapper, add it - xmlToLog = "" + req.Config + "" - } else { - // Has wrapper already, use as-is - xmlToLog = req.Config + return "" + req.Config + "" } - case "get-config", "get": - xmlToLog = req.Filter.Content - case "lock", "unlock", "commit", "discard", "validate": - // Simple operations have no XML content (already logged at line 1385) + return req.Config + case opGetConfig, opGet: + return req.Filter.Content + case opLock, opUnlock, opCommit, opDiscard, opValidate: + return "" // Simple operations have no XML content default: - // For other operations (rpc, copy-config, etc.) - xmlToLog = req.Config + return req.Config // For other operations (rpc, copy-config, etc.) } +} - // Log XML content if present (reusing post-send logging logic) - if xmlToLog != "" { - if len(xmlToLog) <= MaxXMLSizeForLogging { - if !utf8.ValidString(xmlToLog) { - c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF request XML", - "operation", req.Operation, - "size", len(xmlToLog)) - } else { - requestXML := c.prepareXMLForLogging(xmlToLog) - c.logger.Debug(ctx, "NETCONF RPC request XML", - "operation", req.Operation, - "xml", requestXML) - } - } else { - c.logger.Debug(ctx, "NETCONF RPC request XML (truncated)", - "operation", req.Operation, - "size", len(xmlToLog), - "limit", MaxXMLSizeForLogging, - "xml", "[XML TOO LARGE FOR LOGGING]") - } +// logRequestXML logs the request XML content if present. +func (c *Client) logRequestXML(ctx context.Context, req *Req) { + xmlToLog := c.getRequestXMLForLogging(req) + if xmlToLog == "" { + return } - switch req.Operation { - case "get": - // Get method signature: Get(filter string, opts ...util.Option) - // The filter string is the XML subtree for subtree filters, or empty string - // For XPath filters, the XPath expression is passed as the filter string - // Note: scrapligo driver/netconf may require filter type to be indicated via options - // for XPath filters (this is validated but needs integration testing) - filterStr := req.Filter.Content - scrapligoRes, err = c.driver.Get(filterStr) - - case "get-config": - // GetConfig method signature: GetConfig(source string, opts ...util.Option) - // - // Filter options are provided via driver/opoptions package: - // - opoptions.WithFilter(content) sets the filter XML or XPath expression - // - opoptions.WithFilterType(type) sets "subtree" or "xpath" (default is "subtree") - var opts []util.Option - if req.Filter.Content != "" { - // Add filter content - opts = append(opts, opoptions.WithFilter(req.Filter.Content)) - - // Set filter type if XPath (subtree is default) - if req.Filter.Type == filterTypeXPath { - opts = append(opts, opoptions.WithFilterType(filterTypeXPath)) - } - } - scrapligoRes, err = c.driver.GetConfig(req.Target, opts...) - - case "edit-config": - // EditConfig method signature: EditConfig(target, config string) - // If advanced edit-config options are set, build custom XML - if req.DefaultOperation != "" || req.TestOption != "" || req.ErrorOption != "" { - rpcXML := c.buildEditConfigXML(req) - scrapligoRes, err = c.driver.RPC(opoptions.WithFilter(rpcXML)) - } else { - // For standard edit-config, ensure config has wrapper - // scrapligo's EditConfig expects the caller to provide the config element - configContent := req.Config - result := xmldot.Get(req.Config, "config") - if !result.Exists() { - // Config doesn't have wrapper, add it - configContent = "" + req.Config + "" - } - scrapligoRes, err = c.driver.EditConfig(req.Target, configContent) - } + if len(xmlToLog) > MaxXMLSizeForLogging { + c.logger.Debug(ctx, "NETCONF RPC request XML (truncated)", + "operation", req.Operation, + "size", len(xmlToLog), + "limit", MaxXMLSizeForLogging, + "xml", "[XML TOO LARGE FOR LOGGING]") + return + } - case "copy-config": - // CopyConfig method signature: CopyConfig(source, target string) - scrapligoRes, err = c.driver.CopyConfig(req.Config, req.Target) - - case "delete-config": - // DeleteConfig method signature: DeleteConfig(target string) - scrapligoRes, err = c.driver.DeleteConfig(req.Target) - - case "lock": - // Lock method signature: Lock(target string) - scrapligoRes, err = c.driver.Lock(req.Target) - - case "unlock": - // Unlock method signature: Unlock(target string) - scrapligoRes, err = c.driver.Unlock(req.Target) - - case "commit": - // Commit method signature: Commit(opts ...util.Option) - // Support confirmed commit parameters via scrapligo options - var opts []util.Option - if req.ConfirmTimeout > 0 { - // Confirmed commit with timeout - opts = append(opts, opoptions.WithCommitConfirmed()) - opts = append(opts, opoptions.WithCommitConfirmTimeout(uint(req.ConfirmTimeout))) - } - if req.PersistID != "" { - // Persist ID for commit operations - opts = append(opts, opoptions.WithCommitConfirmedPersistID(req.PersistID)) - } - scrapligoRes, err = c.driver.Commit(opts...) + if !utf8.ValidString(xmlToLog) { + c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF request XML", + "operation", req.Operation, + "size", len(xmlToLog)) + return + } - case "discard": - // Discard method signature: Discard() - scrapligoRes, err = c.driver.Discard() + requestXML := c.prepareXMLForLogging(xmlToLog) + c.logger.Debug(ctx, "NETCONF RPC request XML", + "operation", req.Operation, + "xml", requestXML) +} - case "validate": - // Validate method signature: Validate(target string) - scrapligoRes, err = c.driver.Validate(req.Target) +// logResponseXML logs the response XML content. +func (c *Client) logResponseXML(ctx context.Context, operation string, result string) { + if result == "" { + return + } + + if len(result) > MaxXMLSizeForLogging { + c.logger.Debug(ctx, "NETCONF RPC response XML (truncated)", + "operation", operation, + "size", len(result), + "limit", MaxXMLSizeForLogging, + "xml", "[XML TOO LARGE FOR LOGGING]") + return + } - case "rpc": - // RPC method signature: RPC(opts ...util.Option) - // Pass the RPC XML content via WithFilter option - scrapligoRes, err = c.driver.RPC(opoptions.WithFilter(req.Config)) + if !utf8.ValidString(result) { + c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF response XML", + "operation", operation, + "size", len(result)) + return + } + responseXML := c.prepareXMLForLogging(result) + c.logger.Debug(ctx, "NETCONF RPC response XML", + "operation", operation, + "xml", responseXML) +} + +// formatOperationError formats an operation error with context. +func (c *Client) formatOperationError(req *Req, err error) error { + if req.Operation == opEditConfig { + return fmt.Errorf("operation %s failed (target=%s, configSize=%d): %w", + req.Operation, req.Target, len(req.Config), err) + } + return fmt.Errorf("operation %s failed (target=%s): %w", req.Operation, req.Target, err) +} + +// dispatchOperation dispatches the operation to the appropriate scrapligo driver method. +func (c *Client) dispatchOperation(req *Req) (*response.NetconfResponse, error) { + switch req.Operation { + case opGet: + return c.driver.Get(req.Filter.Content) + case opGetConfig: + return c.executeGetConfig(req) + case opEditConfig: + return c.executeEditConfig(req) + case opCopyConfig: + return c.driver.CopyConfig(req.Config, req.Target) + case opDeleteConfig: + return c.driver.DeleteConfig(req.Target) + case opLock: + return c.driver.Lock(req.Target) + case opUnlock: + return c.driver.Unlock(req.Target) + case opCommit: + return c.executeCommit(req) + case opDiscard: + return c.driver.Discard() + case opValidate: + return c.driver.Validate(req.Target) + case opRPC: + return c.driver.RPC(opoptions.WithFilter(req.Config)) default: - return Res{}, fmt.Errorf("unsupported operation: %s", req.Operation) + return nil, fmt.Errorf("unsupported operation: %s", req.Operation) } +} - if err != nil { - // Add context about what was being sent when timeout/error occurred - if req.Operation == "edit-config" { - configSize := len(req.Config) - return Res{}, fmt.Errorf("operation %s failed (target=%s, configSize=%d): %w", - req.Operation, req.Target, configSize, err) +// executeGetConfig executes a get-config operation with filter options. +func (c *Client) executeGetConfig(req *Req) (*response.NetconfResponse, error) { + var opts []util.Option + if req.Filter.Content != "" { + opts = append(opts, opoptions.WithFilter(req.Filter.Content)) + if req.Filter.Type == filterTypeXPath { + opts = append(opts, opoptions.WithFilterType(filterTypeXPath)) } - return Res{}, fmt.Errorf("operation %s failed (target=%s): %w", req.Operation, req.Target, err) } + return c.driver.GetConfig(req.Target, opts...) +} - // Check for nil response - if scrapligoRes == nil { - return Res{}, fmt.Errorf("operation %s: received nil response from driver", req.Operation) +// executeEditConfig executes an edit-config operation. +func (c *Client) executeEditConfig(req *Req) (*response.NetconfResponse, error) { + // If advanced edit-config options are set, build custom XML + if req.DefaultOperation != "" || req.TestOption != "" || req.ErrorOption != "" { + rpcXML := c.buildEditConfigXML(req) + return c.driver.RPC(opoptions.WithFilter(rpcXML)) } - // Log response XML content (Debug level only) - if scrapligoRes.Result != "" { - // Pre-check size limit before processing - if len(scrapligoRes.Result) <= MaxXMLSizeForLogging { - // Validate UTF-8 encoding - if !utf8.ValidString(scrapligoRes.Result) { - c.logger.Warn(ctx, "Invalid UTF-8 in NETCONF response XML", - "operation", req.Operation, - "size", len(scrapligoRes.Result)) - } else { - responseXML := c.prepareXMLForLogging(scrapligoRes.Result) - c.logger.Debug(ctx, "NETCONF RPC response XML", - "operation", req.Operation, - "xml", responseXML) - } - } else { - // Log truncation message only (cheap operation) - c.logger.Debug(ctx, "NETCONF RPC response XML (truncated)", - "operation", req.Operation, - "size", len(scrapligoRes.Result), - "limit", MaxXMLSizeForLogging, - "xml", "[XML TOO LARGE FOR LOGGING]") - } + // For standard edit-config, ensure config has wrapper + configContent := req.Config + if !xmldot.Get(req.Config, "config").Exists() { + configContent = "" + req.Config + "" } + return c.driver.EditConfig(req.Target, configContent) +} - // Parse response XML - return c.parseResponse(scrapligoRes) +// executeCommit executes a commit operation with optional confirmed commit. +func (c *Client) executeCommit(req *Req) (*response.NetconfResponse, error) { + var opts []util.Option + if req.ConfirmTimeout > 0 { + opts = append(opts, opoptions.WithCommitConfirmed()) + opts = append(opts, opoptions.WithCommitConfirmTimeout(uint(req.ConfirmTimeout))) + } + if req.PersistID != "" { + opts = append(opts, opoptions.WithCommitConfirmedPersistID(req.PersistID)) + } + return c.driver.Commit(opts...) } // parseResponse parses a NETCONF response from scrapligo diff --git a/req_test.go b/req_test.go index a0a586b..a6f0c43 100644 --- a/req_test.go +++ b/req_test.go @@ -8,10 +8,13 @@ import ( "testing" ) -// Test constants for filter types (GOCONST) +// Test constants for filter types and operations (GOCONST) const ( testFilterSubtree = "subtree" testFilterXPath = "xpath" + testOpGet = "get" + testOpEditConfig = "edit-config" + testOpCommit = "commit" ) // TestSubtreeFilter tests the SubtreeFilter constructor @@ -172,14 +175,14 @@ func TestFilterStructure(t *testing.T) { func TestReqStructure(t *testing.T) { t.Run("get request", func(t *testing.T) { req := Req{ - Operation: "get", + Operation: testOpGet, Filter: Filter{ Type: testFilterSubtree, Content: "", }, } - if req.Operation != "get" { + if req.Operation != testOpGet { t.Errorf("expected Operation 'get', got %q", req.Operation) } if req.Filter.Type != testFilterSubtree { @@ -189,13 +192,13 @@ func TestReqStructure(t *testing.T) { t.Run("edit-config request", func(t *testing.T) { req := Req{ - Operation: "edit-config", + Operation: testOpEditConfig, Target: "candidate", Config: "router1", DefaultOperation: "merge", } - if req.Operation != "edit-config" { + if req.Operation != testOpEditConfig { t.Errorf("expected Operation 'edit-config', got %q", req.Operation) } if req.Target != "candidate" { @@ -208,12 +211,12 @@ func TestReqStructure(t *testing.T) { t.Run("commit request with confirmed", func(t *testing.T) { req := Req{ - Operation: "commit", + Operation: testOpCommit, ConfirmTimeout: 60, PersistID: "test-123", } - if req.Operation != "commit" { + if req.Operation != testOpCommit { t.Errorf("expected Operation 'commit', got %q", req.Operation) } if req.ConfirmTimeout != 60 {