requests hanging on aspnet webapplication

[mapperr]

Hi everyone,

we have a problem on our aspnet webapplication, in which we use mongodb only from the log4net mongodb appender.

if our instance of mongodb goes down (for whatever cause), the requests to our webapplication start to hang. if the mongodb instance goes up again, then the pending requests are fullfilled.

It's like the logging elaboration is on the request's thread, so if the appender cannot communicate with the mongodb instance, then the entire request waits (until a network timeout occurs).

Is that hypotesis correct?
If that's the case we would like to ask if it's possible to make the appender sort of "non-blocking": if there are problems with mongodb communication, the requests continue to be fullfilled.

That's the appender configuration from our web.config:

<configuration>

  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,  log4net"/>
  </configSections>

  <log4net>

    <appender name="SessionAppender" type="Log4Mongo.MongoDBAppender, Log4Mongo">
      <connectionString value="mongodb://username:password@host/DatabaseName" />
      <collectionName value="Session" />

      <field>
        <name value="App" />
        <layout type="log4net.Layout.PatternLayout" value="%property{App}" />
      </field>

      <!-- ... other fields ... -->


      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="SESSION" />
        <levelMax value="SESSION" />
      </filter>
    </appender>

    <appender name="AuditAppender" type="Log4Mongo.MongoDBAppender, Log4Mongo">
      <connectionString value="mongodb://username:password@host/DatabaseName" />
      <collectionName value="Audit" />

      <field>
        <name value="App" />
        <layout type="log4net.Layout.PatternLayout" value="%property{App}" />
      </field>

      <!-- ... other fields ... -->

      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="REQUEST" />
        <levelMax value="RESPONSE" />
      </filter>
    </appender>

    <appender name="TraceAppender" type="Log4Mongo.MongoDBAppender, Log4Mongo">
      <connectionString value="mongodb://username:password@host/DatabaseName" />
      <collectionName value="Trace" />

      <field>
        <name value="App" />
        <layout type="log4net.Layout.PatternLayout" value="%property{App}" />
      </field>

      <!-- ... other fields ... -->

      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="DEBUG" />
      </filter>
    </appender>

  <appender name="SessionForwardingAppender"
        type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="100"/>
    <appender-ref ref="SessionAppender" /> <!-- already defined -->
  </appender> 
  <appender name="AuditForwardingAppender"
        type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="100"/>
    <appender-ref ref="AuditAppender" /> <!-- already defined -->
  </appender> 
  <appender name="TraceForwardingAppender"
        type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="100"/>
    <appender-ref ref="TraceAppender" /> <!-- already defined -->
  </appender> 



    <level>
      <name value="SESSION" />
      <value value="1" />
    </level>
    <level>
      <name value="REQUEST" />
      <value value="2" />
    </level>
    <level>
      <name value="RESPONSE" />
      <value value="3" />
    </level>

    <level>
      <name value="SQL" />
      <value value="50000" />
    </level>

    <root>
      <level value="ALL" />
      <appender-ref ref="SessionForwardingAppender" />
      <appender-ref ref="AuditForwardingAppender" />
      <appender-ref ref="TraceForwardingAppender" />
    </root>
  </log4net>
</configuration>

[emadb]

Hi @mapperr I think you are right. The method that checks if the collection to log to exists is still synchronous and it waits (for 30 sec) before failing.
You can see the code here: MongoDBAppender.cs
I mark this as a bug and as soon as we have some time we try to fix it.
Thanks

[emadb]

HI @mapperr I was thinking about the problem that you have reported to us but I can't imagine an elegant solution. If the database is down, it's quite normal that the logger tries for 30 seconds to connect to the database. In your opinion what would be the correct behaviour?

[gimmi]

Hi Emanuele,

in the log4net FAQ https://logging.apache.org/log4net/release/faq.html is
reported that "log4net is not reliable. It is a best-effort and fail-stop
logging system.". I think that hanging an application for long (or even
short) time is not in the spirit of log4net, maybe would be better to don't
log anyting if the configured collection does not exist, instead of trying
to create it.

Gian Marco Gherardi
http://gianmarco.gherardi.me

On Wed, Feb 17, 2016 at 9:26 PM, Emanuele DelBono [email protected]
wrote:

HI @mapperr https://github.com/mapperr I was thinking about the problem
that you have reported to us but I can't imagine an elegant solution. If
the database is down, it's quite normal that the logger tries for 30
seconds to connect to the database. In your opinion what would be the
correct behaviour?

—
Reply to this email directly or view it on GitHub
#35 (comment)
.

[serenata-evaldas]

Hey, not sure if it's a covincidence but after I did some performance/fallback test also found this issue. The only alternative I can suggest right no is to add shorter timeouts in the connection string, like for 1s, e.g.:?waitQueueTimeoutMS=1000&socketTimeoutMS=1000&connectTimeoutMS=1000&serverSelectionTimeoutMS=1000

otherwise you'll need to override the appender and implement non blocking async tasks or something.

[seanfitzg]

I had a similar problem in application in the past. We were noticing that calls to our API were taking 30 seconds to complete. It was only by analysing the network traffic that we were able to find out that it was caused by us logging to a server that was not running.

I had a quick try at using Task.Factory.StartNew( () => ..) to append to the logs but we'd have to rethink the unit tests. There is a Mongo command called serverStatus that may be able to help, but unfortunately it's not supported by the C# driver.