🔊 Log element loader’s decisions and results
[Sone.git] / src / test / kotlin / net / pterodactylus / sone / core / DefaultElementLoaderTest.kt
index a3c6af0..98a177b 100644 (file)
@@ -4,14 +4,25 @@ import com.google.common.base.Ticker
 import freenet.keys.FreenetURI
 import net.pterodactylus.sone.core.FreenetInterface.BackgroundFetchCallback
 import net.pterodactylus.sone.test.*
+import org.hamcrest.Description
+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
 
 /**
@@ -45,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"))))
                }
        }
 
@@ -52,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")))
                }
        }
 
@@ -59,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")))
                }
        }
 
@@ -66,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")))
                }
        }
 
@@ -73,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")))
                }
        }
 
@@ -80,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"))))
                }
        }
 
@@ -88,11 +105,19 @@ class DefaultElementLoaderTest {
                runWithCallback(decomposedKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(normalizedKey), "image/png", read("/static/images/unknown-image-0.png"))
                        val linkedElement = elementLoader.loadElement(decomposedKey)
-                       mapOf(
-                               "type" to "image",
-                               "size" to 2451,
-                               "sizeHuman" to "2 KiB"
-                       ).also { assertThat(linkedElement, equalTo(LinkedElement(normalizedKey, properties = it))) }
+                       assertThat(linkedElement, isLinkedElement(equalTo(normalizedKey), allOf(
+                               hasEntry("type", "image"), hasEntry("size", 2451), hasEntry("sizeHuman", "2 KiB"),
+                       )))
+               }
+       }
+
+       @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")
+                       )))
                }
        }
 
@@ -101,13 +126,22 @@ class DefaultElementLoaderTest {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader.html"))
                        val linkedElement = elementLoader.loadElement(textKey)
-                       mapOf(
-                               "type" to "html",
-                               "size" to 266,
-                               "sizeHuman" to "266 B",
-                               "title" to "Some Nice Page Title",
-                               "description" to "This is an example of a very nice freesite."
-                       ).also { assertThat(linkedElement, equalTo(LinkedElement(textKey, properties = it))) }
+                       assertThat(linkedElement, isLinkedElement(equalTo(textKey), allOf(
+                               hasEntry("type", "html"), hasEntry("size", 266), hasEntry("sizeHuman", "266 B"),
+                               hasEntry("title", "Some Nice Page Title"),
+                               hasEntry("description", "This is an example of a very nice freesite.")
+                       )))
+               }
+       }
+
+       @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.")
+                       )))
                }
        }
 
@@ -116,28 +150,24 @@ class DefaultElementLoaderTest {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader2.html"))
                        val linkedElement = elementLoader.loadElement(textKey)
-                       mapOf(
-                               "type" to "html",
-                               "size" to 185,
-                               "sizeHuman" to "185 B",
-                               "title" to "Some Nice Page Title",
-                               "description" to "This is the first paragraph of the very nice freesite."
-                       ).also { assertThat(linkedElement, equalTo(LinkedElement(textKey, properties = it))) }
+                       assertThat(linkedElement, isLinkedElement(equalTo(textKey), allOf(
+                               hasEntry("type", "html"), hasEntry("size", 185), hasEntry("sizeHuman", "185 B"),
+                               hasEntry("title", "Some Nice Page Title"),
+                               hasEntry("description", "This is the first paragraph of the very nice freesite.")
+                       )))
                }
        }
 
        @Test
-       fun `element loader can not extract description if html is more complicated`() {
+       fun `element loader can extract description if html is more complicated`() {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader3.html"))
                        val linkedElement = elementLoader.loadElement(textKey)
-                       mapOf(
-                               "type" to "html",
-                               "size" to 204,
-                               "sizeHuman" to "204 B",
-                               "title" to "Some Nice Page Title",
-                               "description" to null
-                       ).also { assertThat(linkedElement, equalTo(LinkedElement(textKey, properties = it))) }
+                       assertThat(linkedElement, isLinkedElement(equalTo(textKey), allOf(
+                               hasEntry("type", "html"), hasEntry("size", 204), hasEntry("sizeHuman", "204 B"),
+                               hasEntry("title", "Some Nice Page Title"),
+                               hasEntry("description", "This is the first paragraph of the very nice freesite.")
+                       )))
                }
        }
 
@@ -146,13 +176,22 @@ class DefaultElementLoaderTest {
                runWithCallback(textKey) { elementLoader, _, callback, _ ->
                        callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader4.html"))
                        val linkedElement = elementLoader.loadElement(textKey)
-                       mapOf(
-                               "type" to "html",
-                               "size" to 229,
-                               "sizeHuman" to "229 B",
-                               "title" to null,
-                               "description" to "This is an example of a very nice freesite."
-                       ).also { assertThat(linkedElement, equalTo(LinkedElement(textKey, properties = it))) }
+                       assertThat(linkedElement, isLinkedElement(equalTo(textKey), allOf(
+                               hasEntry("type", "html"), hasEntry("size", 229), hasEntry("sizeHuman", "229 B"), hasEntry("title", null),
+                               hasEntry("description", "This is an example of a very nice freesite.")
+                       )))
+               }
+       }
+
+       @Test
+       fun `element loader can extract first paragraph from real-world example`() {
+               runWithCallback(textKey) { elementLoader, _, callback, _ ->
+                       callback.loaded(FreenetURI(textKey), "text/html; charset=UTF-8", read("element-loader5.html"))
+                       val linkedElement = elementLoader.loadElement(textKey)
+                       assertThat(linkedElement, isLinkedElement(equalTo(textKey), allOf(
+                               hasEntry("type", "html"), hasEntry("title", "Some Nice Page Title"),
+                               hasEntry("description", "This is the first paragraph of the very nice freesite.")
+                       )))
                }
        }
 
@@ -166,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)
@@ -187,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) {
@@ -214,6 +278,21 @@ private fun createTicker(vararg times: Long = LongArray(1) { 1 }) = object : Tic
                        .also { counter++ }
 }
 
+private fun isLinkedElement(link: Matcher<String> = everything(), properties: Matcher<Map<String, Any?>> = everything(), failed: Matcher<Boolean> = everything(), loading: Matcher<Boolean> = everything()) = object : TypeSafeDiagnosingMatcher<LinkedElement>() {
+       override fun matchesSafely(item: LinkedElement, mismatchDescription: Description) =
+               handleMatcher(link, item.link, mismatchDescription) &&
+                               handleMatcher(properties, item.properties, mismatchDescription) &&
+                               handleMatcher(failed, item.failed, mismatchDescription) &&
+                               handleMatcher(loading, item.loading, mismatchDescription)
+
+       override fun describeTo(description: Description) {
+               description.appendText("is linked element for key matching ").appendValue(link)
+                       .appendText(", properties matching ").appendValue(properties)
+                       .appendText(", failed matching ").appendValue(failed)
+                       .appendText(", loading matching ").appendValue(loading)
+       }
+}
+
 private const val IMAGE_ID = "KSK@gpl.png"
 private val freenetURI = FreenetURI(IMAGE_ID)
 private const val decomposedKey = "CHK@DCiVgTWW9nnWHJc9EVwtFJ6jAfBSVyy~rgiPvhUKbS4,mNY85V0x7dYcv7SnEYo1PCC6y2wNWMDNt-y9UWQx9fI,AAMC--8/fru%CC%88hstu%CC%88ck.jpg"