One thing that you learn as you rise in your career as a software developer is that good logging is very important. I had a great experience of why writing out as much data as you can is important.

A client of ours has been load testing our application before their production pilot. During the load test I noticed in our single sign on routine that we were getting primary key errors on role insertion. Being that this was one of the first things I had worked on early in my career, I had not done any duplicate checking on the roles. After fixing that, we received the results of the second round of testing. We were still getting duplicate errors! I frantically and frustratingly went back an retested my logic over and over again. Not once would it try to insert a duplicate.

Finally after combing the logs I noticed one tiny discrepancy between the logging lines where the duplicate role was trying to be inserted. The process ID was the same, but the Thread ID was different. Because we are calling an external service before the insertion, we have a thread collision occurring and trying to insert the same user in two separate threads. Granted this is mostly due to the fact that there are only a few user id’s being used during the load testing, it still can be something that can be seen in production.

Had we not logged this out, I’d still be beating my head against a wall to try to figure it out. Now to come up with a bulletproof solution for the thread collision problem.