serilog / serilog-expressions

An embeddable mini-language for filtering, enriching, and formatting Serilog events, ideal for use with JSON or XML configuration.
Apache License 2.0
190 stars 17 forks source link

Logs still showing on a ByExcluding filter when I have StatusCode on expression #89

Closed aristotelis79 closed 1 year ago

aristotelis79 commented 1 year ago

Hello,

I use this filter rule on appSettings ... "Using": [ "Serilog.Expressions", "Serilog.Settings.Configuration" ], "Filter": [ { "Name": "ByExcluding", "Args": { "expression": "(RequestPath like '%/something/%' or RequestPath like '%/something2/%') and StatusCode = 200" } } ] ... but not working, still show the logs. When change the "expression": "(RequestPath like '%/something/%' or RequestPath like '%/something2/%')" without status code is working fine.

P.S. I tried several simple compinations like RequestPath like "expression": "RequestPath = '/something' and StatusCode = 200" but every time I have the statuscode is not working

Thank you in advance.

enviroment: .net core 7 with Serilog.AspNetCore 6.1.0, Serilog.Expressions 3.4.1, Serilog.Settings.Configuration 3.4.0, Serilog.Formatting.Compact 1.1.0

nblumhardt commented 1 year ago

Hi! Thanks for dropping us a line. Can you please post an example log event that's being emitted but shouldn't (ideally in the compact JSON format?) Thanks!

aristotelis79 commented 1 year ago

At first thank you for the response.

Here the logs I want to exclude on 200. (Sorry but I have it in a format for console)

-- expression: RequestPath like '%/home/%' and StatusCode = 200

[07:43:50] [INF] [cldfncnm400031w3j83cdwo4o] Request starting HTTP/1.1 POST http://localhost:5006/home/update - 0 [07:43:50] [INF] [cldfncnm400031w3j83cdwo4o] Executing endpoint 'Project.API.Controllers.HomeController.Update (Project.API)' [07:43:50] [INF] [cldfncnm400031w3j83cdwo4o] Route matched with {action = "Update", controller = "Home"}. Executing controller action with signature System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.IActionResult] Update(System.Nullable1[System.DateTime], System.Threading.CancellationToken) on controller Project.API.Controllers.HomeController (Project.API). [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] {"Value": "", "HasValue": false, "$type": "QueryString"} [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executing action method Project.API.Controllers.HomeController.Update (Project.API) - Validation state: Valid [07:43:51] [DBG] [cldfncnm400031w3j83cdwo4o] {"Timestamp": null, "$type": "Update"} [07:43:51] [DBG] [cldfncnm400031w3j83cdwo4o] {"Timestamp": null, "$type": "AllRecentQuery"} [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executed DbCommand (65ms) [Parameters=[@__after_0='?' (DbType = DateTime2)], CommandType='Text', CommandTimeout='30'] <SQL Query to DB> [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executed action method Project.API.Controllers.HomeController.Update (Project.API), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 461.1453ms. [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] 0 [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executing OkObjectResult, writing value of type 'System.Int64'. [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executed action Project.API.Controllers.HomeController.Update (Project.API) in 633.8218ms [07:43:51] [INF] [cldfncnm400031w3j83cdwo4o] Executed endpoint 'Project.API.Controllers.HomeController.Update (Project.API)'

nblumhardt commented 1 year ago

Need the JSON to see what properties are on the events. These ones don't look like they carry a StatusCode property so that would be the most likely reason for them not matching the filter. HTH!

aristotelis79 commented 1 year ago

Thank you again. I try add the status code to the message. Here the json [{"@t":"2023-01-31T08:32:50.8724037Z","@m":"Route matched with \"{action = \\\"Update\\\", controller = \\\"Project\\\"}\". Executing controller action with signature \"System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.IActionResult] Update(System.Nullable1[System.DateTime], System.Threading.CancellationToken)\" on controller \"Sample.Project.API.Controllers.HomeController\" (\"Sample.Project.API\").","@i":"122b2fdf","RouteData":"{action = \"Update\", controller = \"Project\"}","MethodInfo":"System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.IActionResult] Update(System.Nullable1[System.DateTime], System.Threading.CancellationToken)","Controller":"Sample.Project.API.Controllers.HomeController","AssemblyName":"Sample.Project.API","EventId":{"Id":102,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.0370205Z","@m":"QueryString { Value: \"\", HasValue: False }","@i":"47841fc9","queryString":{"Value":"","HasValue":false,"$type":"QueryString"},"Request":{"Params":{"timestamp":null,"token":{"IsCancellationRequested":false,"CanBeCanceled":true,"WaitHandle":{"Handle":{"$type":"IntPtr"},"SafeWaitHandle":{"IsInvalid":false,"IsClosed":false,"$type":"SafeWaitHandle"},"$type":"ManualResetEvent"},"$type":"CancellationToken"}},"Headers":{"Accept":["*/*"],"Connection":["keep-alive"],"Host":["localhost:5006"],"User-Agent":["PostmanRuntime/7.30.0"],"Accept-Encoding":["gzip, deflate, br"],"Authorization":["Bearer ...."],"Cache-Control":["no-cache"],"traceparent":["00-214165f2b5f7a8a8a8e42cf14fab79ec-874e6e4d255843cb-00"],"Content-Length":["0"],"Postman-Token":["abdad865-a8fc-45db-9862-961f05bda9c5"],"x-auth-id":["1000"],"x-user-id":["1000"],"x-trace-id":["cldk3pjge0002y83j9ot5m8fy"]},"Host":"localhost:5006","ClientInfo":{"String":"PostmanRuntime/7.30.0","OS":{"Family":"Other","Major":null,"Minor":null,"Patch":null,"PatchMinor":null,"$type":"OS"},"Device":{"IsSpider":false,"Brand":"","Family":"Other","Model":"","$type":"Device"},"UserAgent":{"Family":"Other","Major":null,"Minor":null,"Patch":null,"$type":"UserAgent"},"UA":{"Family":"Other","Major":null,"Minor":null,"Patch":null,"$type":"UserAgent"},"$type":"ClientInfo"},"Ip":null,"Country":null},"Method":"req: POST /project/update","Context":"api","UserId":"1000","AuthId":"1000","TraceId":"cldk3pjge0002y83j9ot5m8fy","Service":"project","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.0415984Z","@m":"Executing action method \"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)\" - Validation state: Valid","@i":"dad538d7","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","ValidationState":"Valid","EventId":{"Id":101,"Name":"ActionMethodExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.0571635Z","@m":"UpdateCommand { Timestamp: null }","@i":"c5134d08","@l":"Debug","request":{"Timestamp":null,"$type":"UpdateCommand"},"Event":{"Timestamp":null,"$type":"UpdateCommand"},"Method":"command: UpdateCommand","Context":"mediatr","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.0726529Z","@m":"AllRecentQuery { Timestamp: null }","@i":"c5134d08","@l":"Debug","request":{"Timestamp":null,"$type":"AllRecentQuery"},"Method":"query: AllRecentQuery","Context":"persistence","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5055769Z","@m":"Executed DbCommand (\"73\"ms) [Parameters=[....","@i":"0723d8ff","elapsed":"73","parameters":"@__after_0='?' (DbType = DateTime2)","commandType":"Text","commandTimeout":30,"newLine":"\r\n","commandText":"SELECT ....","EventId":{"Id":20101,"Name":"Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted"},"SourceContext":"Microsoft.EntityFrameworkCore.Database.Command","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5352623Z","@m":"Executed action method \"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)\", returned result \"Microsoft.AspNetCore.Mvc.OkObjectResult\" in 489.9776ms.","@i":"50a9e262","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","ActionResult":"Microsoft.AspNetCore.Mvc.OkObjectResult","ElapsedMilliseconds":489.9776,"EventId":{"Id":103,"Name":"ActionMethodExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5433322Z","@m":"0","@i":"db5c774a","response":0,"Response":{"Headers":{"X-MiniProfiler-Ids":["[\"cff70dbc-cd79-4c73-a835-e65f2c27eecc\"]"]},"StatusCode":200,"Response":0},"Method":"res: POST /project/update","Context":"api","UserId":"1000","AuthId":"1000","TraceId":"cldk3pjge0002y83j9ot5m8fy","Service":"project","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5489429Z","@m":"Executing \"OkObjectResult\", writing value of type '\"System.Int64\"'.","@i":"605b4265","ObjectResultType":"OkObjectResult","Type":"System.Int64","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5759462Z","@m":"Executed action \"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)\" in 699.7335ms","@i":"afa2e885","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","ElapsedMilliseconds":699.7335,"EventId":{"Id":105,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."},{"@t":"2023-01-31T08:32:51.5767701Z","@m":"Executed endpoint '\"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)\"'","@i":"99874f2b","EndpointName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","EventId":{"Id":1,"Name":"ExecutedEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","Service":"project","TraceId":"cldk3pjge0002y83j9ot5m8fy","AuthId":"1000","UserId":"1000","MachineName":"LAPTOP-..."}]

nblumhardt commented 1 year ago

Only:

{"@t":"2023-01-31T08:32:51.5433322Z","@m":"0","@i":"db5c774a","response":0,"Response":{"Headers":{"X-MiniProfiler-Ids":["[\"cff70dbc-cd79-4c73-a835-e65f2c27eecc\"]"]},"StatusCode":200,"Response":0},"Method":"res: POST /project/update","Context":"api","UserId":"1000","AuthId":"1000","TraceId":"cldk3pjge0002y83j9ot5m8fy","Service":"project","ActionId":"e76a98e8-f944-4d11-8953-e7afd2b9cf7d","ActionName":"Sample.Project.API.Controllers.HomeController.Update (Sample.Project.API)","RequestId":"0HMO3CMUM01M3:00000001","RequestPath":"/project/update","ConnectionId":"0HMO3CMUM01M3","MachineName":"LAPTOP-..."}

seems to have a status code on it, and its request path is /project, so RequestPath like '%/home/%' and StatusCode = 200 won't match it.

I'd recommend switching over to Serilog's request logging with:

https://github.com/serilog/serilog-aspnetcore#request-logging

This condenses all of the per-request events into a single entry, and it carries enough info on it that you should be able to exclude/include it effectively. HTH!

aristotelis79 commented 1 year ago

Thank you very much for your answer and for your suggestion was very helpful.