From 452b72e057f577c3b06389caf606b670ecc600c3 Mon Sep 17 00:00:00 2001 From: =?utf8?q?David=20=E2=80=98Bombe=E2=80=99=20Roden?= Date: Fri, 2 Sep 2022 17:56:58 +0200 Subject: [PATCH] =?utf8?q?=F0=9F=94=8A=20Log=20element=20loader=E2=80=99s?= =?utf8?q?=20decisions=20and=20results?= MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit This should make it way easier to find out why a certain element wasn’t loaded. --- .../sone/core/DefaultElementLoader.kt | 20 +++++++- .../sone/core/DefaultElementLoaderTest.kt | 58 ++++++++++++++++++++++ 2 files changed, 76 insertions(+), 2 deletions(-) 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 --- 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 = CacheBuilder.newBuilder().build() private val failureCache: Cache = CacheBuilder.newBuilder().ticker(ticker).expireAfterWrite(30, MINUTES).build() private val elementCache: Cache = 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 --- 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() + + 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) -> Unit) { -- 2.7.4