Wednesday, November 22, 2017

Log Unexpected Switch Options

There are many things a Java developer can do to make his or her own life and the lives of others maintaining that code easier. In this post, I'm going to look at a very easy approach a developer can take to make things easier for everyone. The point of this post will likely seem obvious to everyone reading it, but I see this not done far more often than I would have expected. In short, developers should typically log the value they are switch-ing on when that value is not represented by any of the explicit case statements within that switch.

Before moving to specifics, I will add a few caveats. There are times when it may not make sense to log the value being switch-ed on that was not explicitly matched to a case. Some of these are listed here.

  • The value being switched on is sensitive and should not be logged for security reasons.
  • The value being switched on has numerous cases in which no match is expected and so the developer doesn't want to log unnecessarily.
  • A default can be provided that will always work well for any values that don't have matching case blocks (this seems rare).

In the cases I've seen that are the cause of this being one of my main pet peeves, none of the above caveats applied. In fact, in most of these cases, the developer has provided a logged message in the default block warning that the value was unexpected, but that same developer has failed to provide the candidate value that was not matched. A contrived example of this is shown in the next code listing.

Enum default That Logs Without switch Candidate Value

/**
 * Provides the Roman numeral equivalent of the
 * provided integer.
 * 
 * @param integer Integer for which Roman numeral
 *    equivalent is desired.
 * @return Roman numeral equivalent of the provided
 *    integer or empty string ("") if I'm not aware of
 *    the Roman numeral equivalent.
 */
public String getRomanNumeralEquivalent(final int integer)
{
   String romanNumeral;
   switch (integer)
   {
      case 0:
         romanNumeral = "nulla";
         break;
      case 1:
         romanNumeral = "I";
         break;
      case 2:
         romanNumeral = "II";
         break;
      case 3:
         romanNumeral = "III";
         break;
      case 4:
         romanNumeral = "IV";
         break;
      case 5:
         romanNumeral = "V";
         break;
      case 6:
         romanNumeral = "VI";
         break;
      case 7:
         romanNumeral = "VII";
         break;
      case 8:
         romanNumeral = "VIII";
         break;
      case 9:
         romanNumeral = "IX";
         break;
      case 10:
         romanNumeral = "X";
         break;
      default:
         out.println("Unexpected integer was provided.");
         romanNumeral = "";
         break;
   }
   return romanNumeral;
}

The issue here is really a specific example of a more general issue developers should avoid: logging without sufficient context. In some cases, it might be difficult or computationally expensive to provide the type of context that makes log messages more useful. That's typically not the case with switch statements, however, where we can easily log the value that we were trying to switch on. In the above code listing, developers supporting runtime issues in deployment will only be told that an "Unexpected integer was provided." Without any context, it's difficult to know what that provided integer was and, without knowing the candidate integer, it's difficult to trace what happened or even reproduce it.

Only very small effort is required to make this default logging statement useful and this is shown in the next code listing.

Constructing a Better default Log Statement

default:
   out.println("Unexpected integer (" + integer
      + ") was provided, so empty String being returned for Roman Numeral.");
   romanNumeral = "";

The "enhanced" log message indicates which integer was being switched on and adds what is being returned because of that not being an expected integer. The second part is not as necessary for the developer because the static code will show the developer what is returned in that "default" case. However, the logging of the integer that was being switched on is highly valuable because there's no good way to access this information later unless a different log message somewhere else made it clear that's what was being switched on.

I have been the victim numerous times of developers not providing this simple context. It has made what would have likely been an easy diagnosis much more difficult. In extreme cases, I've had to add this context to the log message and wait for it to be encountered again. Had the developer added that simple context information at the time of writing of the code, the issue could have been resolved much more readily.

I like to take this concept a little further when writing my own switch statements. I typically add a default block even when my switch covers all possible (current) cases explicitly. This default block is unnecessary at the time of writing and will "never be called," but I add it to future-proof the switch statement (unit tests can be used to implement similar protections). I add the logging of the unexpected candidate value provided to the switch statement so that if another case is added "upstream" in the code, my switch will quickly tell me when it runs into an unexpected value and tell me what that unexpected value is.

It often turns out that having a candidate value for a switch statement without matching case is an exceptional circumstance. In such cases, it's likely more appropriate to thrown an exception than to simply log the exceptional situation. A standard exception such as IllegalArgumentException works well for this (it is, in a way, an illegal argument to the switch statement), but I have occasionally also written a custom exception to help with this. When I've decided to implement and use this custom exception, part of the reason for making that decision is that throwing of that exception encourages developers to provide the object being switched upon as part of the exception's constructor. A representative example of this type of custom exception is shown next (source code is also available on GitHub).

SwitchOptionNotExpectedException.java

package dustin.utilities.exceptions;

/**
 * Exception used to communicate a candidate value for
 * a {@code switch} statement not being matched by any
 * of the explicitly provided {@code case} blocks.
 */
public class SwitchOptionNotExpectedException extends RuntimeException
{
   /**
    * Object being switched on for which no matching
    * {@code case} clause existed.
    */
   private final Object switchedObject;

   /**
    * Constructor accepting exception message and the instance
    * upon which the {@code switch} was being attempted when no
    * matching {@code case} was found.
    *
    * @param newMessage Exception summary message.
    * @param newSwitchedObject Object being switched on for
    *    which there was no explicitly specifed {@code case}.
    */
   public SwitchOptionNotExpectedException(
      final String newMessage, final Object newSwitchedObject)
   {
      super(newMessage + " (unable to switch on '" + String.valueOf(newSwitchedObject) + "')");
      switchedObject = newSwitchedObject;
   }

   /**
    * Constructor accepting the instance upon which the {@code switch}
    * was being attempted when no matching {@code case} was found.
    *
    * @param newSwitchedObject Object being switched on for
    *    which there was no explicitly specified {@code case}.
    */
   public SwitchOptionNotExpectedException(final Object newSwitchedObject)
   {
      super(
           "Switch statement did not expect '" + String.valueOf(newSwitchedObject)
         + "'.");
      switchedObject = newSwitchedObject;
   }

   /**
    * Provides String representation of the object being
    * switched upon.
    *
    * @return String representation of the object being
    *    switched upon.
    */
   public String getSwitchedObjectString()
   {
      return String.valueOf(switchedObject);
   }

   /**
    * Provides type of object being switched upon.
    *
    * @return Type of the object being switched upon or
    *    {@code null} if that switched upon object is null.
    */
   public Class getSwitchedObjectType()
   {
      return switchedObject != null ? switchedObject.getClass() : null;
   }
}

Whether the developer is simply logging the switch candidate not being found or throws an exception is response to that, the value being switched on should typically be logged or included in the exception to make it easier to diagnose the issue. The custom exception above will provide that message automatically regardless of the constructor used as long as the developer provides the switched-on object. A developer would have to go out of his or her way to not provide that object in this case rather than simply neglecting or forgetting to include it.

After ruling out cases where it's not appropriate to log or write out the value being switched on that has no match, the mostly likely reason a developer fails to indicate the value is simply not thinking about it. It can be "obvious" to the developer at time of writing the code that any unexpected case "will never happen" or that it would be obvious what the value was if it did happen. Another likely reason for not including context in these types of messages (or any log messages for that matter) is being rushed or being lazy. A developer might know that it would be best to provide these details, but doesn't want to take the time to do it. It's this latter reason that sometimes encourages me to write a custom exception like that shown above.

Debugging and maintaining production software is a valuable experience for developers because it helps them to better understand how their actions (or lack thereof) make others' jobs more difficult in the future. In general, the conscientious developer can help others (and possibly himself or herself) by providing context information in logged messages, especially for warning, error, and exception conditions. In particular, adding the context of what value was being switch-ed on when no match is found is easy to do and could save yourself, other developers, and customers quite a bit of time in the future.

No comments: