Log in/out messages/params from overloaded xfmr callbacks - Xfmr infra logging enhancements to improve debuggability - (sonic-net#48)

* Xfmr infra logging enhancements to improve debuggability - Log in/out messages/params from overloaded xfmr callbacks

* Addressed code review comment to change log messsages around callbacks to have before and after

Author: amrutasali

translib/transformer/xlate.go

@@ -512,7 +512,6 @@ func XlateFromDb(uri string, ygRoot *ygot.GoStruct, dbs [db.MaxDB]*db.DB, data R
 										log.Warningf("value-xfmr:fldpath(\"%v\") val(\"%v\"):err(\"%v\").", dbSpecField, leafListInstVal, err)
 										return []byte(""), true, err
 									}
-									log.Info("valueXfmrHandler() retuned ", retVal)
 									leafListInstVal = retVal
 								}
 								if leafListInstExists(dbData[cdb][tableName][keyStr].Field[fieldName], leafListInstVal) {

translib/transformer/xlate_from_db.go

@@ -961,7 +961,6 @@ func terminalNodeProcess(inParamsForGet xlateFromDbParams, terminalNodeQuery boo
 								log.Warningf("value-xfmr:fldpath(\"%v\") val(\"%v\"):err(\"%v\").", dbSpecField, leafListInstVal, valXfmrErr)
 								return resFldValMap, valXfmrErr
 							}
-							log.Info("valueXfmrHandler() retuned ", retVal)
 							leafListInstVal = retVal
 						}
 						if !leafListInstExists((*dbDataMap)[cdb][tbl][tblKey].Field[dbFldName], leafListInstVal) {

translib/transformer/xlate_qp.go

@@ -65,11 +65,6 @@ func (qp *QueryParams) isFieldsEnabled() bool {
 	return len(qp.fields) != 0
 }
 
-func (qp *QueryParams) String() string {
-	return fmt.Sprintf("depthEnabled: %v curDepth: %d content: %s fields: %s",
-		qp.depthEnabled, qp.curDepth, qp.content, qp.fields)
-}
-
 func (ct ContentType) String() string {
 	ret := "Unknown"
 	switch ct {
@@ -84,3 +79,9 @@ func (ct ContentType) String() string {
 	}
 	return ret
 }
+
+func (qp QueryParams) String() string {
+	return fmt.Sprintf("QueryParams{depthEnabled: %v, curDepth: %v, content: %v, fields: %v, fieldsFillAll: %v, "+
+		"allowFieldsXpath: %v, tgtFieldsXpathMap: %v", qp.depthEnabled, qp.curDepth, qp.content,
+		qp.fields, qp.fieldsFillAll, qp.allowFieldsXpath, qp.tgtFieldsXpathMap)
+}

translib/transformer/xlate_utils.go

@@ -2374,3 +2374,40 @@ func (appParams *AppParams) GetUser() AppUser {
 func (e *qpSubtreePruningErr) Error() string {
 	return fmt.Sprintf("Query Parameter pruning unsuccessful for subtree - %s", e.subtreePath)
 }
+
+func (inPm XfmrParams) String() string {
+	return fmt.Sprintf("{d(config Db ptr): %p, dbs(Dbs ptrs to following Dbs): %v, Current Node DB: %v, ygRoot: %v, xpath: %v, "+
+		"uri: %v, requestUri: %v, oper: %v, table: %v, key: %v, dbDataMap: %v, subOpDataMap: %v, "+
+		"param: %v, txCache: %v, skipOrdTblChk: %v, isVirtualTbl: %v, pCascadeDelTbl: %v, "+
+		"yangDefValMap: %v, queryParams: %v, pruneDone: %v, invokeCRUSubtreeOnce: %v", inPm.d, dbPtrsToNames(inPm.dbs), inPm.curDb.Name(),
+		inPm.ygRoot, inPm.xpath, inPm.uri, inPm.requestUri, inPm.oper, inPm.table, inPm.key, inPm.dbDataMap, inPm.subOpDataMap,
+		inPm.param, inPm.txCache, boolPtrToString(inPm.skipOrdTblChk), boolPtrToString(inPm.isVirtualTbl), inPm.pCascadeDelTbl,
+		inPm.yangDefValMap, inPm.queryParams, boolPtrToString(inPm.pruneDone), boolPtrToString(inPm.invokeCRUSubtreeOnce))
+}
+
+func dbPtrsToNames(dbs [db.MaxDB]*db.DB) string {
+	dbNms := ""
+	for _, val := range dbs {
+		if val != nil && val.Opts != nil {
+			dbNms = dbNms + " " + val.Opts.DBNo.Name()
+		}
+	}
+	return dbNms
+}
+
+func boolPtrToString(boolPtr *bool) string {
+	if boolPtr == nil {
+		return "<nil>"
+	} else {
+		return fmt.Sprintf("%v", *boolPtr)
+	}
+}
+
+func (inPm XfmrDbParams) String() string {
+	return fmt.Sprintf("{oper: %v, dbNum: %v, tableName: %v, key: %v, fieldName: %v, value: %v", inPm.oper, inPm.dbNum, inPm.tableName,
+		inPm.key, inPm.fieldName, inPm.value)
+}
+
+func (inPm SonicXfmrParams) String() string {
+	return fmt.Sprintf("{dbNum: %v, tableName: %v, key: %v, xpath: %v", inPm.dbNum, inPm.tableName, inPm.key, inPm.xpath)
+}

translib/transformer/xlate_xfmr_handler.go

@@ -25,7 +25,6 @@ import (
 
 func xfmrHandlerFunc(inParams XfmrParams, xfmrFuncNm string) error {
 	const DBTY_SBT_XFMR_RET_ERR_INDX = 0
-	xfmrLogInfoAll("Received inParams %v Subtree function name %v", inParams, xfmrFuncNm)
 	if inParams.uri != inParams.requestUri {
 		_, yerr := xlateUnMarshallUri(inParams.ygRoot, inParams.uri)
 		if yerr != nil {
@@ -34,7 +33,9 @@ func xfmrHandlerFunc(inParams XfmrParams, xfmrFuncNm string) error {
 	}
 
 	inParams.pruneDone = new(bool)
+	xfmrLogInfoAll("Before calling dbToYang subtree xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	ret, err := XlateFuncCall(dbToYangXfmrFunc(xfmrFuncNm), inParams)
+	xfmrLogInfoAll("After calling dbToYang subtree xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	if err != nil {
 		xfmrLogInfoAll("Failed to retrieve data for xpath(\"%v\") err(%v).", inParams.uri, err)
 		return err
@@ -73,8 +74,9 @@ func leafXfmrHandlerFunc(inParams XfmrParams, xfmrFieldFuncNm string) (map[strin
 	var err error
 	var fldValMap map[string]interface{}
 
-	xfmrLogInfoAll("Received inParams %v to invoke Field transformer %v", inParams, xfmrFieldFuncNm)
+	xfmrLogInfoAll("Before calling dbToYang field xfmr %v, inParams %v", xfmrFieldFuncNm, inParams)
 	ret, err := XlateFuncCall(dbToYangXfmrFunc(xfmrFieldFuncNm), inParams)
+	xfmrLogInfoAll("After calling dbToYang field xfmr %v, inParams %v", xfmrFieldFuncNm, inParams)
 	if err != nil {
 		return fldValMap, err
 	}
@@ -91,6 +93,7 @@ func leafXfmrHandlerFunc(inParams XfmrParams, xfmrFieldFuncNm string) (map[strin
 
 		if ret[DBTY_FLD_XFMR_RET_VAL_INDX].Interface() != nil {
 			fldValMap = ret[DBTY_FLD_XFMR_RET_VAL_INDX].Interface().(map[string]interface{})
+			xfmrLogInfoAll("Field transformer returned %v", fldValMap)
 		}
 	}
 	return fldValMap, err
@@ -102,13 +105,13 @@ func keyXfmrHandlerFunc(inParams XfmrParams, xfmrFuncNm string) (map[string]inte
 		DBTY_KEY_XFMR_RET_VAL_INDX = 0
 		DBTY_KEY_XFMR_RET_ERR_INDX = 1
 	)
-	xfmrLogInfoAll("Received inParams %v key transformer function name %v", inParams, xfmrFuncNm)
+	xfmrLogInfoAll("Before calling dbToYang key xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	ret, err := XlateFuncCall(dbToYangXfmrFunc(xfmrFuncNm), inParams)
+	xfmrLogInfoAll("After calling dbToYang key xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	retVal := make(map[string]interface{})
 	if err != nil {
 		return retVal, err
 	}
-
 	if (ret != nil) && (len(ret) > 0) {
 		if len(ret) == DBTY_KEY_XFMR_RET_ARGS {
 			// key xfmr returns err as second value in return data list from <xfmr_func>.Call()
@@ -122,19 +125,23 @@ func keyXfmrHandlerFunc(inParams XfmrParams, xfmrFuncNm string) (map[string]inte
 		}
 		if ret[DBTY_KEY_XFMR_RET_VAL_INDX].Interface() != nil {
 			retVal = ret[DBTY_KEY_XFMR_RET_VAL_INDX].Interface().(map[string]interface{})
+			xfmrLogInfoAll("Key transformer returned %v", retVal)
 			return retVal, nil
 		}
 	}
 	return retVal, nil
 }
 
 func validateHandlerFunc(inParams XfmrParams, validateFuncNm string) bool {
-	xfmrLogInfoAll("Received inParams %v, validate transformer function name %v", inParams, validateFuncNm)
+	xfmrLogInfoAll("Before calling validate xfmr %v, inParams %v", validateFuncNm, inParams)
 	ret, err := XlateFuncCall(validateFuncNm, inParams)
+	xfmrLogInfoAll("After calling validate xfmr %v, inParams %v", validateFuncNm, inParams)
 	if err != nil {
 		return false
 	}
-	return ret[0].Interface().(bool)
+	result := ret[0].Interface().(bool)
+	xfmrLogInfoAll("Validate transformer returned %v", result)
+	return result
 }
 
 func xfmrTblHandlerFunc(xfmrTblFunc string, inParams XfmrParams, xfmrTblKeyCache map[string]tblKeyCache) ([]string, error) {
@@ -143,17 +150,19 @@ func xfmrTblHandlerFunc(xfmrTblFunc string, inParams XfmrParams, xfmrTblKeyCache
 		TBL_XFMR_RET_VAL_INDX = 0
 		TBL_XFMR_RET_ERR_INDX = 1
 	)
-	xfmrLogInfoAll("Received inParams %v, table transformer function name %v", inParams, xfmrTblFunc)
+	xfmrLogInfoAll("Before calling table xfmr %v, inParams %v", xfmrTblFunc, inParams)
 	if inParams.oper == GET && xfmrTblKeyCache != nil {
 		if tkCache, _ok := xfmrTblKeyCache[inParams.uri]; _ok {
 			if len(tkCache.dbTblList) > 0 {
+				xfmrLogInfoAll("Returning table list from cache %v", tkCache.dbTblList)
 				return tkCache.dbTblList, nil
 			}
 		}
 	}
 
 	var retTblLst []string
 	ret, err := XlateFuncCall(xfmrTblFunc, inParams)
+	xfmrLogInfoAll("After calling table xfmr %v, inParams %v", xfmrTblFunc, inParams)
 	if err != nil {
 		return retTblLst, err
 	}
@@ -182,6 +191,7 @@ func xfmrTblHandlerFunc(xfmrTblFunc string, inParams XfmrParams, xfmrTblKeyCache
 		xfmrTblKeyCache[inParams.uri] = tkCache
 	}
 
+	xfmrLogInfoAll("Table transformer returned : %v", retTblLst)
 	return retTblLst, err
 }
 
@@ -192,9 +202,9 @@ func valueXfmrHandler(inParams XfmrDbParams, xfmrValueFuncNm string) (string, er
 		YTDB_FLD_XFMR_RET_ERR_INDX = 1
 	)
 
-	xfmrLogInfoAll("Received inParams %v Value transformer name %v", inParams, xfmrValueFuncNm)
-
+	xfmrLogInfoAll("Before calling value xfmr %v, inParams %v", xfmrValueFuncNm, inParams)
 	ret, err := XlateFuncCall(xfmrValueFuncNm, inParams)
+	xfmrLogInfoAll("After calling value xfmr %v, inParams %v", xfmrValueFuncNm, inParams)
 	if err != nil {
 		return "", err
 	}
@@ -213,6 +223,7 @@ func valueXfmrHandler(inParams XfmrDbParams, xfmrValueFuncNm string) (string, er
 
 		if ret[YTDB_FLD_XFMR_RET_VAL_INDX].Interface() != nil {
 			retVal := ret[YTDB_FLD_XFMR_RET_VAL_INDX].Interface().(string)
+			xfmrLogInfoAll("Value transformer returned : %v", retVal)
 			return retVal, nil
 		}
 	}
@@ -227,8 +238,9 @@ func leafXfmrHandler(inParams XfmrParams, xfmrFieldFuncNm string) (map[string]st
 		YTDB_FLD_XFMR_RET_ERR_INDX = 1
 	)
 
-	xfmrLogInfoAll("Received inParams %v Field transformer name %v", inParams, xfmrFieldFuncNm)
+	xfmrLogInfoAll("Before calling yangToDb field xfmr %v, inParams %v", xfmrFieldFuncNm, inParams)
 	ret, err := XlateFuncCall(yangToDbXfmrFunc(xfmrFieldFuncNm), inParams)
+	xfmrLogInfoAll("After calling yangToDb field xfmr %v, inParams %v", xfmrFieldFuncNm, inParams)
 	if err != nil {
 		return nil, err
 	}
@@ -246,6 +258,7 @@ func leafXfmrHandler(inParams XfmrParams, xfmrFieldFuncNm string) (map[string]st
 
 		if ret[YTDB_FLD_XFMR_RET_VAL_INDX].Interface() != nil {
 			fldValMap := ret[YTDB_FLD_XFMR_RET_VAL_INDX].Interface().(map[string]string)
+			xfmrLogInfoAll("Field transformer returned %v", fldValMap)
 			return fldValMap, nil
 		}
 	} else {
@@ -263,8 +276,9 @@ func xfmrHandler(inParams XfmrParams, xfmrFuncNm string) (map[string]map[string]
 		YTDB_SBT_XFMR_RET_ERR_INDX = 1
 	)
 
-	xfmrLogInfoAll("Received inParams %v Subtree function name %v", inParams, xfmrFuncNm)
+	xfmrLogInfoAll("Before calling yangToDb subtree xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	ret, err := XlateFuncCall(yangToDbXfmrFunc(xfmrFuncNm), inParams)
+	xfmrLogInfoAll("After calling yangToDb subtree xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	if err != nil {
 		return nil, err
 	}
@@ -282,6 +296,7 @@ func xfmrHandler(inParams XfmrParams, xfmrFuncNm string) (map[string]map[string]
 		}
 		if ret[YTDB_SBT_XFMR_RET_VAL_INDX].Interface() != nil {
 			retMap := ret[YTDB_SBT_XFMR_RET_VAL_INDX].Interface().(map[string]map[string]db.Value)
+			xfmrLogInfoAll("Subtree function returned %v", retMap)
 			return retMap, nil
 		}
 	}
@@ -295,8 +310,9 @@ func keyXfmrHandler(inParams XfmrParams, xfmrFuncNm string) (string, error) {
 		YTDB_KEY_XFMR_RET_ERR_INDX = 1
 	)
 
-	xfmrLogInfoAll("Received inParams %v key transformer function name %v", inParams, xfmrFuncNm)
+	xfmrLogInfoAll("Before calling yangToDb key xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	ret, err := XlateFuncCall(yangToDbXfmrFunc(xfmrFuncNm), inParams)
+	xfmrLogInfoAll("After calling yangToDb key xfmr %v, inParams %v", xfmrFuncNm, inParams)
 	retVal := ""
 	if err != nil {
 		return retVal, err
@@ -315,6 +331,7 @@ func keyXfmrHandler(inParams XfmrParams, xfmrFuncNm string) (string, error) {
 		}
 		if ret[YTDB_KEY_XFMR_RET_VAL_INDX].Interface() != nil {
 			retVal = ret[YTDB_KEY_XFMR_RET_VAL_INDX].Interface().(string)
+			xfmrLogInfoAll("Key Transformer returned %v", retVal)
 			return retVal, nil
 		}
 	}
@@ -329,8 +346,9 @@ func postXfmrHandlerFunc(xfmrPost string, inParams XfmrParams) (map[string]map[s
 		POST_XFMR_RET_ERR_INDX = 1
 	)
 	retData := make(map[string]map[string]db.Value)
-	xfmrLogInfoAll("Received inParams %v, post transformer function name %v", inParams, xfmrPost)
+	xfmrLogInfoAll("Before calling post xfmr %v, inParams %v", xfmrPost, inParams)
 	ret, err := XlateFuncCall(xfmrPost, inParams)
+	xfmrLogInfoAll("After calling post xfmr %v, inParams %v", xfmrPost, inParams)
 	if err != nil {
 		return nil, err
 	}
@@ -360,8 +378,9 @@ func preXfmrHandlerFunc(xfmrPre string, inParams XfmrParams) error {
 		PRE_XFMR_RET_ERR_INDX = 0
 	)
 
-	xfmrLogInfoAll("Received inParams %v, pre transformer function name %v", inParams, xfmrPre)
+	xfmrLogInfoAll("Before calling pre xfmr %v, inParams %v", xfmrPre, inParams)
 	ret, err := XlateFuncCall(xfmrPre, inParams)
+	xfmrLogInfoAll("After calling pre xfmr %v, inParams %v", xfmrPre, inParams)
 	if err != nil {
 		log.Warningf("Pre-transformer function(\"%v\") returned error - %v.", xfmrPre, err)
 		return err
@@ -385,8 +404,9 @@ func sonicKeyXfmrHandlerFunc(inParams SonicXfmrParams, xfmrKeyNm string) (map[st
 		DBTY_KEY_XFMR_RET_ERR_INDX = 1
 	)
 
-	xfmrLogInfoAll("Received inParams %v key transformer function name %v", inParams, xfmrKeyNm)
+	xfmrLogInfoAll("Before calling dbToYang sonic key xfmr %v, inParams %v", xfmrKeyNm, inParams)
 	ret, err := XlateFuncCall(dbToYangXfmrFunc(xfmrKeyNm), inParams)
+	xfmrLogInfoAll("After calling dbToYang sonic key xfmr %v, inParams %v", xfmrKeyNm, inParams)
 	retVal := make(map[string]interface{})
 	if err != nil {
 		return retVal, err
@@ -405,6 +425,7 @@ func sonicKeyXfmrHandlerFunc(inParams SonicXfmrParams, xfmrKeyNm string) (map[st
 		}
 		if ret[DBTY_KEY_XFMR_RET_VAL_INDX].Interface() != nil {
 			retVal = ret[DBTY_KEY_XFMR_RET_VAL_INDX].Interface().(map[string]interface{})
+			xfmrLogInfoAll("Sonic key transformer returned %v", retVal)
 			return retVal, nil
 		}
 	}