Merge pull request '请求缓存优化' (#6) from feature/upgrade_res_cache into master

Reviewed-on: #6

httpclient/client.go

@@ -106,11 +106,11 @@ func NewHttpClient(reqConfig *define.Request, cacheInstance cache.ICache) (*Http
 	hc.OnRequestFinish(func(req *define.Request, rep *define.Response) {
 		if rep.IsSuccess {
 			// 请求成功
-			log.Record(req.Ctx, req.Logger, consts.LogLevelInfo, "接口请求成功", req, rep)
+			log.Record(consts.LogLevelInfo, "接口请求成功", req, rep)
 			return
 		}
 		// 请求失败
-		log.Record(req.Ctx, req.Logger, consts.LogLevelError, "接口请求失败", req, rep)
+		log.Record(consts.LogLevelError, "接口请求失败", req, rep)
 	})
 	return hc, nil
 }
@@ -218,47 +218,83 @@ func (hc *HttpClient) Request() *define.Response {
 		cacheResult *define.Response
 	)
 
-	if cacheResult = hc.getCacheResult(); nil != cacheResult {
+	if cacheResult = hc.getCacheResult(); nil == cacheResult {
+		// 未命中缓存, 直接请求后端接口, 无需
+		return hc.requestBackendApi()
+	}
+	// TODO : 预热加锁, 并发请求触发预热, 仅触发一个即可
 	// 判断是否开启预热
 	inputCachePreHeatConfig := hc.cacheInstance.PreHeatConfig()
 	var cachePreHeatConfig define.CachePreHeatConfig
 	serialize.JSON.TransitionIgnoreError(inputCachePreHeatConfig, &cachePreHeatConfig)
+	log.RecordDebug("接口请求命中缓存", map[string]any{
+		"cache_info": cacheResult.CacheInfo,
+	}, hc.reqConfig)
+	defer func() {
+		// 命中缓存的情况下, 检测缓存预热策略, 判断是否进行缓存预热
+		go func() {
 			if !cachePreHeatConfig.Enable || (cachePreHeatConfig.MinTTL <= 0 && cachePreHeatConfig.MinPercent <= 0 && !cachePreHeatConfig.Force) {
 				// 无预热配置或未启用预热或者未设置预热规则
-			return cacheResult
+				log.RecordDebug("接口请求命中缓存, 未配置缓存预热策略", map[string]any{
+					"cache_pre_heat_config": cachePreHeatConfig,
+				}, hc.reqConfig)
+				return
 			}
-		go func() {
 			// 判断是否触发预热
 			if cachePreHeatConfig.Force {
+				log.RecordDebug("接口请求命中缓存, 强制执行缓存预热, 忽略其他策略配置", map[string]any{
+					"cache_pre_heat_config": cachePreHeatConfig,
+				}, hc.reqConfig)
 				_ = hc.requestBackendApi()
 				return
 			}
 			// 将百分比的配置归一化成最小剩余时间的配置
 			if cachePreHeatConfig.MinPercent > 0 {
 				expectMinTTL := hc.cacheInstance.CacheTime() * cachePreHeatConfig.MinPercent / 100
+				log.RecordDebug("接口请求命中缓存, 配置预热策略：有效时长剩余百分比", map[string]any{
+					"cache_pre_heat_config": cachePreHeatConfig,
+					"percent_min_ttl":       expectMinTTL,
+					"min_ttl":               cachePreHeatConfig.MinTTL,
+				}, hc.reqConfig)
 				if cachePreHeatConfig.MinTTL == 0 || cachePreHeatConfig.MinTTL > expectMinTTL {
 					cachePreHeatConfig.MinTTL = expectMinTTL
 				}
 			}
 			if cachePreHeatConfig.MinTTL <= 0 {
 				// 未配置最小剩余时间
+				log.RecordDebug("接口请求命中缓存, 未配置预热市场策略, 不执行预热", map[string]any{
+					"min_ttl": cachePreHeatConfig.MinTTL,
+				}, hc.reqConfig)
 				return
 			}
 			ttl := hc.cacheInstance.TTL(cacheResult.CacheInfo.CacheKey)
 			if ttl < 0 {
 				// 不存在或者未设置有效期
+				log.RecordDebug("接口请求命中缓存, 当前缓存结果不存在或未设置有效期, 不执行预热", map[string]any{
+					"min_ttl": cachePreHeatConfig.MinTTL,
+					"note":    "预热时间至少在缓存过期前10s触发预热, 以保证足够时间进行预热, 以及不会因为预热尚未完成, 但是大量流量涌入, 进而导致流量穿透",
+				}, hc.reqConfig)
 				return
 			}
 
-			if ttl <= cachePreHeatConfig.MinTTL {
+			if ttl > cachePreHeatConfig.MinTTL {
+				log.RecordDebug("接口请求命中缓存, 缓存结果有效期剩余时长大于配置阈值, 不执行预热", map[string]any{
+					"min_ttl":       cachePreHeatConfig.MinTTL,
+					"remaining_ttl": ttl,
+				}, hc.reqConfig)
+				return
+			}
+			log.RecordDebug("接口请求命中缓存, 缓存结果有效期大于剩余时长小于配置阈值, 触发预热", map[string]any{
+				"min_ttl":       cachePreHeatConfig.MinTTL,
+				"remaining_ttl": ttl,
+			}, hc.reqConfig)
 			// 配置了最小剩余时间,并且key剩余有效期小于最小剩余时间
 			_ = hc.requestBackendApi()
-			}
 		}()
-	}
+	}()
-
+	// 命中缓存必然请求成功, 直接记录成功日志即可
-	return hc.requestBackendApi()
+	log.Record(consts.LogLevelInfo, "接口请求成功:命中缓存", hc.reqConfig, cacheResult)
-
+	return cacheResult
 }
 
 // requestBackendApi 请求后端接口
@@ -275,6 +311,10 @@ func (hc *HttpClient) requestBackendApi() *define.Response {
 
 	response := hc.newResponse()
 	for i := 0; i < hc.reqConfig.RetryRule.RetryCount+1; i++ {
+		if i > 0 {
+			// 非首次请求, 说明是重试, 暂停指定时间间隔
+			time.Sleep(time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond)
+		}
 		if response.Seq > 0 {
 			// 说明是重试, 记录上一次的请求信息
 			response.RequestFinishTime = time.Now().UnixMilli()
@@ -306,23 +346,36 @@ func (hc *HttpClient) requestBackendApi() *define.Response {
 			if err.Error() == resty.ErrRateLimitExceeded.Error() {
 				// 命中限流
 				errType = define.RequestFailTypeRateLimit
-			} else if _, ok := err.(net.Error); ok {
+			} else if netErr, ok := err.(net.Error); ok {
+				if netErr.Timeout() {
 					// 请求超时
 					errType = define.RequestFailTypeTimeoutError
 				}
+			}
 			response.FailInfo = &define.ResponseFailInfo{
 				Type:    errType,
 				Message: err.Error(),
 			}
+			log.RecordDebug("请求发送出现异常", map[string]any{
+				"err_type": errType,
+				"err_msg":  err.Error(),
+			}, hc.reqConfig)
 			if errType == define.RequestFailTypeSend {
 				// 命中限流就不重试了
+				log.RecordDebug("请求命中限流, 忽略重试策略, 不进行重试", nil, hc.reqConfig)
 				break
 			}
-			if len(retryHttpCodeTable) > 0 && !retryHttpCodeTable[499] {
+
+			if errType == define.RequestFailTypeTimeoutError && !retryHttpCodeTable[499] {
 				// 未配置超时重试
+				log.RecordDebug("请求超时, 未配置超时重试, 不进行重试", nil, hc.reqConfig)
 				break
 			}
-			time.Sleep(time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond)
+			log.RecordDebug("请求发送出现异常, 进行重试", map[string]any{
+				"err_type":      errType,
+				"err_msg":       err.Error(),
+				"time_interval": time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond,
+			}, hc.reqConfig)
 			continue
 		}
 
@@ -331,7 +384,10 @@ func (hc *HttpClient) requestBackendApi() *define.Response {
 				Type:    define.RequestFailTypeSend,
 				Message: "response instance is nil",
 			}
-			time.Sleep(time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond)
+			log.RecordDebug("RestyResponse为nil, 准备重试", map[string]any{
+				"err_type":      response.FailInfo.Type,
+				"time_interval": time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond,
+			}, hc.reqConfig)
 			continue
 		}
 		// 解析返回信息
@@ -351,11 +407,18 @@ func (hc *HttpClient) requestBackendApi() *define.Response {
 				Type:    errType,
 				Message: "http code is " + response.HttpCodeStatus + ", not success",
 			}
+			log.RecordWarn("请求响应的http状态码非成功", map[string]any{
+				"err_type":           errType,
+				"err_msg":            response.RestyResponse.Status(),
+				"response_http_code": response.HttpCode,
+				"success_http_code":  hc.reqConfig.SuccessHttpCodeList,
+				"allow_retry":        len(retryHttpCodeTable) == 0 || retryHttpCodeTable[int64(response.HttpCode)],
+				"time_interval":      time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond,
+			}, hc.reqConfig)
 			if len(retryHttpCodeTable) > 0 && !retryHttpCodeTable[int64(response.HttpCode)] {
 				// 未配置http code重试
 				break
 			}
-			time.Sleep(time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond)
 			continue
 		}
 		if !hc.isCodeSuccess(response) {
@@ -363,11 +426,18 @@ func (hc *HttpClient) requestBackendApi() *define.Response {
 				Type:    define.RequestFailTypeBusinessError,
 				Message: "business code is " + response.Code + ", not success",
 			}
+			log.RecordWarn("请求响应状态码成功, 业务状态码非成功", map[string]any{
+				"err_type":      response.FailInfo.Type,
+				"err_msg":       response.Message,
+				"response_code": response.Code,
+				"success_code":  hc.reqConfig.SuccessCodeList,
+				"allow_retry":   len(retryBusinessCodeTable) == 0 || retryBusinessCodeTable[response.Code],
+				"time_interval": time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond,
+			}, hc.reqConfig)
 			if len(retryBusinessCodeTable) > 0 && !retryBusinessCodeTable[response.Code] {
 				// 未配置业务code重试
 				break
 			}
-			time.Sleep(time.Duration(hc.reqConfig.RetryRule.RetryTimeInterval) * time.Millisecond)
 			continue
 		}
 		response.IsSuccess = true                                                                //设置成功
@@ -511,17 +581,26 @@ func (hc *HttpClient) isCodeSuccess(response *define.Response) bool {
 //
 // Date : 16:04 2024/6/3
 func (hc *HttpClient) getCacheResult() *define.Response {
-	if nil == hc.cacheInstance || !hc.cacheInstance.Enable() {
+	if nil == hc.cacheInstance {
+		log.RecordDebug("接口请求前缓存检测, 未设置缓存实例", map[string]any{}, hc.reqConfig)
+		return nil
+	}
+	if !hc.cacheInstance.Enable() {
+		log.RecordDebug("接口请求前缓存检测, 设置缓存实例, 但未启用缓存功能", map[string]any{}, hc.reqConfig)
 		return nil
 	}
 	startTime := time.Now().UnixMilli()
 	cacheKey := hc.cacheInstance.GetKey(hc.reqConfig)
 	cacheValue := strings.TrimSpace(hc.cacheInstance.GetValue(cacheKey))
 	if len(cacheValue) == 0 {
+		log.RecordDebug("接口请求前缓存检测, 未读取到缓存数据", map[string]any{}, hc.reqConfig)
 		return nil
 	}
 	response := hc.newResponse()
 	if err := serialize.JSON.UnmarshalWithNumber([]byte(cacheValue), response); nil != err {
+		log.RecordWarn("接口请求前缓存检测, 读取到缓存数据, 数据解析失败, 将跳过缓存, 请求对应接口", map[string]any{
+			"err_msg": err.Error(),
+		}, hc.reqConfig)
 		return nil
 	}
 	response.CacheInfo.IsCache = true                                          // 设置缓存标记
@@ -530,6 +609,7 @@ func (hc *HttpClient) getCacheResult() *define.Response {
 	response.UsedTime = response.RequestFinishTime - response.RequestStartTime // 耗时
 	response.CacheInfo.CacheKey = cacheKey                                     // 缓存key
 	response.CacheInfo.CacheValue = cacheValue                                 // 缓存值
+	log.RecordDebug("接口请求前缓存检测, 命中缓存, 直接返回缓存数据", map[string]any{}, hc.reqConfig)
 	return response
 }
 
@@ -540,17 +620,36 @@ func (hc *HttpClient) getCacheResult() *define.Response {
 // Date : 16:24 2024/6/3
 func (hc *HttpClient) setCacheResult(response *define.Response) (bool, error) {
 	if nil == response || nil == hc.cacheInstance {
+		log.RecordDebug("接口请求成功后, 缓存设置失败", map[string]any{
+			"response_is_nil":       response == nil,
+			"cache_instance_is_nil": hc.cacheInstance == nil,
+		}, hc.reqConfig)
 		return false, nil
 	}
 	// 全局未开启或者当前请求不支持缓存
-	if !hc.cacheInstance.Enable() || !hc.cacheInstance.IsAllow(hc.reqConfig, response) {
+	globalCacheEnable := hc.cacheInstance.Enable()
+	currentRequestAllowCache := hc.cacheInstance.IsAllow(hc.reqConfig, response)
+	log.RecordDebug("检测缓存是否允许执行", map[string]any{
+		"current_cache_enable": currentRequestAllowCache,
+		"global_cache_enable":  globalCacheEnable,
+	}, hc.reqConfig)
+	if !globalCacheEnable || !currentRequestAllowCache {
 		return false, nil
 	}
 	cacheKey := hc.cacheInstance.GetKey(hc.reqConfig)
 	cacheValue := serialize.JSON.MarshalForStringIgnoreError(response)
 	if err := hc.cacheInstance.SetValue(cacheKey, cacheValue); nil != err {
+		log.RecordWarn("开启结果缓存, 缓存设置失败", map[string]any{
+			"current_cache_enable": currentRequestAllowCache,
+			"global_cache_enable":  globalCacheEnable,
+			"err_msg":              err.Error(),
+		}, hc.reqConfig)
 		return false, err
 	}
+	log.RecordDebug("开启结果缓存, 缓存设置成功", map[string]any{
+		"current_cache_enable": currentRequestAllowCache,
+		"global_cache_enable":  globalCacheEnable,
+	}, hc.reqConfig)
 	response.CacheInfo.CacheKey = cacheKey
 	response.CacheInfo.CacheValue = cacheValue
 	return true, nil

httpclient/log/log.go

@@ -33,13 +33,17 @@ func Set(l *zap.Logger) {
 //
 // Date : 18:19 2025/3/31
 func Get() *zap.Logger {
+	if nil == logger {
+		// 返回日志空实现
+		return zap.NewNop()
+	}
 	return logger
 }
 
 var buildHttpLogDataFunc BuildHttpLogDataFunc
 
 // BuildHttpLogDataFunc 构建http请求日志数据的方法
-type BuildHttpLogDataFunc func(ctx context.Context, reqCfg *define.Request, response *define.Response) []zap.Field
+type BuildHttpLogDataFunc func(ctx context.Context, isResponseLog bool, businessData map[string]any, reqCfg *define.Request, response *define.Response) []zap.Field
 
 func SetBuildDataFunc(f BuildHttpLogDataFunc) {
 	buildHttpLogDataFunc = f
@@ -54,8 +58,8 @@ func GetBuildDataFunc() BuildHttpLogDataFunc {
 // Author : go_developer@163.com<白茶清欢>
 //
 // Date : 18:07 2025/3/31
-func Record(ctx context.Context, logInstance *zap.Logger, level consts.LogLevel, msg string, reqCfg *define.Request, response *define.Response) {
+func Record(level consts.LogLevel, msg string, reqCfg *define.Request, response *define.Response) {
-	if nil == logInstance {
+	if nil == reqCfg.Logger {
 		// 未设置日志实例
 		return
 	}
@@ -64,7 +68,8 @@ func Record(ctx context.Context, logInstance *zap.Logger, level consts.LogLevel,
 		// 未设置构建日志数据的方法
 		return
 	}
-	fields := buildDataFunc(ctx, reqCfg, response)
+	fields := buildDataFunc(reqCfg.Ctx, true, nil, reqCfg, response)
+	logInstance := reqCfg.Logger
 	switch level {
 	case consts.LogLevelDebug:
 		logInstance.Debug(msg, fields...)
@@ -78,3 +83,63 @@ func Record(ctx context.Context, logInstance *zap.Logger, level consts.LogLevel,
 		logInstance.Panic(msg, fields...)
 	}
 }
+
+// RecordDebug 日志记录
+func RecordDebug(msg string, businessData map[string]any, reqCfg *define.Request) {
+	if nil == reqCfg.Logger {
+		// 未设置日志实例
+		return
+	}
+	buildDataFunc := GetBuildDataFunc()
+	if nil == buildDataFunc {
+		// 未设置构建日志数据的方法
+		return
+	}
+	fields := buildDataFunc(reqCfg.Ctx, false, businessData, reqCfg, nil)
+	reqCfg.Logger.Debug(msg, fields...)
+}
+
+// RecordInfo ...
+func RecordInfo(msg string, businessData map[string]any, reqCfg *define.Request) {
+	if nil == reqCfg.Logger {
+		// 未设置日志实例
+		return
+	}
+	buildDataFunc := GetBuildDataFunc()
+	if nil == buildDataFunc {
+		// 未设置构建日志数据的方法
+		return
+	}
+	fields := buildDataFunc(reqCfg.Ctx, false, businessData, reqCfg, nil)
+	reqCfg.Logger.Info(msg, fields...)
+}
+
+// RecordWarn ...
+func RecordWarn(msg string, businessData map[string]any, reqCfg *define.Request) {
+	if nil == reqCfg.Logger {
+		// 未设置日志实例
+		return
+	}
+	buildDataFunc := GetBuildDataFunc()
+	if nil == buildDataFunc {
+		// 未设置构建日志数据的方法
+		return
+	}
+	fields := buildDataFunc(reqCfg.Ctx, false, businessData, reqCfg, nil)
+	reqCfg.Logger.Warn(msg, fields...)
+}
+
+// RecordError ...
+func RecordError(msg string, businessData map[string]any, reqCfg *define.Request) {
+	if nil == reqCfg.Logger {
+		// 未设置日志实例
+		return
+	}
+	buildDataFunc := GetBuildDataFunc()
+	if nil == buildDataFunc {
+		// 未设置构建日志数据的方法
+		return
+	}
+	fields := buildDataFunc(reqCfg.Ctx, false, businessData, reqCfg, nil)
+	reqCfg.Logger.Error(msg, fields...)
+}