0x01业务描述
说明: 同事搭建的业务系统,最开始使用 log4net 记录到本地日志. 然后多个项目为了日志统一,全部记录在 Elasticsearch ,使用 log4net.ElasticSearchAppender.DotNetCore.
然后搭建了 Kibanal 对 Elasticsearch 进行查询. 但是项目组开发人员众多,不是每个人都想要学会如何在 Kibanal 中查询日志.
所以 就需要开发一个 有针对性的, 查询用户界面. 最近这个功能就交到我手上了.
方案是: 通过 NEST 查询 Elasticsearch 的接口, 将前端页面传过来的参数, 组装成 NEST 的查询请求.
0x02主要实现代码
日志索引为: xxxapilog_*
时间关键字段为: "@timestamp"
1 /// <summary> 2 /// 根据查询条件,封装请求 3 /// </summary> 4 /// <param name="query"></param> 5 /// <returns></returns> 6 public async Task<ISearchResponse<Dictionary<string, object>>> GetSearchResponse(API_Query query) 7 { 8 int size = query.PageSize; 9 int from = (query.PageIndex - 1) * size; 10 ISearchResponse<Dictionary<string, object>> searchResponse1 = await elasticClient.SearchAsync<Dictionary<string, object>>(searchDescriptor => 11 { 12 Field sortField = new Field("@timestamp"); 13 return searchDescriptor.Index("xxxapilog_*") 14 .Query(queryContainerDescriptor => 15 { 16 return queryContainerDescriptor.Bool(boolQueryDescriptor => 17 { 18 IList<Func<QueryContainerDescriptor<Dictionary<string, object>>, QueryContainer>> queryContainers = new List<Func<QueryContainerDescriptor<Dictionary<string, object>>, QueryContainer>>(); 19 20 if (!string.IsNullOrEmpty(query.Level)) 21 { 22 queryContainers.Add(queryContainerDescriptor => 23 { 24 return queryContainerDescriptor.Term(c => c.Field("Level").Value(query.Level.ToLower())); 25 }); 26 } 27 if (query.QueryStartTime.Year>=2020) 28 { 29 queryContainers.Add(queryContainerDescriptor => 30 { 31 return queryContainerDescriptor.DateRange(c => c.Field("@timestamp").GreaterThanOrEquals(query.QueryStartTime)); 32 }); 33 34 } 35 if (query.QueryEndTime.Year >= 2020) 36 { 37 queryContainers.Add(queryContainerDescriptor => 38 { 39 return queryContainerDescriptor.DateRange(c => c.Field("@timestamp").LessThanOrEquals(query.QueryEndTime)); 40 }); 41 } 42 //...省略其他字段 相关查询 43 44 boolQueryDescriptor.Must(x => x.Bool(b => b.Must(queryContainers))); 45 return boolQueryDescriptor; 46 }); 47 }) 48 .Sort(q => q.Descending(sortField)) 49 .From(from).Size(size); 50 }); 51 return searchResponse1; 52 }
接口参数类:
/// <summary> /// api接口日志查询参数 /// </summary> public class API_Query { /// <summary> /// 默认第一页 /// </summary> public int PageIndex { get; set; } /// <summary> /// 默认页大小为500 /// </summary> public int PageSize { get; set; } /// <summary> /// WARN 和 INFO /// </summary> public string Level { get; set; } /// <summary> /// 对应@timestamp 的开始时间,默认15分钟内 /// </summary> public string StartTime { get; set; } /// <summary> /// 对应@timestamp 的结束时间,默认当前时间 /// </summary> public string EndTime { get; set; } public DateTime QueryStartTime { get; set; } public DateTime QueryEndTime { get; set; } }
调用方式:
API_Query query = new API_Query () { PageIndex=1, PageSize=10 }; ISearchResponse<Dictionary<string, object>> searchResponse = await GetSearchResponse(query); var hits = searchResponse.HitsMetadata.Hits; var total = searchResponse.Total; IReadOnlyCollection<Dictionary<string, object>> res2 = searchResponse.Documents; if (total > 0) { return res2.ToList()[0]; }
0x03 时间字段预处理
PS: 如果 StartTime 和 EndTime 都不传值, 那么 默认设置 只查最近的 15分钟
封装一下 QueryStartTime 和 QueryEndTime
public DateTime QueryStartTime { get { DateTime dt = DateTime.Now.AddMinutes(-15); if (!string.IsNullOrEmpty(StartTime) && StartTime.Trim() != "") { DateTime p; DateTime.TryParse(StartTime.Trim(), out p); if (p.Year >= 2020) { dt = p; } } return dt; } } public DateTime QueryEndTime { get { DateTime dt = DateTime.Now; if (!string.IsNullOrEmpty(EndTime) && EndTime.Trim() != "") { DateTime p; DateTime.TryParse(EndTime.Trim(), out p); if (p.Year >= 2020) { dt = p; } } return dt; } }
0x04 查找问题原因
以上 封装,经过测试, 能够获取到查询数据. 但是,但是 ,但是 坑爹的来了,当 外面传入参数
API_Query query = new API_Query () { PageIndex=1, PageSize=10,StartTime = "2023-04-28",EndTime = "2023-04-28 15:00:00"};
查询的结果集里面居然有 2023-04-28 15:00:00 之后的数据. 使用的人反馈到我这里以后,我也觉得纳闷,啥情况呀.
需要监听一下 NEST 请求的实际语句
public class ESAPILogHelper { ElasticClient elasticClient; /// <summary> /// es通用查询类 /// </summary> /// <param name="address"></param> public ESAPILogHelper(string address) { elasticClient = new ElasticClient(new ConnectionSettings(new Uri(address)).DisableDirectStreaming() .OnRequestCompleted(apiCallDetails => { if (apiCallDetails.Success) { string infos = GetInfosFromApiCallDetails(apiCallDetails);
//在此处打断点,查看请求响应的原始内容 Console.WriteLine(infos); })); } private string GetInfosFromApiCallDetails(IApiCallDetails r) { string infos = ""; infos += $"Uri:t{r.Uri}n"; infos += $"Success:t{r.Success}n"; infos += $"SuccessOrKnownError:t{r.SuccessOrKnownError}n"; infos += $"HttpMethod:t{r.HttpMethod}n"; infos += $"HttpStatusCode:t{r.HttpStatusCode}n"; //infos += $"DebugInformation:n{r.DebugInformation}n"; //foreach (var deprecationWarning in r.DeprecationWarnings) // infos += $"DeprecationWarnings:n{deprecationWarning}n"; if (r.OriginalException != null) { infos += $"OriginalException.GetMessage:n{r.OriginalException.Message}n"; infos += $"OriginalException.GetStackTrace:n{r.OriginalException.Message}n"; } if (r.RequestBodyInBytes != null) infos += $"RequestBody:n{Encoding.UTF8.GetString(r.RequestBodyInBytes)}n"; if (r.ResponseBodyInBytes != null) infos += $"ResponseBody:n{Encoding.UTF8.GetString(r.ResponseBodyInBytes)}n"; infos += $"ResponseMimeType:n{r.ResponseMimeType}n"; return infos; }
请求分析:
如果 StartTime 和 EndTime 都不传值 , 请求的 参数为
{
"from": 0,
"query": {
"bool": {
"must": [
{
"bool": {
"must": [
{
"range": {
"@timestamp": {
"gte": "2023-04-28T17:44:09.6630219+08:00"
}
}
},
{
"range": {
"@timestamp": {
"lte": "2023-04-28T17:59:09.6652844+08:00"
}
}
}
]
}
}
]
}
},
"size": 10,
"sort": [
{
"@timestamp": {
"order": "desc"
}
}
]
}
如果 StartTime 和 EndTime 传入 2023-04-28 和 2023-04-28 15:00:00, 请求的 参数为
{ "from": 0, "query": { "bool": { "must": [ { "bool": { "must": [ { "range": { "@timestamp": { "gte": "2023-04-28T00:00:00" } } }, { "range": { "@timestamp": { "lte": "2023-04-28T15:00:00" } } } ] } } ] } }, "size": 10, "sort": [ { "@timestamp": { "order": "desc" } } ] }
对比后发现 , 时间传值有2种不同的格式
"@timestamp": { "gte": "2023-04-28T17:44:09.6630219+08:00" }
"@timestamp": {"gte": "2023-04-28T00:00:00" }
这两种格式 有什么 不一样呢?
0x05 测试求证
我做了个测试
//不传参数, 默认结束时间为当前时间 DateTime end_current = DateTime.Now; //如果传了参数, 使用 DateTime.TryParse 取 结束时间 DateTime init = query.QueryEndTime; DateTime endNew = new DateTime(init.Year, init.Month, init.Day, init.Hour, init.Minute, init.Second); //这一步是 为了 补偿 时间值, 让 enNew 和 end_current 的ticks 一致 long s1_input = endNew.Ticks; long s2_current = end_current.Ticks; endNew = endNew.AddTicks(s2_current - s1_input); long t1 = endNew.Ticks; long t2 = end_current.Ticks; //对比 end_current 和 endNew, 现在的确是 相等的. bool isEqual = t1 == t2; // 结果为 true //但是, 传入 end_current 和 enNew,执行的请求 却不一样, queryContainerDescriptor.DateRange(c => c.Field("timeStamp").LessThanOrEquals(end_current)); ==>请求结果为: 2023-04-28T17:44:09.6630219+08:00 queryContainerDescriptor.DateRange(c => c.Field("timeStamp").LessThanOrEquals(enNew)); ==>请求结果为: 2023-04-28T17:44:09.6630219Z
进一步测试
isEqual = endNew == end_current; //结果 true
isEqual = endNew.ToUniversalTime() == end_current.ToUniversalTime(); //结果仍然为true
isEqual = endNew.ToLocalTime() == end_current.ToLocalTime(); //结果居然为 fasle !!!
基于以上测试, 算是搞明白了是怎么回事.
比如现在是北京时间 : DateTime.Now 值为 2023-04-28 15:00:00, 那么 DateTime.Now.ToLocalTime() 还是 2023-04-28 15:00:00
Console.WriteLine(DateTime.Now.ToLocalTime());
如是字符串 DateTime.Parse("2023-04-28 15:00:00").ToLocalTime(), 值为 2023-04-28 23:00:00 (比2023-04-28 15:00:00 多 8 个小时)
那么回到题头部分, 当用户输入
2023-04-28 和 2023-04-28 15:00:00, 实际查询的数据范围为 2023-04-28 08:00:00 和 2023-04-28 23:00:00 自然就显示出了 2023-04-28 15点以后的数据,然后因为是倒序,又分了页
所以看不出日志的开始时间, 只能根据日志的结果时间 发现超了,来诊断.
0x06 解决方案
基于以上测试, 现在统一用 ToUniversalTime,即可保持数据的一致
isEqual = endNew.ToUniversalTime().ToLocalTime() == end_current.ToUniversalTime().ToLocalTime(); //结果为true
Console.WriteLine(isEqual); //结果为 true
那么修改一下参数的取值
1 public DateTime QueryStartTime 2 { 3 get 4 { 5 DateTime dt = DateTime.Now.AddMinutes(-15); 6 if (!string.IsNullOrEmpty(StartTime) && StartTime.Trim() != "") 7 { 8 DateTime p; 9 DateTime.TryParse(StartTime.Trim(), out p); 10 if (p.Year >= 2020) 11 { 12 dt = p; 13 } 14 } 15 return dt.ToUniversalTime(); 16 } 17 } 18 19 public DateTime QueryEndTime 20 { 21 get 22 { 23 24 DateTime dt = DateTime.Now; 25 if (!string.IsNullOrEmpty(EndTime) && EndTime.Trim() != "") 26 { 27 DateTime p; 28 DateTime.TryParse(EndTime.Trim(), out p); 29 if (p.Year >= 2020) 30 { 31 dt = p; 32 } 33 } 34 return dt.ToUniversalTime(); 35 } 36 }
好了, 现在问题解决了!!!
==>由此 推测
return queryContainerDescriptor.DateRange(c => c.Field("timeStamp").GreaterThanOrEquals(DateMath from));
DateMath from 使用了 ToLocalTime .
0x07 简单测试用例
这里贴上简要的测试用例,方便重现问题.
static void Main(string[] args) { //首先 读取配置 Console.WriteLine("程序运行开始"); try { //不传参数, 默认结束时间为当前时间 DateTime end_current = DateTime.Now; //如果传了参数, 使用 DateTime.TryParse 取 结束时间 DateTime init = new DateTime() ; DateTime.TryParse("2023-04-28 15:00:00", out init); DateTime endNew = new DateTime(init.Year, init.Month, init.Day, init.Hour, init.Minute, init.Second); //这一步是 为了 补偿 时间值, 让 enNew 和 end_current 的ticks 一致 long s1_input = endNew.Ticks; long s2_current = end_current.Ticks; endNew = endNew.AddTicks(s2_current - s1_input); //对比 end_current 和 enNew, 现在的确是 相等的. long t1 = endNew.Ticks; long t2 = end_current.Ticks; bool isEqual = t1 == t2; // 结果为 true Console.WriteLine(isEqual); isEqual = endNew == end_current; Console.WriteLine(isEqual); isEqual = endNew.ToUniversalTime() == end_current.ToUniversalTime(); Console.WriteLine(isEqual); isEqual = endNew.ToLocalTime() == end_current.ToLocalTime(); Console.WriteLine(isEqual); Console.WriteLine(endNew.ToLocalTime()); Console.WriteLine(end_current.ToLocalTime()); DateTime dinit; DateTime.TryParse("2023-04-28 15:00:00", out dinit); Console.WriteLine(dinit.ToLocalTime()); isEqual = endNew.ToUniversalTime().ToLocalTime() == end_current.ToUniversalTime().ToLocalTime(); Console.WriteLine(isEqual); } catch (Exception ex) { string msg = ex.Message; if (ex.InnerException != null) { msg += ex.InnerException.Message; } Console.WriteLine("程序运行出现异常"); Console.WriteLine(msg); } Console.WriteLine("程序运行结束"); Console.ReadLine(); }
