So far, we have crafted a domain object for MongoDB, defined a reactive repository, and updated our ImageService to use it. If we fire things up, though, how can we see what's happening? Apart from viewing the web page, what can we expect to see in the console logs?
So far, this appears to be the most we get:
We see some log messages about connecting to an instance of MongoDB, but that's it! Not much there to debug things, ehh? Never fear, Spring Boot to the rescue.
Spring Boot comes with extensive logging support. Off the cuff, we can create a logback.xml file, and add it to our configuration in src/main/resources. Spring Boot will read it, and override its default logging policy. That's nice if we want to totally overhaul the log settings.
But often times, we just want to adjust some logging levels for specific packages. Spring Boot grants us a more fine-grained way to alter what gets logged.
Simply add this to src/main/resources/application.properties:
logging.level.com.greglturnquist=DEBUG
logging.level.org.springframework.data=TRACE
logging.level.reactor.core=TRACE
logging.level.reactor.util=TRACE
These adjustments can be described as follows:
- logging.level tells Spring Boot to adjust log levels with the name of the package tacked on followed by a level
- The application code, com.greglturnquist, is set to DEBUG
- Spring Data, org.springframework.data, is set to TRACE
- Project Reactor, reactor.core and reactor.util, are set to TRACE
With these adjustments, if we launch our application, this is part of the output we get:
This preceding output shows some MongoDB activity including cluster configuration, connections, and domain analysis. Toward the end, the effects of InitDatabase preloading our data can be seen to some degree, and can be explained as follows:
- Dropped collection [image]: This indicates all the entries being deleted by our dropCollection
- Inserting Document containing fields...: This indicates entries being saved using our insert
This is definitely an improvement, but something that's missing is the role that Reactor plays in handling all of this. While we've dialed up the log levels for Reactor, nothing has been output.
If we look at ImageService, the question arises, where can we add more logging? In traditional imperative programming, we would, typically, write log.debug("blah blah") at several spots along the way. But in this reactive flow, there are no "stops" to put them.
Project Reactor comes with a declarative log statement we can add along the way. Here is how we can decorate findAllImages:
public Flux<Image> findAllImages() {
return imageRepository.findAll()
.log("findAll");
}
This preceding service operation has but one reactive step, so we can only slip in a single log statement. ImageService.findOneImage has the same story, so no need to show that.
However, createImage has several steps, which are seen in this code:
public Mono<Void> createImage(Flux<FilePart> files) {
return files
.log("createImage-files")
.flatMap(file -> {
Mono<Image> saveDatabaseImage = imageRepository.save(
new Image(
UUID.randomUUID().toString(),
file.filename()))
.log("createImage-save");
Mono<Void> copyFile = Mono.just(
Paths.get(UPLOAD_ROOT, file.filename())
.toFile())
.log("createImage-picktarget")
.map(destFile -> {
try {
destFile.createNewFile();
return destFile;
} catch (IOException e) {
throw new RuntimeException(e);
}
})
.log("createImage-newfile")
.flatMap(file::transferTo)
.log("createImage-copy");
return Mono.when(saveDatabaseImage, copyFile)
.log("createImage-when");
})
.log("createImage-flatMap")
.then()
.log("createImage-done");
}
This last code is identical to what we had before except that each Reactor operation is tagged with a log statement. And each one has a unique tag appended, so, we can tell exactly what is happening and where.
If we exercise this code from a unit test that uploads two mock multipart files (a test we'll look closer at in the next chapter, Chapter 4, Testing with Spring Boot), we can spot each tag in the console output as follows:
This preceding output shows each of the steps, and how they play together in the reactive streams' dance of subscribe, request, next, and complete. Most notably, the outer operations (files, flatMap, and done) are shown at the top when subscriptions are made. Each file causes a filter operation to occur followed by a save and a copy. And at the bottom, the same outer operations (again files, flatMap, and done) issue a reactive streams complete.
To mark up deleteImage with logs, let's make these changes:
public Mono<Void> deleteImage(String filename) {
Mono<Void> deleteDatabaseImage = imageRepository
.findByName(filename)
.log("deleteImage-find")
.flatMap(imageRepository::delete)
.log("deleteImage-record");
Mono<Object> deleteFile = Mono.fromRunnable(() -> {
try {
Files.deleteIfExists(
Paths.get(UPLOAD_ROOT, filename));
} catch (IOException e) {
throw new RuntimeException(e);
}
})
.log("deleteImage-file");
return Mono.when(deleteDatabaseImage, deleteFile)
.log("deleteImage-when")
.then()
.log("deleteImage-done");
}
This is the same deleteImage code we wrote earlier, only, we've sprinkled in log statements everywhere to indicate exactly what is happening.
With everything set up, we should be able to test things out. For starters, we can launch the code by either running the LearningSpringBootApplication class's public static void main() method, or we can run it from the command line using Gradle like this:
$ ./gradlew clean bootRun
If we launch the application and navigate to http://localhost:8080, we can see our preloaded images, as seen in this screenshot:
We can click on a single image, and see some comparable log messages like this:
findOneImage : | onSubscribe([Fuseable] Operators.MonoSubscriber) findOneImage : | request(unbounded) findOneImage : | onNext(URL [file:upload-dir/learning-spring-boot-
cover.jpg]) findOneImage : | onComplete()
This very simple flow illustrates the Reactive Streams pattern. We subscribe for an image. A request is sent--in this case, unbounded (even though we know in advance there is only one result). onNext is the answer, and it's a file-based URL (a Spring Resource) being returned. Then the complete is issued.
If we click on the Delete button, it deletes the image and refreshes the page, as follows:
After completing the deletion, if we look at the console logs and focus on what happened, we will see something like this:
At the very top, we can see a MongoDB query issued to find the desired image with the findOne using query output. A Mono.when is set up, and then, a Remove using query is issued to delete the record. The actual deletion of the file is logged with little details except the complete signal. The whole thing is wrapped up when we see deleteImage-done issue a complete.
With this, we have successfully coded a reactive ImageService that both copies files to the server and writes records in MongoDB; and we did it letting Spring Boot autoconfigure all the beans needed to make Spring Data MongoDB work seamlessly with Spring WebFlux and MongoDB.