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(); }