Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.2.13
    • Fix Version/s: None
    • Component/s: Builds
    • Labels:
      None
    • Environment:
      Microsoft .NET 4.5.1

      Description

      Hello, in our .NET application using Log4Net to log on a Sql Server 2014 database, we set the parameter "ReconnectOnError" to true in the ADO.Net Appender configuration.

      Even if the property seems to be read correctly (as visible on the log), whenever the server is not reachable for a while the appender does not reconnect anymore thus not logging anything else.

      We get the log file attached of a test where we turned off SQL Server for about 1 minute before restarting it.

      Thank you.
      Regards

      1. log4net.txt
        20 kB
        Alessio Sanguineti

        Activity

        Hide
        nachbarslumpi Dominik Psenner added a comment -

        The FAQ entry is a good step forward, can we do something about this in the SendBuffer? I would actually like to drop the checks that fail to detect the disconnection anyway and simply react on exceptions when sending the buffer more or less like how Alessio Sanguineti pointed out in comment https://issues.apache.org/jira/browse/LOG4NET-442?focusedCommentId=14157931&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14157931 .

        Show
        nachbarslumpi Dominik Psenner added a comment - The FAQ entry is a good step forward, can we do something about this in the SendBuffer? I would actually like to drop the checks that fail to detect the disconnection anyway and simply react on exceptions when sending the buffer more or less like how Alessio Sanguineti pointed out in comment https://issues.apache.org/jira/browse/LOG4NET-442?focusedCommentId=14157931&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14157931 .
        Hide
        bodewig Stefan Bodewig added a comment -

        FAQ added with svn revision 1670054

        Show
        bodewig Stefan Bodewig added a comment - FAQ added with svn revision 1670054
        Hide
        bodewig Stefan Bodewig added a comment -

        should we close this as "Won't fix" ("Not a Problem" is not appropriate IMHO) and add an entry to the FAQ?

        Show
        bodewig Stefan Bodewig added a comment - should we close this as "Won't fix" ("Not a Problem" is not appropriate IMHO) and add an entry to the FAQ?
        Hide
        nachbarslumpi Dominik Psenner added a comment - - edited

        I'm afraid this might be a new "feature" of .NET framework 4.5.1:

        http://blogs.msdn.com/b/dotnet/archive/2013/06/26/announcing-the-net-framework-4-5-1-preview.aspx

        ADO.NET connection resiliency is a great answer to these connection scenarios. It is able to re-connect an app to the database and replay session state transparently when an app’s database connection is broken.

        You could try to set ConnectRetryCount to 0 in the ConnectionString according to this source:

        http://msdn.microsoft.com/en-us/library/system.data.sqlclient.sqlconnection.connectionstring%28v=vs.110%29.aspx

        Show
        nachbarslumpi Dominik Psenner added a comment - - edited I'm afraid this might be a new "feature" of .NET framework 4.5.1: http://blogs.msdn.com/b/dotnet/archive/2013/06/26/announcing-the-net-framework-4-5-1-preview.aspx ADO.NET connection resiliency is a great answer to these connection scenarios. It is able to re-connect an app to the database and replay session state transparently when an app’s database connection is broken . You could try to set ConnectRetryCount to 0 in the ConnectionString according to this source: http://msdn.microsoft.com/en-us/library/system.data.sqlclient.sqlconnection.connectionstring%28v=vs.110%29.aspx
        Hide
        asanguineti Alessio Sanguineti added a comment -

        We tried to rebuild our application under .NET framework 3.0 and the logger worked properly.
        It doesn't seem named pipes could be a probem, as we are using TCP connection to the SQL Server.

        Actually, we debugged log4net and discovered, using the 4.5 framework, that as you guessed the SqlConnection state stays "Open" even if the connection is broken, so log4net doen't recognize the problem and doesn't refresh the connection.

        So, at the moment we implemented a workaround so that when an exception is thrown in the SendBuffer portion of the code, a "SELECT 1" query is performed and, if it fails too, the connection is refreshed.

        This way the logger works fine even after disconnection..

        Thank you for your help.
        Regards.

        Show
        asanguineti Alessio Sanguineti added a comment - We tried to rebuild our application under .NET framework 3.0 and the logger worked properly. It doesn't seem named pipes could be a probem, as we are using TCP connection to the SQL Server. Actually, we debugged log4net and discovered, using the 4.5 framework, that as you guessed the SqlConnection state stays "Open" even if the connection is broken, so log4net doen't recognize the problem and doesn't refresh the connection. So, at the moment we implemented a workaround so that when an exception is thrown in the SendBuffer portion of the code, a "SELECT 1" query is performed and, if it fails too, the connection is refreshed. This way the logger works fine even after disconnection.. Thank you for your help. Regards.
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        A little bit of googling brought up this:

        http://social.msdn.microsoft.com/Forums/sqlserver/en-US/c488cf76-2515-440f-b3f8-9cfad689c5b6/named-pipes-provider-error-40-could-not-open-a-connection-to-sql-server?forum=sqldataaccess

        It might be an issue that your client provider uses named pipes to communicate and thus does behave somewhat strange to disconnections. Have you enabled TCP/IP connections on the SQL server?

        Show
        nachbarslumpi Dominik Psenner added a comment - A little bit of googling brought up this: http://social.msdn.microsoft.com/Forums/sqlserver/en-US/c488cf76-2515-440f-b3f8-9cfad689c5b6/named-pipes-provider-error-40-could-not-open-a-connection-to-sql-server?forum=sqldataaccess It might be an issue that your client provider uses named pipes to communicate and thus does behave somewhat strange to disconnections. Have you enabled TCP/IP connections on the SQL server?
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        Alright, can you share the last nights debug log? It would be awesome if you were able to run log4net from source and attach a debugger to see if m_dbConnection.State still reports "Open" even if the connection is lost. My current assumption is that this is an issue of the database connection provider you are using.

        Show
        nachbarslumpi Dominik Psenner added a comment - Alright, can you share the last nights debug log? It would be awesome if you were able to run log4net from source and attach a debugger to see if m_dbConnection.State still reports "Open" even if the connection is lost. My current assumption is that this is an issue of the database connection provider you are using.
        Hide
        asanguineti Alessio Sanguineti added a comment -

        Hello, we tried to do our test again and the result is still the same as before.
        In addition, we made a new test consisting of a loop which logs every second. Then we stopped Sql Server and, after
        a few minutes, restarted it. We left the test application waiting for reconnection the whole night, but this morning still no log was written on the Sql table since when we stopped Sql Server.
        So it doesn't seem a matter of timing.

        Show
        asanguineti Alessio Sanguineti added a comment - Hello, we tried to do our test again and the result is still the same as before. In addition, we made a new test consisting of a loop which logs every second. Then we stopped Sql Server and, after a few minutes, restarted it. We left the test application waiting for reconnection the whole night, but this morning still no log was written on the Sql table since when we stopped Sql Server. So it doesn't seem a matter of timing.
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        From what I can understand out of the log this indicates that the provider did pass the check if it is connected and went straight to the point where it opens a transaction:

        at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction()
        at log4net.Appender.AdoNetAppender.SendBuffer(LoggingEvent[] events)

        Whereas it should reconnect a little earlier if this condition holds:

        if (m_reconnectOnError && (m_dbConnection == null || m_dbConnection.State != ConnectionState.Open))
        {
        LogLog.Debug(declaringType, "Attempting to reconnect to database. Current Connection State: " + ((m_dbConnection==null)?SystemInfo.NullText:m_dbConnection.State.ToString()) );

        Thus it is possible that the connection went away just a jiffy after the check and since there is no other call to SendBuffer() it is not possible to determine if log4net tried to reconnect. Would you please retry your test?

        My best bet at the moment is that the provider tries to handle the disconnection internally and does thus not report the broken connection state at m_dbConnection.State. Can you debug this?

        Please note also that connection timeouts can take quite a long time (even more than a few minutes) and thus you may have to send log events for quite a long time before log4net gets a turn to finish the previous SendBuffer and do the next call to SendBuffer.

        Show
        nachbarslumpi Dominik Psenner added a comment - From what I can understand out of the log this indicates that the provider did pass the check if it is connected and went straight to the point where it opens a transaction: at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction() at log4net.Appender.AdoNetAppender.SendBuffer(LoggingEvent[] events) Whereas it should reconnect a little earlier if this condition holds: if (m_reconnectOnError && (m_dbConnection == null || m_dbConnection.State != ConnectionState.Open)) { LogLog.Debug(declaringType, "Attempting to reconnect to database. Current Connection State: " + ((m_dbConnection==null)?SystemInfo.NullText:m_dbConnection.State.ToString()) ); Thus it is possible that the connection went away just a jiffy after the check and since there is no other call to SendBuffer() it is not possible to determine if log4net tried to reconnect. Would you please retry your test? My best bet at the moment is that the provider tries to handle the disconnection internally and does thus not report the broken connection state at m_dbConnection.State. Can you debug this? Please note also that connection timeouts can take quite a long time (even more than a few minutes) and thus you may have to send log events for quite a long time before log4net gets a turn to finish the previous SendBuffer and do the next call to SendBuffer.
        Hide
        asanguineti Alessio Sanguineti added a comment -

        yes, new events were sent to the logger but they were somehow discarded (not written).

        We also waited some minutes after the server restart, but no writing on the DB happened

        Show
        asanguineti Alessio Sanguineti added a comment - yes, new events were sent to the logger but they were somehow discarded (not written). We also waited some minutes after the server restart, but no writing on the DB happened
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        The appender failed to connect to the sql server when trying to send the buffer. I would expect the appender to discard the events and only retry to connect when the next events come in. So the question is: have you "created" some log events after that the server was turned on again and was running successfully? Powering the server up might take some time and you will have to consider to wait for that time to pass by.

        Show
        nachbarslumpi Dominik Psenner added a comment - The appender failed to connect to the sql server when trying to send the buffer. I would expect the appender to discard the events and only retry to connect when the next events come in. So the question is: have you "created" some log events after that the server was turned on again and was running successfully? Powering the server up might take some time and you will have to consider to wait for that time to pass by.
        Hide
        asanguineti Alessio Sanguineti added a comment -

        Log file

        Show
        asanguineti Alessio Sanguineti added a comment - Log file

          People

          • Assignee:
            Unassigned
            Reporter:
            asanguineti Alessio Sanguineti
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:

              Development