Making REST Calls Retryable in Biking Weather Suitability Forecast Application

One frustration I had noticed with my Biking Weather Suitability Forecast Application was that I found it often would not show results until I reloaded the page, and a look at the application logs showed that the REST calls to one of the APIs called had failed or timed out. After doing some research into using Spring’s Retryable options for methods, I decided to make the DailyReportCollectionService method getCurrentDailyReports() retryable, so that it would be attempted a second time after a one second pause if the first try didn’t succeed in returning complete data, with a third and final attempt made as the “Recover” option.

First, I added the following two required dependencies to the dependencies section of the application’s pom.xml file.

        <dependency>
            <groupId>org.springframework.retry</groupId>
            <artifactId>spring-retry</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-aspects</artifactId>
        </dependency>

I needed to add a new Exception, IncompleteForecastException, which would trigger retries of the failed method call. I created a new “exception” package, with the following package-info.java to document the package.

/**
 * Package containing custom Exceptions for biking weather application.
 */
package biz.noip.johnwatne.bikingweather.exception;

The IncompleteForecastException class is a very simple extension of the Exception class, with the following code.

package biz.noip.johnwatne.bikingweather.exception;

/**
 * Exception thrown if the forecast information returned has either less than
 * seven days' data, or missing sunrise or sunset information.
 *
 * @author John Watne
 *
 */
public class IncompleteForecastException extends Exception {
    private static final long serialVersionUID = 1L;

    public IncompleteForecastException(final String message) {
        super(message);
    }
}

I then made the changes required to have the retryable code in DailyReportCollectionService. Since the existing getCurrentDailyReports() needed to be executed both as the standard Retryable code and as the Recovery code, it’s logic was moved to a new private method, appropriately named getRetryableCurrentDailyReports(), starting as follows.

    /**
     * The shared code of {@link #getCurrentDailyReports()} and
     * {@link #getFInalCurrentDailyReports(IncompleteForecastException)}.
     *
     * @return the latest {@link DailyReportCollection}.
     */
    private DailyReportCollection getRetryableCurrentDailyReports() {
.
.
.
.

I added a couple String constants for possible error return values passed on from getRetryableCurrentDailyReports().

    private static final String MISSING_SUNSET_DATA_FOR_TIME =
            "Missing sunset data for time ";
    private static final String MISSING_SUNRISE_DATA_FOR_TIME =
            "Missing sunrise data for time ";
    private static final String MISSING_FORECAST_DATA = "Missing forecast data";
    private static final String NO_DAILY_REPORT_COLLECTION_OBTAINED =
            "No DailyReportCollection obtained";

The existing getCurrentDailyReports() method was revised to be a Retryable caller of the extracted getRetryableCurrentDailyReports(), throwing an IncompleteForecastException with one of the above messages when needed.

    /**
     * Makes calls to get and return the latest {@link DailyReportCollection}.
     * If forecast data is incomplete, throw an
     * {@link IncompleteForecastException} and attempt again in a second.
     *
     * @return the latest {@link DailyReportCollection}.
     * @throws IncompleteForecastException
     *             if the DailyReportCollection to be returned is incomplete.
     */
    @Retryable(value = {IncompleteForecastException.class}, maxAttempts = 2,
            backoff = @Backoff(delay = 1000))
    public DailyReportCollection getCurrentDailyReports()
            throws IncompleteForecastException {
        final DailyReportCollection reports = getRetryableCurrentDailyReports();

        if (reports == null) {
            LOGGER.warn(NO_DAILY_REPORT_COLLECTION_OBTAINED);
            throw new IncompleteForecastException(
                    NO_DAILY_REPORT_COLLECTION_OBTAINED);
        } else {
            final SortedMap<Long,
                    DailyAndHourlySuitabilityForDay> dailyReports =
                            reports.getDailyReports();

            if (dailyReports.size() < 7) {
                LOGGER.warn(MISSING_FORECAST_DATA);
                throw new IncompleteForecastException(MISSING_FORECAST_DATA);
            }

            for (Entry<Long,
                    DailyAndHourlySuitabilityForDay> entry : dailyReports
                            .entrySet()) {
                final DailyAndHourlySuitabilityForDay suitabilityForDay =
                        entry.getValue();
                final Long dayValue = entry.getKey();

                if (!StringUtils.hasText(suitabilityForDay.getSunrise())) {
                    LOGGER.warn(MISSING_SUNRISE_DATA_FOR_TIME + dayValue);
                    throw new IncompleteForecastException(
                            MISSING_SUNRISE_DATA_FOR_TIME + dayValue);
                }

                if (!StringUtils.hasText(suitabilityForDay.getSunset())) {
                    LOGGER.warn(MISSING_SUNSET_DATA_FOR_TIME + dayValue);
                    throw new IncompleteForecastException(
                            MISSING_SUNSET_DATA_FOR_TIME + dayValue);
                }
            }
        }

        return reports;
    }

I then added the new recovery method, getFInalCurrentDailyReports(final IncompleteForecastException e) [sic], making the third and final attempt to get results, if needed.

    /**
     * Final attempt at getting complete data for the
     * {@link DailyReportCollection} that was to be returned by
     * {@link #getCurrentDailyReports()}. This time, do not check for
     * completeness of data, and just return results obtained.
     *
     * @param e
     *            the last {@link IncompleteForecastException} thrown by the
     *            last retry of {@link #getCurrentDailyReports()}.
     * @return the latest {@link DailyReportCollection}.
     */
    @Recover
    public DailyReportCollection
            getFInalCurrentDailyReports(final IncompleteForecastException e) {
        LOGGER.warn(
                "Final attempt at getting current daily reports - not checking for completeness afterward!");
        return getRetryableCurrentDailyReports();
    }

With the additional information provided in the message contained within any IncompleteForecastException thrown, the ForecastController class’ getForecast(model) method was slightly modified to write to the error log if the call to the DailyReportCollectionService’s getCurrentDailyReports() method resulted in such an Exception being thrown.

    @GetMapping("/")
    public String getForecast(final Model model) {
        model.addAttribute("cityname", cityName);

        try {
            model.addAttribute("dailyReports",
                    dailyReportCollectionService.getCurrentDailyReports());
        } catch (IncompleteForecastException e) {
            LOGGER.error("Errored out of all attempts to get forecast", e);
        }

        return "forecast";
    }

Finally, the EnableRetry annotation was added to the BikingweatherApplication class as part of the configuration required by the application to retry any Retryable code.

@EnableRetry
@SpringBootApplication(exclude = {DataSourceAutoConfiguration.class})
@ComponentScan(basePackageClasses = {ForecastController.class,
        DailyAndHourlySuitabilityForDay.class,
        DailyReportCollectionService.class, LoggingAspect.class})
public class BikingweatherApplication extends SpringBootServletInitializer {
.
.
.
.
}

After making these additions, I have found that needing to reload the page to see results occurs much less frequently. I hope others may find this retryable code capability valuable.

A Simple Example of Using Spring Aspect Oriented Programming to Log the Beginning and End of All Methods in All Classes in a Package

I have often seen, in development work, certain types of code fragments that get repeated many times throughout the code, which would seem a prime use case for Aspect Oriented Programming (AOP). I thought I would try creating an aspect to do debug logging in my Biking Weather Suitability Forecast application as follows:

  1. Do the following debug logging items for all methods in all classes in the biz.noip.johnwatne.bikingweather.service package.
  2. Log the start of a method’s execution, including the name of the method and listing the parameters passed to it.
  3. For methods that return an Object or value, log the item returned.
  4. For void methods, indicate the end of the method’s execution.
  5. Allow toggling the enabling of the aspect’s code based on the value of a property in the application’s properties file. This allows temporarily enabling the logging while testing new development, then disabling it, or, alternatively, having environment-specific properties files that would have differing values depending on whether or not the logging was desired for that environment.

The application had already been written using Spring Boot. After doing a bit of research on Spring AOP, I decided to use Spring AspectJ annotations to make an aspect out of a POJO (Plain Old Java Object).

The first step was to enable Spring Boot AOP by adding the following dependency to the dependencies section of the application’s pom.xml file:

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>

Similar dependencies could be added for Spring without using Spring Boot, but I did not explore those options for my application. After creating a new package to contain aspects for the application, I added the following single class to it:

package biz.noip.johnwatne.bikingweather.aspects;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

/**
 * Logging aspect.
 *
 * @author John Watne
 *
 */
@Aspect
@Component
public class LoggingAspect {
    private static final Logger LOGGER =
            LoggerFactory.getLogger(LoggingAspect.class);

    @Before("execution(* biz.noip.johnwatne.bikingweather.service..*(..))")
    public void logMethodStart(final JoinPoint joinPoint) {
        LOGGER.debug("*** Starting " + joinPoint.getSignature().getName());

        for (Object arg : joinPoint.getArgs()) {
            LOGGER.debug("****** " + arg);
        }
    }
}
  1. The @Aspect annotation indicates that this is an aspect.
  2. The @Component annotation makes this a Spring Bean.
  3. The @Before annotation indicates that this is code to be inserted at the start of every method matching the criteria specified within its “execution” parameter. The breakdown of the argument passed to execution is as follows:
    1. The “*” before the package specification indicates that it applies to methods of all return types.
    2. biz.noip.johnwatne.bikingweather.service..*(..)” indicates that all methods within the specified package, with any combination of parameters passed to them, are to have the annotated code executed at the start of the method.
  4. The JoinPoint parameter passed to the “advice” method indicates where the “advice” method’s code gets joined to the main code of the program. joinPoint.getSignature.getName() returns the name of the method receiving the “advice”, and joinPoint.getArgs() gives a List of all the parameters passed to that method.

Having created this class with the @Component annotation, I added the class to the list of basePackageClasses in the @ComponentScan annotation on my main application class, as follows.

@SpringBootApplication(exclude = {DataSourceAutoConfiguration.class})
@ComponentScan(basePackageClasses = {ForecastController.class,
        DailyAndHourlySuitabilityForDay.class,
        DailyReportCollectionService.class, LoggingAspect.class})
public class BikingweatherApplication extends SpringBootServletInitializer {

After confirming that the @Before-annotated advice worked, I added the following two methods to the LoggingAspect class. The first uses the @AfterReturning annotation in order to get the value returned by the method, and the second should indicate the completion of executing a void method.

    @AfterReturning(
            value = "execution(* biz.noip.johnwatne.bikingweather.service..*(..))",
            returning = "result")
    public void logReturnValue(final JoinPoint joinPoint, final Object result) {
        LOGGER.debug("*** " + joinPoint.getSignature().getName() + " returns "
                + result);
    }

    @After("execution(void biz.noip.johnwatne.bikingweather.service..*(..))")
    public void logReturnFromVoidMethod(final JoinPoint joinPoint) {
        LOGGER.debug(
                "*** end void method " + joinPoint.getSignature().getName());
    }

The following log excerpt gives an example of the code generated by these “advice” methods.

2020-11-23 02:06:45,522 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** Starting getForecastRequest
2020-11-23 02:06:45,552 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** getForecastRequest returns ForecastRequest{url=https://api.darksky.net/forecast/0f57d37e9e219b7569810eb003a03073/44.887321,-93.312086?lang=en&units=us&exclude=minutely}
2020-11-23 02:06:46,729 INFO biz.noip.johnwatne.bikingweather.service.DailyReportCollectionService [http-nio-1986-exec-7] *** Obtaining new NWS forecast ***
2020-11-23 02:06:46,730 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** Starting getHourlyForecast
2020-11-23 02:06:48,506 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** getHourlyForecast returns HourlyForecast [getType()=Feature, getGeometry()=biz.noip.johnwatne.bikingweather.model.nws.Geometry@2e6896d, getProperties()=
Properties [getUpdated()=2020-11-23T05:09:17+00:00, getUnits()=us, getForecastGenerator()=HourlyForecastGenerator, getGeneratedAt()=2020-11-23T08:06:48+00:00, getUpdateTime()=2020-11-23T05:09:17+00:00, getValidTimes()=2020-11-22T23:00:00+00:00/P7DT2H, getPeriods()=[
Period [getNumber()=1, getStartTime()=2020-11-23T02:00:00-06:00, getEndTime()=2020-11-23T03:00:00-06:00, isDaytime()=false, getTemperature()=27, getTemperatureUnit()=F, getWindSpeed()=5 mph, getWindDirection()=NW, getIcon()=https://api.weather.gov/icons/land/night/sct?size=small, getShortForecast()=Partly Cloudy], 
.
.
.

Finally, I added the @ConditionalOnProperty(...) annotation to the LoggingAspect class such that the class would only have its code injected into methods if the expanded.logging property was defined with a value of true.

@Aspect
@Component
@ConditionalOnProperty(prefix = "expanded", name = "logging",
        havingValue = "true")
public class LoggingAspect {
.
.
.

This code is enabled by adding the following line to the application’s application.properties file.

expanded.logging=true

Note that the @ConditionalOnProperty is a configuration annotation for Spring Boot. It should be possible to do something comparable in Spring, without Spring Boot, using the @Conditional annotation added in Spring 4. The class implementing the Condition interface would be responsible for checking the value of the expanded.logging property, in this case.

This was an interesting first experiment with Aspect Oriented Programming. I hope that this example, and the links above, may be of use to others interested in exploring this subject.