I can't get log4net filtering to work - seems to be ignoring Level and filter settings

139 views Asked by At

I'm currently getting reacquainted with log4Net configuration after a few years of it "just working", and I'm running into an issue while working in Visual Studio 2019 with ASP.NET Core. Any help figuring this out would be appreciated.

I have the following filter and level settings, but my log file STILL ends up with all the "Cahtter" that goes in the debug window of the IDE. As you can see, I've set the level to "INFO" and above, and also tried to filter out "noise" containing "Microsoft.AspNetCore" but no luck. I've researched how to do filtering and THINK I've done it right, but it's not filtering ANYTHING.

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="DebugAppender" type="log4net.Appender.DebugAppender" >
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
    </layout>
  </appender>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="SDPerf.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date %5level %logger.%method [%line] - MESSAGE: %message%newline %exception" />
    </layout>
    <filter type="log4net.Filter.StringMatchFilter">
      <stringToMatch value="Microsoft.AspNetCore"/>
      <acceptOnMatch value="false"/>
    </filter>
  </appender>
  <root>
    <level value="INFO"/>
    <appender-ref ref="DebugAppender" />
    <appender-ref ref="RollingFile" />
  </root>
</log4net>

and here's a snip from the log file:

 2021-05-21 15:50:01,744  INFO Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.? [?] - MESSAGE: Executing action method LongRunningTask.Controllers.HomeController.Test2 (LongRunningTask) - Validation state: Valid
 2021-05-21 15:50:01,754  INFO Microsoft.AspNetCore.Mvc.ViewFeatures.PartialViewResultExecutor.? [?] - MESSAGE: Executing PartialViewResult, running view Jobs.
 2021-05-21 15:50:01,762  INFO Microsoft.AspNetCore.Mvc.ViewFeatures.PartialViewResultExecutor.? [?] - MESSAGE: Executed PartialViewResult - view Jobs executed in 7.4295ms.
 2021-05-21 15:50:01,768  INFO Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.? [?] - MESSAGE: Executed action LongRunningTask.Controllers.HomeController.Test2 (LongRunningTask) in 43.365ms
 2021-05-21 15:50:01,772  INFO Microsoft.AspNetCore.Routing.EndpointMiddleware.? [?] - MESSAGE: Executed endpoint 'LongRunningTask.Controllers.HomeController.Test2 (LongRunningTask)'
 2021-05-21 15:50:01,776  INFO Microsoft.AspNetCore.Hosting.Diagnostics.? [?] - MESSAGE: Request finished in 71.9539ms 200 text/html; charset=utf-8
 2021-05-21 15:50:03,561  INFO Microsoft.AspNetCore.Hosting.Diagnostics.? [?] - MESSAGE: Request starting HTTP/2.0 GET https://localhost:44345/Home/ProcessJob  
 2021-05-21 15:50:03,567  INFO Microsoft.AspNetCore.Routing.EndpointMiddleware.? [?] - MESSAGE: Executing endpoint 'LongRunningTask.Controllers.HomeController.ProcessJob (LongRunningTask)'
 2021-05-21 15:50:03,588  INFO Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.? [?] - MESSAGE: Executing action method LongRunningTask.Controllers.HomeController.ProcessJob (LongRunningTask) - Validation state: Valid
 2021-05-21 15:50:03,592  INFO SDPerf..ctor [24] - MESSAGE: Starting Task calls
 2021-05-21 15:50:03,602  INFO SDPerf.NewMethod [51] - MESSAGE: Starting iterations for method '2'
 2021-05-21 15:50:03,606  INFO SDPerf.NewMethod [51] - MESSAGE: Starting iterations for method '3'
 2021-05-21 15:50:03,612  INFO SDPerf.NewMethod [51] - MESSAGE: Starting iterations for method '1'
 2021-05-21 15:50:03,619  INFO Microsoft.AspNetCore.Mvc.RedirectToActionResult.? [?] - MESSAGE: Executing RedirectResult, redirecting to /Home/ShowJobProgress?requestId=7b1a8cf8-641f-4599-a90f-748707f4ed63.
 2021-05-21 15:50:03,621  INFO Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.? [?] - MESSAGE: Executed action LongRunningTask.Controllers.HomeController.ProcessJob (LongRunningTask) in 44.8757ms
 2021-05-21 15:50:03,624  INFO Microsoft.AspNetCore.Routing.EndpointMiddleware.? [?] - MESSAGE: Executed endpoint 'LongRunningTask.Controllers.HomeController.ProcessJob (LongRunningTask)'
 2021-05-21 15:50:03,627  INFO Microsoft.AspNetCore.Hosting.Diagnostics.? [
1

There are 1 answers

0
bregia On BEST ANSWER

Finally solved this by trial and error. While I couldn't find ANY example to help me figure it out, I discovered that the "StringMatchFilter" method only works on the original text of the message, NOT the entire line being logged.