Question Why not errors written to DB?

[raysefo]

Hello,

I have unhandled exception logger which logs every error into a table. Actually, it works but there is a rare condition when I do a load test with more than 1000 users, errors aren't written into this table. (950 success, 50 errors) Why could this happen? Any ideas? 50 users didn't even start for some reason?

public class UnhandledExceptionLogger : ExceptionLogger
    {
        public override void Log(ExceptionLoggerContext context)
        {
            var ex = context.Exception;

            string strLogText = "";
            strLogText += Environment.NewLine + "Source ---\n{0}" + ex.Source;
            strLogText += Environment.NewLine + "StackTrace ---\n{0}" + ex.StackTrace;
            strLogText += Environment.NewLine + "TargetSite ---\n{0}" + ex.TargetSite;

            if (ex.InnerException != null)
            {
                strLogText += Environment.NewLine + "Inner Exception is {0}" + ex.InnerException;//error prone
            }
            if (ex.Message != null)
            {
                strLogText += Environment.NewLine + "Message ---\n{0}" + ex.Message;//error prone
            }

            var requestedURi = (string)context.Request.RequestUri.AbsoluteUri;
            var requestMethod = context.Request.Method.ToString();
            var timeUtc = DateTime.Now;

            SqlErrorLogging sqlErrorLogging = new SqlErrorLogging();
            ApiError apiError = new ApiError()
            {
                Message = strLogText,
                RequestUri = requestedURi,
                RequestMethod = requestMethod,
                TimeUtc = DateTime.Now
            };
            sqlErrorLogging.InsertErrorLog(apiError);
        }
    }

public void InsertErrorLog(ApiError apiError)
        {
            using (var sqlConnection =
                new SqlConnection(ConfigurationManager.ConnectionStrings["GameContext"].ConnectionString))
            {
                try
                {
                    sqlConnection.Open();
                    using (SqlCommand cmd =
                        new SqlCommand(
                            "INSERT INTO [dbo].[API_Error] ([Message],[RequestMethod],[RequestUri],[TimeUtc]) VALUES (@Message, @RequestMethod, @RequestUri, @TimeUtc)",
                            sqlConnection))
                    {
                        cmd.Parameters.AddWithValue("@TimeUtc", apiError.TimeUtc);
                        cmd.Parameters.AddWithValue("@RequestUri", apiError.RequestUri);
                        cmd.Parameters.AddWithValue("@Message", apiError.Message);
                        cmd.Parameters.AddWithValue("@RequestMethod", apiError.RequestMethod);

                        cmd.ExecuteNonQuery();
                    }
                }
                catch (Exception e)
                {
                    throw e;
                }
                finally
                {
                    sqlConnection.Close();
                }
            }
        }

 

[jmcilhinney]

If you want to rethrow an exception in a catch block then you should just use throw rather than throw e because the latter will truncate the stack trace to the current method. Also, if you have a finally block then you aren't required to have a catch block, so having one that simply rethrows an exception is pointless.

Also, there's no need to nest multiple using blocks unless you specifically require code between them, which you don't in this case. You could do this:

using (var connection = new SqlConnection("..."))
using (var command = new SqlCommand("...", connection))
{
    // ...
   
    connection.Open();
    command.ExecuteNonQuery();
}

The fact that you are creating the SqlConnection with a using statement means that closing the connection is pointless. It will be closed implicitly when it is disposed at the end of the block.

As for the issue, you should add some Debug.WriteLine calls to your try and catch blocks. You can log the result of ExecuteNonQuery and whether any exception was thrown, which will tell you exactly how many records should have been inserted.

 

[Skydiver]

I doubt this is doing what you really want it to do:

strLogText += Environment.NewLine + "Source ---\n{0}" + ex.Source;

If ex.Source were "The End Of The World", you resulting string would look like: "\r\nSource ---\n{0}The End Of The World".

I think that the result you wanted was something like: "\r\nSource ---\nThe End Of The World" without the "{0}" stuck in there. You could use string interpolation to get that:

strLogText += Environment.NewLine + $"Source ---\n{ex.Source}" + ex.Source;

I also don't think you want the leading line break there as well as the embedded newline there. I recommend using a StringBuilder as well as some string interpolation So all of that above could be something like:

string FormatException(Exception ex, int depth = 0)
{
    string indent = ""
    if (depth > 0)
        indent.PadRight(depth * 4);

    var sb = new StringBuilder();
    IndentLine($"Source --- {ex.Source}");
    IndentLine($"StackTrace --- {ex.StackTrace}");
    IndentLine($"TargetSite --- {ex.TargetSite}");

    if (ex.InnerException != null)
    {
        IndentLine("--- Inner Exception ---");
        sb.Append(FormatException(ex.InnerException, depth + 1));
        IndentLine("--- End Inner Exception ---");
    }
    if (ex.Message != null)
    {
        IndentLine($"Message --- {ex.Message}");
    }
    return sb.ToString();

    void IndentLine(string s)
    {
        sb.Append(indent);
        sb.AppendLine(s);
    }
}

:

string strLogText = FormatException(ex);

 

[raysefo]

Thank you @jmcilhinney and @Skydiver, I will make the changes but I think I couldn't explain my issue clearly. What I am trying to say is, this happens only when trying to load testing. I see errors on the Jmeter but there is no error in the DB table.

 

[Skydiver]

What are the exact errors that JMeter is reporting? Are they error 500's? Are they error 503's?

If you are running on IIS, you can try looking at the Windows Event log to see if any connections attempts are being rejected. You can also look in the Logs directory for IIS to see if the connections even made it in.

If the connection attempt doesn't even make it to your application, then there is nothing to log within your application since that logger you have above is presumably only for when you catch an exception within your code.

Is this the same code base you've been posting about over the past few weeks where you used to exhaust the SQL connection pool? Perhaps you couldn't even open a connection to write to your database?

I have a web service running on IIS that easily handles 5000 sessions/transactions per second, so personally I don't think you are pushing IIS to the limits yet with just 1000 users. Perhaps you are keeping all the IIS threads busy and so it can't accept more sessions?

 

[raysefo]

Is this the same code base you've been posting about over the past few weeks where you used to exhaust the SQL connection pool? Perhaps you couldn't even open a connection to write to your database?

I think you are right. My application can handle 600 users but after 600 it gets some errors which are due to exhausted SQL connections I guess.

 

[NoUserHere]

Nesting using blocks is not necessary, but its not a bad habit to apply using blocks where possible.

Since your connection will be the first and last object in use, you would wrap that in using blocks and put your command inside the using statement to be consumed with it. Since your command will execute after your connection becomes used, there is no need to wrap that in a using statement too. And since you're using try blocks, you should also read up on using statements with try blocks - this opens up a whole new debate of structuring your code properly. I'd advise reading that link thoroughly including all the comments before going forward.

Once you understand the use of these statements, you should rethink and restructure your code slightly to follow best practice where you consider using both blocks. Essential reading on the finally block is important too, as the functionality of this block works similarly to IDisposable from using statements. Note : if a CLR is under illusion that further executions will result in more exceptions, it will not call for the execution of a dispose method because it will not execute that try-finally block which a dispose method is compiled and compelled to execute, and that is also explained in the MSDN docs I've linked you.

 

[raysefo]

Thank you @Sheepings and @Skydiver. I checked the IIS logs under inetpub. I can see the error logs there. And I also checked the C:\Windows\System32\LogFiles\HTTPERR logs. There are also errors.

inetpub sample log:

2019-08-09 20:19:48 11.1.11.1 POST /api/v2/game/purchase - 1907 - 11.11.111.111 Apache-HttpClient/4.5.7+(Java/1.8.0_191) - 500 0 0 155468

HTTPERR log:

2019-08-08 18:05:06 99.99.999.999 59334 11.1.11.1 1907 HTTP/1.1 POST /api/v2/game/purchase - 3 Connection_Dropped_List_Full EPIN
2019-08-08 18:05:46 99.99.999.999 59801 11.1.11.1 1907 HTTP/1.1 POST /api/v2/game/purchase - 3 Request_Cancelled EPIN

 

[Skydiver]

"Connection_Dropped_List_Full" and "Request_Cancelled" would suggest to me that JMeter can't even connect to your app, and not that you app is throwing an exception while processing a request. The HTTP error 500 also suggests to me that the application is crashing or not running which maybe in line with the dropped connections.

 

[raysefo]

I doubt this is doing what you really want it to do:

strLogText += Environment.NewLine + "Source ---\n{0}" + ex.Source;

If ex.Source were "The End Of The World", you resulting string would look like: "\r\nSource ---\n{0}The End Of The World".

I think that the result you wanted was something like: "\r\nSource ---\nThe End Of The World" without the "{0}" stuck in there. You could use string interpolation to get that:

strLogText += Environment.NewLine + $"Source ---\n{ex.Source}" + ex.Source;

I also don't think you want the leading line break there as well as the embedded newline there. I recommend using a StringBuilder as well as some string interpolation So all of that above could be something like:

string FormatException(Exception ex, int depth = 0)
{
    string indent = ""
    if (depth > 0)
        indent.PadRight(depth * 4);

    var sb = new StringBuilder();
    IndentLine($"Source --- {ex.Source}");
    IndentLine($"StackTrace --- {ex.StackTrace}");
    IndentLine($"TargetSite --- {ex.TargetSite}");

    if (ex.InnerException != null)
    {
        IndentLine("--- Inner Exception ---");
        sb.Append(FormatException(ex.InnerException, depth + 1));
        IndentLine("--- End Inner Exception ---");
    }
    if (ex.Message != null)
    {
        IndentLine($"Message --- {ex.Message}");
    }
    return sb.ToString();

    void IndentLine(string s)
    {
        sb.Append(indent);
        sb.AppendLine(s);
    }
}

:

string strLogText = FormatException(ex);

@Skydiver VS 2015 community edition says can not use local variable 'IndentLine' before it is declared. Any library missing?

 

[Skydiver]

Sorry, I was using a C# 7.0 feature. This should work with C# 6.0:

string FormatException(Exception ex, int depth = 0)
{
    string indent = ""
    if (depth > 0)
        indent.PadRight(depth * 4);

    var sb = new StringBuilder();
    sb.AppendLine($"{indent}Source --- {ex.Source}");
    sb.AppendLine($"{indent}StackTrace --- {ex.StackTrace}");
    sb.AppendLine($"{indent}TargetSite --- {ex.TargetSite}");

    if (ex.InnerException != null)
    {
        sb.AppendLine("{indent}--- Inner Exception ---");
        sb.Append(FormatException(ex.InnerException, depth + 1));
        sb.AppendLine("{indent}--- End Inner Exception ---");
    }
    if (ex.Message != null)
    {
        sb.AppendLine($"{indent}Message --- {ex.Message}");
    }
    return sb.ToString();
}

 

[raysefo]

Sorry, this is off the topic but I wonder does this quickly eat connection pool? Should I change it to a Task (rather than void) and added an await ?

 public void IncomingMessageAsync(ApiLog apiLog)
        {
            apiLog.RequestType = "Request";
            var sqlErrorLogging = new ApiLogging();
            sqlErrorLogging.InsertLog(apiLog);
        }

        public void OutgoingMessageAsync(ApiLog apiLog)
        {
            apiLog.RequestType = "Response";
            var sqlErrorLogging = new ApiLogging();
            sqlErrorLogging.InsertLog(apiLog);
        }

 

[Skydiver]

What does the class ApiLogging do with regards to connections? Is the implementation of ApiLogging.InsertLog() exact to the implementation of your InsertErrorLog() in your post #1 above? Please share the code for ApiLogging.

 

[raysefo]

here is the ApiLogging.

public class ApiLogging
    {
        public void InsertLog(ApiLog apiLog)
        {
            try
            {
                using (var sqlConnection =
                    new SqlConnection(ConfigurationManager.ConnectionStrings["GameContext"].ConnectionString))
                {
                    using (SqlCommand cmd = new SqlCommand(
                        "INSERT INTO [dbo].[API_Log] ([Host],[Headers],[StatusCode],[TimeUtc],[RequestBody],[RequestedMethod],[UserHostAddress],[Useragent],[AbsoluteUri],[RequestType])    VALUES (@Host,@Headers,@StatusCode,getdate(),@RequestBody,@RequestedMethod,@UserHostAddress,@Useragent,@AbsoluteUri,@RequestType)",
                        sqlConnection))
                    {
                        sqlConnection.Open();
                        cmd.Parameters.AddWithValue("@Host", apiLog.Host);
                        cmd.Parameters.AddWithValue("@Headers", apiLog.Headers);
                        cmd.Parameters.AddWithValue("@StatusCode", apiLog.StatusCode);
                        cmd.Parameters.AddWithValue("@RequestBody", apiLog.RequestBody);
                        cmd.Parameters.AddWithValue("@RequestedMethod", apiLog.RequestedMethod);
                        cmd.Parameters.AddWithValue("@UserHostAddress", apiLog.UserHostAddress);
                        cmd.Parameters.AddWithValue("@Useragent", apiLog.Useragent);
                        cmd.Parameters.AddWithValue("@AbsoluteUri", apiLog.AbsoluteUri);
                        cmd.Parameters.AddWithValue("@RequestType", apiLog.RequestType);
                        cmd.ExecuteNonQuery();
                    }
                }
            }
            catch (Exception e)
            {
                Console.WriteLine(e);
                throw;
            }
        }
    }

 

[Skydiver]

That code there looks like it cleanly releases connections.