🔊 Log element loader’s decisions and results

This should make it way easier to find out why a certain element wasn’t loaded.

diff --git a/src/main/kotlin/net/pterodactylus/sone/core/DefaultElementLoader.kt b/src/main/kotlin/net/pterodactylus/sone/core/DefaultElementLoader.kt
index 69872c5..fd3d8c8 100644 (file)
--- a/src/main/kotlin/net/pterodactylus/sone/core/DefaultElementLoader.kt
+++ b/src/main/kotlin/net/pterodactylus/sone/core/DefaultElementLoader.kt
@@ -11,6 +11,7 @@ import java.net.URLDecoder
 import java.nio.charset.Charset
 import java.text.Normalizer
 import java.util.concurrent.TimeUnit.MINUTES
+import java.util.logging.Logger
 import javax.activation.MimeType
 import javax.imageio.ImageIO
 import javax.inject.Inject
@@ -25,9 +26,18 @@ class DefaultElementLoader(private val freenetInterface: FreenetInterface, ticke
        private val loadingLinks: Cache<String, Boolean> = CacheBuilder.newBuilder().build()
        private val failureCache: Cache<String, Boolean> = CacheBuilder.newBuilder().ticker(ticker).expireAfterWrite(30, MINUTES).build()
        private val elementCache: Cache<String, LinkedElement> = CacheBuilder.newBuilder().build()
+       private val logger = Logger.getLogger(DefaultElementLoader::class.qualifiedName)
        private val callback = object: FreenetInterface.BackgroundFetchCallback {
                override fun shouldCancel(uri: FreenetURI, mimeType: String, size: Long): Boolean {
-                       return (size > 2097152) || (!mimeType.startsWith("image/") && !mimeType.startsWith("text/html"))
+                       if (size > 2097152) {
+                               logger.fine { "Canceling download of $uri because it’s > 2 MiB." }
+                               return true
+                       }
+                       if (!mimeType.startsWith("image/") && !mimeType.startsWith("text/html")) {
+                               logger.fine { "Canceling download of $uri because of its MIME type, $mimeType." }
+                               return true
+                       }
+                       return false
                }
 
                override fun loaded(uri: FreenetURI, mimeTypeText: String, data: ByteArray) {
@@ -39,6 +49,9 @@ class DefaultElementLoader(private val freenetInterface: FreenetInterface, ticke
                                                }?.let {
                                                        elementCache.get(uri.toString().decode().normalize()) {
                                                                LinkedElement(uri.toString(), properties = mapOf("type" to "image", "size" to data.size, "sizeHuman" to data.size.human))
+                                                                       .apply {
+                                                                               logger.fine("Downloaded image from $link: size=${properties["size"]}.")
+                                                                       }
                                                        }
                                                }
                                        }
@@ -49,7 +62,9 @@ class DefaultElementLoader(private val freenetInterface: FreenetInterface, ticke
                                                                        "type" to "html", "size" to data.size, "sizeHuman" to data.size.human,
                                                                        "title" to document.title().emptyToNull,
                                                                        "description" to (document.metaDescription ?: document.firstNonHeadingParagraph)
-                                                       ))
+                                                       )).apply {
+                                                               logger.fine { "Extracted information from $link: title=${properties["title"]}, description=${properties["description"]}." }
+                                                       }
                                                }
                                        }
                                }
@@ -60,6 +75,7 @@ class DefaultElementLoader(private val freenetInterface: FreenetInterface, ticke
                override fun failed(uri: FreenetURI) {
                        failureCache.put(uri.toString().decode().normalize(), true)
                        removeLoadingLink(uri)
+                       logger.fine { "Download failed for $uri." }
                }
 
                private fun removeLoadingLink(uri: FreenetURI) {

diff --git a/src/test/kotlin/net/pterodactylus/sone/core/DefaultElementLoaderTest.kt b/src/test/kotlin/net/pterodactylus/sone/core/DefaultElementLoaderTest.kt
index 64456bc..98a177b 100644 (file)
--- a/src/test/kotlin/net/pterodactylus/sone/core/DefaultElementLoaderTest.kt
+++ b/src/test/kotlin/net/pterodactylus/sone/core/DefaultElementLoaderTest.kt
@@ -9,14 +9,20 @@ import org.hamcrest.Matcher
 import org.hamcrest.MatcherAssert.assertThat
 import org.hamcrest.Matchers.allOf
 import org.hamcrest.Matchers.contains
+import org.hamcrest.Matchers.containsString
 import org.hamcrest.Matchers.equalTo
 import org.hamcrest.Matchers.hasEntry
+import org.hamcrest.Matchers.not
 import org.hamcrest.TypeSafeDiagnosingMatcher
 import org.junit.Rule
 import org.junit.Test
 import java.io.ByteArrayOutputStream
 import java.util.concurrent.TimeUnit.MINUTES
 import java.util.concurrent.atomic.AtomicReference
+import java.util.logging.Handler
+import java.util.logging.Level.ALL
+import java.util.logging.LogRecord
+import java.util.logging.Logger
 import kotlin.math.min
 
 /**
@@ -50,6 +56,7 @@ class DefaultElementLoaderTest {
        fun `element loader does not cancel on image mime type with 2 mib size`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "image/png", sizeOkay), equalTo(false))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), not(contains(containsString("Canceling download"))))
                }
        }
 
@@ -57,6 +64,7 @@ class DefaultElementLoaderTest {
        fun `element loader does cancel on image mime type with more than 2 mib size`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "image/png", sizeNotOkay), equalTo(true))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(containsString("Canceling download")))
                }
        }
 
@@ -64,6 +72,7 @@ class DefaultElementLoaderTest {
        fun `element loader does cancel on audio mime type`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "audio/mpeg", sizeOkay), equalTo(true))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(containsString("Canceling download")))
                }
        }
 
@@ -71,6 +80,7 @@ class DefaultElementLoaderTest {
        fun `element loader does cancel on video mime type`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "video/mkv", sizeOkay), equalTo(true))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(containsString("Canceling download")))
                }
        }
 
@@ -78,6 +88,7 @@ class DefaultElementLoaderTest {
        fun `element loader does cancel on text mime type`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "text/plain", sizeOkay), equalTo(true))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(containsString("Canceling download")))
                }
        }
 
@@ -85,6 +96,7 @@ class DefaultElementLoaderTest {
        fun `element loader does not cancel on text html mime type`() {
                runWithCallback(IMAGE_ID) { _, _, callback, _ ->
                        assertThat(callback.shouldCancel(freenetURI, "text/html", sizeOkay), equalTo(false))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), not(contains(containsString("Canceling download"))))
                }
        }
 
@@ -100,6 +112,16 @@ class DefaultElementLoaderTest {
        }
 
        @Test
+       fun `element loader logs information about downloaded image`() {
+               runWithCallback(decomposedKey) { _, _, callback, _ ->
+                       callback.loaded(FreenetURI(normalizedKey), "image/png", read("/static/images/unknown-image-0.png"))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(allOf(
+                               containsString(normalizedKey), containsString("2451")
+                       )))
+               }
+       }
+
+       @Test
        fun `element loader can extract description from description header`() {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader.html"))
@@ -113,6 +135,17 @@ class DefaultElementLoaderTest {
        }
 
        @Test
+       fun `element loader logs information from downloaded freesite`() {
+               runWithCallback(textKey) { _, _, callback, _ ->
+                       callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader.html"))
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(allOf(
+                               containsString(textKey), containsString("Some Nice Page Title"),
+                               containsString("This is an example of a very nice freesite.")
+                       )))
+               }
+       }
+
+       @Test
        fun `element loader can extract description from first non-heading paragraph`() {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader2.html"))
@@ -172,6 +205,14 @@ class DefaultElementLoaderTest {
        }
 
        @Test
+       fun `element loading failure is logged`() {
+               runWithCallback(IMAGE_ID) { _, _, callback, _ ->
+                       callback.failed(freenetURI)
+                       assertThat(loggedRecords.map(LogRecord::getMessage), contains(containsString("Download failed")))
+               }
+       }
+
+       @Test
        fun `image is loaded again after failure cache is expired`() {
                runWithCallback(IMAGE_ID, createTicker(1, MINUTES.toNanos(31))) { elementLoader, _, callback, _ ->
                        elementLoader.loadElement(IMAGE_ID)
@@ -193,6 +234,23 @@ class DefaultElementLoaderTest {
        @get:Rule
        val silencedLoggin = silencedLogging()
 
+       private val loggedRecords = mutableListOf<LogRecord>()
+
+       init {
+               Logger.getLogger(DefaultElementLoader::class.qualifiedName)
+                       .apply { level = ALL }
+                       .apply {
+                               addHandler(object : Handler() {
+                                       override fun publish(record: LogRecord) {
+                                               loggedRecords += record
+                                       }
+
+                                       override fun flush() = Unit
+                                       override fun close() = Unit
+                               })
+                       }
+       }
+
 }
 
 private fun runWithCallback(requestUri: String, ticker: Ticker = createTicker(), callbackAction: (elementLoader: ElementLoader, linkedElement: LinkedElement, callback: BackgroundFetchCallback, fetchedUris: List<FreenetURI>) -> Unit) {