[port = 35987 \22:59:12,928 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found logback-core version 1.6.1 \22:59:12,928 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - No custom configurators were discovered as a service. \22:59:12,928 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator \22:59:12,929 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator \22:59:12,930 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] \22:59:12,932 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/jenkins/.jenkins/workspace/dev-playlists-links-end-to-end-tests/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] \22:59:12,932 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs multiple times on the classpath. \22:59:12,932 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs at [file:/home/jenkins/.jenkins/workspace/dev-playlists-links-end-to-end-tests/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] \22:59:12,932 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs at [jar:file:/home/jenkins/.jenkins/workspace/dev-playlists-links-end-to-end-tests/respect-server/build/libs/respect-server-1.0.39.jar!/logback.xml] \22:59:12,991 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Scan attribute not set or set to unrecognized value. \22:59:12,994 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT] \22:59:12,994 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] \22:59:12,998 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property \22:59:13,021 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - NOTE: Writing to the console can be slow. Try to avoid logging to the \22:59:13,021 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - console in production environments, especially in high volume systems. \22:59:13,021 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also https://logback.qos.ch/codes.html#slowConsole \22:59:13,021 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to TRACE \22:59:13,022 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT] \22:59:13,022 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [io.netty] to INFO \22:59:13,022 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@4b45dcb8 - End of configuration. \22:59:13,023 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7216fb24 - Registering current configuration as safe fallback point \22:59:13,025 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 95 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY \ \2026-09-16 22:59:13.180 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. dport = 38157 d2026-09-16 22:59:15.243 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. hport = 37661 h2026-09-16 22:59:16.323 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. m2026-09-16 22:59:17.588 [Test worker @coroutine#62] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. m2026-09-16 22:59:17.598 [Test worker @coroutine#62] INFO io.ktor.server.Application - Application started in 0.113 seconds. m2026-09-16 22:59:17.602 [DefaultDispatcher-worker-2 @coroutine#71] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41355 m2026-09-16 22:59:17.611 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41355/api/school/respect/schoolpermissiongrant m2026-09-16 22:59:17.611 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41355/api/school/respect/schoolpermissiongrant. m2026-09-16 22:59:17.616 [eventLoopGroupProxy-13-1 @call-handler#74] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] m/, segment:0 -> SUCCESS @ / m /api, segment:1 -> SUCCESS @ /api m /api/school, segment:2 -> SUCCESS @ /api/school m /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect m /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person m /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant m /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] mMatched routes: m "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" mRouting resolve result: m SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] m2026-09-16 22:59:17.629 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41355/api/school/respect/schoolpermissiongrant m2026-09-16 22:59:17.630 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41355/api/school/respect/schoolpermissiongrant m2026-09-16 22:59:17.630 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41355/api/school/respect/schoolpermissiongrant m2026-09-16 22:59:17.632 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41355/api/school/respect/schoolpermissiongrant. nA2026-09-16 22:59:17.698 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41355/api/school/respect/person?includeRelated=false nA2026-09-16 22:59:17.698 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41355/api/school/respect/person?includeRelated=false. nC2026-09-16 22:59:17.700 [eventLoopGroupProxy-13-1 @call-handler#80] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] nC/, segment:0 -> SUCCESS @ / nC /api, segment:1 -> SUCCESS @ /api nC /api/school, segment:2 -> SUCCESS @ /api/school nC /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect nC /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person nC /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] nD /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] nD /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant nDMatched routes: nD "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" nDRouting resolve result: nD SUCCESS @ /api/school/respect/person [(method:GET)] nZ2026-09-16 22:59:17.723 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41355/api/school/respect/person?includeRelated=false nZ2026-09-16 22:59:17.723 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41355/api/school/respect/person?includeRelated=false nZ2026-09-16 22:59:17.723 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41355/api/school/respect/person?includeRelated=false n\2026-09-16 22:59:17.724 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41355/api/school/respect/person?includeRelated=false. nb2026-09-16 22:59:17.731 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41355/api/school/respect/person?includeRelated=false nb2026-09-16 22:59:17.731 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41355/api/school/respect/person?includeRelated=false. nd2026-09-16 22:59:17.733 [eventLoopGroupProxy-13-1 @call-handler#86] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] nd/, segment:0 -> SUCCESS @ / nd /api, segment:1 -> SUCCESS @ /api nd /api/school, segment:2 -> SUCCESS @ /api/school nd /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect nd /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person nd /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] nd /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] nd /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ndMatched routes: nd "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" neRouting resolve result: ne SUCCESS @ /api/school/respect/person [(method:GET)] nf2026-09-16 22:59:17.735 [eventLoopGroupProxy-13-1 @call-handler#86] TRACE i.k.s.p.c.ContentNegotiation - Skipping response body transformation from HttpStatusCode to OutgoingContent for the GET /api/school/respect/person?includeRelated=false request because the HttpStatusCode type is ignored. See [ContentNegotiationConfig::ignoreType]. ng2026-09-16 22:59:17.736 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41355/api/school/respect/person?includeRelated=false ng2026-09-16 22:59:17.736 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41355/api/school/respect/person?includeRelated=false ng2026-09-16 22:59:17.736 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41355/api/school/respect/person?includeRelated=false r2026-09-16 22:59:18.839 [Test worker @coroutine#90] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. r2026-09-16 22:59:18.840 [Test worker @coroutine#90] INFO io.ktor.server.Application - Application started in 0.04 seconds. r2026-09-16 22:59:18.841 [DefaultDispatcher-worker-1 @coroutine#99] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41725 r2026-09-16 22:59:18.842 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41725/api/school/respect/schoolpermissiongrant r2026-09-16 22:59:18.842 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41725/api/school/respect/schoolpermissiongrant. r2026-09-16 22:59:18.845 [eventLoopGroupProxy-16-1 @call-handler#102] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] r/, segment:0 -> SUCCESS @ / r /api, segment:1 -> SUCCESS @ /api r /api/school, segment:2 -> SUCCESS @ /api/school r /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect r /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person r /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant r /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] rMatched routes: r "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" rRouting resolve result: r SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] r2026-09-16 22:59:18.847 [Test worker @coroutine#90] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41725/api/school/respect/schoolpermissiongrant r2026-09-16 22:59:18.847 [Test worker @coroutine#90] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41725/api/school/respect/schoolpermissiongrant r2026-09-16 22:59:18.847 [Test worker @coroutine#90] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41725/api/school/respect/schoolpermissiongrant r2026-09-16 22:59:18.847 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41725/api/school/respect/schoolpermissiongrant. s2026-09-16 22:59:18.913 [DefaultDispatcher-worker-2 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 s2026-09-16 22:59:18.913 [DefaultDispatcher-worker-2 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. s2026-09-16 22:59:18.915 [eventLoopGroupProxy-16-1 @call-handler#112] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] s/, segment:0 -> SUCCESS @ / s /api, segment:1 -> SUCCESS @ /api s /api/school, segment:2 -> SUCCESS @ /api/school s /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect s /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person s /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] s /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] s /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant sMatched routes: s "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" sRouting resolve result: s SUCCESS @ /api/school/respect/person [(method:GET)] s2026-09-16 22:59:18.919 [DefaultDispatcher-worker-1 @coroutine#108] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 s2026-09-16 22:59:18.919 [DefaultDispatcher-worker-1 @coroutine#108] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 s2026-09-16 22:59:18.919 [DefaultDispatcher-worker-1 @coroutine#108] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 s2026-09-16 22:59:18.920 [DefaultDispatcher-worker-1 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41725/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. wI2026-09-16 22:59:20.009 [Test worker @coroutine#117] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. wJ2026-09-16 22:59:20.010 [Test worker @coroutine#117] INFO io.ktor.server.Application - Application started in 0.039 seconds. wK2026-09-16 22:59:20.011 [DefaultDispatcher-worker-4 @coroutine#126] INFO io.ktor.server.Application - Responding at http://0.0.0.0:42025 wN2026-09-16 22:59:20.014 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42025/api/school/respect/person?includeRelated=false wN2026-09-16 22:59:20.014 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:42025/api/school/respect/person?includeRelated=false. wP2026-09-16 22:59:20.017 [eventLoopGroupProxy-19-1 @call-handler#130] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] wP/, segment:0 -> SUCCESS @ / wP /api, segment:1 -> SUCCESS @ /api wP /api/school, segment:2 -> SUCCESS @ /api/school wP /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect wP /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person wP /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] wP /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] wPMatched routes: wP "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" wPRouting resolve result: wP SUCCESS @ /api/school/respect/person [(method:GET)] wT2026-09-16 22:59:20.020 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42025/api/school/respect/person?includeRelated=false wT2026-09-16 22:59:20.020 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42025/api/school/respect/person?includeRelated=false wT2026-09-16 22:59:20.020 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42025/api/school/respect/person?includeRelated=false wU2026-09-16 22:59:20.022 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42025/api/school/respect/person?includeRelated=false. w0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:19.931Z, stored=2026-09-16T18:59:20.059Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585159931, lastStored=1789585160059, etag=null, url=http://localhost:42025/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T18:59:20.060785493Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:19.931Z, stored=2026-09-16T18:59:20.059Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585159931, lastStored=1789585160059, etag=null, url=null, consistentThrough=2026-09-16T18:59:20.060785493Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=null, remoteState=null), remoteState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:19.931Z, stored=2026-09-16T18:59:19.970Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null), Person(guid=42, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:19.929Z, stored=2026-09-16T18:59:20.012Z, metadata=null, userMasterIdentifier=null, username=test, givenName=test, familyName=test, middleName=null, gender=FEMALE, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SITE_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585160000, lastStored=-1, etag=null, url=http://localhost:42025/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T18:59:20.017635799Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@7b598d05, permissionsLastModified=null), localState=null, remoteState=null)) w2026-09-16 22:59:20.073 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false w2026-09-16 22:59:20.074 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false. w2026-09-16 22:59:20.075 [eventLoopGroupProxy-19-1 @call-handler#136] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] w/, segment:0 -> SUCCESS @ / w /api, segment:1 -> SUCCESS @ /api w /api/school, segment:2 -> SUCCESS @ /api/school w /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect w /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person w /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] w /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] wMatched routes: w "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" wRouting resolve result: w SUCCESS @ /api/school/respect/person [(method:GET)] w2026-09-16 22:59:20.077 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false w2026-09-16 22:59:20.077 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false w2026-09-16 22:59:20.077 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false w2026-09-16 22:59:20.077 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42025/api/school/respect/person?since=2026-09-16T18%3A59%3A20.017635799Z&includeRelated=false. wRun time: 66.355522ms {2026-09-16 22:59:21.195 [Test worker @coroutine#142] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. {2026-09-16 22:59:21.195 [Test worker @coroutine#142] INFO io.ktor.server.Application - Application started in 0.048 seconds. {2026-09-16 22:59:21.198 [DefaultDispatcher-worker-1 @coroutine#151] INFO io.ktor.server.Application - Responding at http://0.0.0.0:40467 |2026-09-16 22:59:21.241 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40467/api/school/respect/person |2026-09-16 22:59:21.242 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@1546d629 for http://localhost:40467/api/school/respect/person |2026-09-16 22:59:21.242 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:40467/api/school/respect/person from class io.ktor.http.content.TextContent |2026-09-16 22:59:21.245 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] |/, segment:0 -> SUCCESS @ / | /api, segment:1 -> SUCCESS @ /api | /api/school, segment:2 -> SUCCESS @ /api/school | /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect | /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person | /api/school/respect/person [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:GET)] | /api/school/respect/person [(method:POST)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:POST)] |Matched routes: | "" -> "api" -> "school" -> "respect" -> "person" -> "(method:POST)" |Routing resolve result: | SUCCESS @ /api/school/respect/person [(method:POST)] | 2026-09-16 22:59:21.249 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE i.k.server.engine.DefaultTransform - No Default Transformations found for class io.ktor.utils.io.ByteChannel and expected type TypeInfo(kotlin.collections.List) for call /api/school/respect/person |"2026-09-16 22:59:21.250 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE i.k.s.p.c.ContentNegotiation - Skipping response body transformation from HttpStatusCode to OutgoingContent for the POST /api/school/respect/person request because the HttpStatusCode type is ignored. See [ContentNegotiationConfig::ignoreType]. |#2026-09-16 22:59:21.251 [DefaultDispatcher-worker-2 @coroutine#149] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40467/api/school/respect/person |#2026-09-16 22:59:21.251 [DefaultDispatcher-worker-2 @coroutine#149] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40467/api/school/respect/person |#2026-09-16 22:59:21.251 [DefaultDispatcher-worker-2 @coroutine#149] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40467/api/school/respect/person k2026-09-16 22:59:22.348 [Test worker @coroutine#165] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. l2026-09-16 22:59:22.349 [Test worker @coroutine#165] INFO io.ktor.server.Application - Application started in 0.04 seconds. m2026-09-16 22:59:22.350 [DefaultDispatcher-worker-4 @coroutine#174] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41043 n2026-09-16 22:59:22.351 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41043/api/school/respect/schoolpermissiongrant n2026-09-16 22:59:22.351 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41043/api/school/respect/schoolpermissiongrant. p2026-09-16 22:59:22.353 [eventLoopGroupProxy-25-1 @call-handler#177] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] p/, segment:0 -> SUCCESS @ / p /api, segment:1 -> SUCCESS @ /api p /api/school, segment:2 -> SUCCESS @ /api/school q /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect q /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person q /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant q /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] qMatched routes: q "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" qRouting resolve result: q SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] r2026-09-16 22:59:22.355 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41043/api/school/respect/schoolpermissiongrant s2026-09-16 22:59:22.355 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41043/api/school/respect/schoolpermissiongrant s2026-09-16 22:59:22.355 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41043/api/school/respect/schoolpermissiongrant s2026-09-16 22:59:22.355 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41043/api/school/respect/schoolpermissiongrant. 2026-09-16 22:59:22.397 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41043/api/school/respect/person?includeRelated=false 2026-09-16 22:59:22.397 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41043/api/school/respect/person?includeRelated=false. 2026-09-16 22:59:22.399 [eventLoopGroupProxy-25-1 @call-handler#183] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)]  /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 16, 2026 10:59:22 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-16 22:59:22.404 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41043/api/school/respect/person?includeRelated=false 2026-09-16 22:59:22.404 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41043/api/school/respect/person?includeRelated=false 2026-09-16 22:59:22.404 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41043/api/school/respect/person?includeRelated=false 2026-09-16 22:59:22.405 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41043/api/school/respect/person?includeRelated=false. ySep 16, 2026 10:59:24 PM io.github.aakira.napier.DebugAntilog performLog yFINE: [DEBUG] DelegatedInvalidationPagingSource$onSrcInvalidated - RPaging/DelegatedInvalidationPagingSource(extra=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))) src invalidated zSep 16, 2026 10:59:24 PM io.github.aakira.napier.DebugAntilog performLog zFINE: [DEBUG] HttpRequestBuilderExtKt$addCacheValidationHeaders - addCacheValidationHeaders = If-Modified-Since = Wed, 16 Sep 2026 18:59:22 GMT for http://localhost:41043/api/school/respect/person?includeRelated=false z2026-09-16 22:59:24.410 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41043/api/school/respect/person?includeRelated=false z2026-09-16 22:59:24.410 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:41043/api/school/respect/person?includeRelated=false. {2026-09-16 22:59:24.412 [eventLoopGroupProxy-25-1 @call-handler#190] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] {/, segment:0 -> SUCCESS @ / { /api, segment:1 -> SUCCESS @ /api { /api/school, segment:2 -> SUCCESS @ /api/school { /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect { /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person { /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] { /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] { /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant {Matched routes: { "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" {Routing resolve result: { SUCCESS @ /api/school/respect/person [(method:GET)] |Sep 16, 2026 10:59:24 PM io.github.aakira.napier.DebugAntilog performLog |FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) }2026-09-16 22:59:24.414 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41043/api/school/respect/person?includeRelated=false }2026-09-16 22:59:24.414 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41043/api/school/respect/person?includeRelated=false }2026-09-16 22:59:24.414 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41043/api/school/respect/person?includeRelated=false ~2026-09-16 22:59:24.415 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41043/api/school/respect/person?includeRelated=false. 2026-09-16 22:59:25.507 [Test worker @coroutine#196] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-16 22:59:25.508 [Test worker @coroutine#196] INFO io.ktor.server.Application - Application started in 0.048 seconds. 2026-09-16 22:59:25.509 [DefaultDispatcher-worker-3 @coroutine#205] INFO io.ktor.server.Application - Responding at http://0.0.0.0:37281 2026-09-16 22:59:25.512 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:37281/api/school/respect/person?includeRelated=false 2026-09-16 22:59:25.512 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:37281/api/school/respect/person?includeRelated=false. 2026-09-16 22:59:25.514 [eventLoopGroupProxy-28-1 @call-handler#209] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 16, 2026 10:59:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-16 22:59:25.518 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:37281/api/school/respect/person?includeRelated=false 2026-09-16 22:59:25.518 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:37281/api/school/respect/person?includeRelated=false 2026-09-16 22:59:25.518 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:37281/api/school/respect/person?includeRelated=false 2026-09-16 22:59:25.519 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:37281/api/school/respect/person?includeRelated=false. 0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:25.421Z, stored=2026-09-16T18:59:25.565Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585165421, lastStored=1789585165565, etag=null, url=http://localhost:37281/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T18:59:25.566472190Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:25.421Z, stored=2026-09-16T18:59:25.565Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585165421, lastStored=1789585165565, etag=null, url=null, consistentThrough=2026-09-16T18:59:25.566472190Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=null, remoteState=null), remoteState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:25.421Z, stored=2026-09-16T18:59:25.459Z, metadata=null, userMasterIdentifier=null, username=null, givenName=Admin, familyName=User, middleName=null, gender=UNSPECIFIED, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SYSTEM_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null), Person(guid=42, userActive=true, status=ACTIVE, lastModified=2026-09-16T18:59:25.420Z, stored=2026-09-16T18:59:25.510Z, metadata=null, userMasterIdentifier=null, username=test, givenName=test, familyName=test, middleName=null, gender=FEMALE, preferredFirstName=null, preferredMiddleName=null, preferredLastName=null, pronouns=null, roles=[PersonRole(isPrimaryRole=true, roleEnum=SITE_ADMINISTRATOR, beginDate=null, endDate=null)], relatedPersonUids=[], dateOfBirth=null, email=null, phoneNumber=null)], metaInfo=DataLoadMetaInfo(lastModified=1789585165000, lastStored=-1, etag=null, url=http://localhost:37281/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T18:59:25.514855111Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@1530d0f2, permissionsLastModified=null), localState=null, remoteState=null)) Sep 16, 2026 10:59:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] DelegatedInvalidationPagingSource$onSrcInvalidated - RPaging/DelegatedInvalidationPagingSource(extra=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))) src invalidated 2026-09-16 22:59:25.570 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false 2026-09-16 22:59:25.570 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false. 2026-09-16 22:59:25.571 [eventLoopGroupProxy-28-1 @call-handler#216] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 16, 2026 10:59:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=2026-09-16T18:59:25.514855111Z, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-16 22:59:25.572 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false 2026-09-16 22:59:25.573 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false 2026-09-16 22:59:25.573 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false 2026-09-16 22:59:25.573 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:37281/api/school/respect/person?since=2026-09-16T18%3A59%3A25.514855111Z&includeRelated=false. Run time: 64.075447ms O2026-09-16 22:59:26.671 [Test worker @coroutine#222] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. P2026-09-16 22:59:26.673 [Test worker @coroutine#222] INFO io.ktor.server.Application - Application started in 0.04 seconds. Q2026-09-16 22:59:26.674 [DefaultDispatcher-worker-5 @coroutine#231] INFO io.ktor.server.Application - Responding at http://0.0.0.0:37605 2026-09-16 22:59:26.781 [DefaultDispatcher-worker-3 @coroutine#229] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:37605/api/school/xapi/statements 2026-09-16 22:59:26.783 [DefaultDispatcher-worker-3 @coroutine#229] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@7aa062b7 for http://localhost:37605/api/school/xapi/statements 2026-09-16 22:59:26.783 [DefaultDispatcher-worker-3 @coroutine#229] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:37605/api/school/xapi/statements from class io.ktor.http.content.TextContent 2026-09-16 22:59:26.786 [eventLoopGroupProxy-31-1 @call-handler#240] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi  /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements  /api/school/xapi/statements [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:GET)]  /api/school/xapi/statements [(method:POST)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:POST)" Routing resolve result:  SUCCESS @ /api/school/xapi/statements [(method:POST)] 2026-09-16 22:59:26.786 [eventLoopGroupProxy-31-1 @call-handler#240] TRACE i.k.server.engine.DefaultTransform - No Default Transformations found for class io.ktor.utils.io.ByteChannel and expected type TypeInfo(kotlinx.serialization.json.JsonElement) for call /api/school/xapi/statements 2026-09-16 22:59:26.797 [DefaultDispatcher-worker-5 @coroutine#229] TRACE i.k.client.plugins.HttpCallValidator - Processing exception java.io.IOException: unexpected end of stream on http://localhost:37605/... for request http://localhost:37605/api/school/xapi/statements Exception in thread "DefaultDispatcher-worker-5 @coroutine#229" java.io.IOException: unexpected end of stream on http://localhost:37605/...  at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)  at io.ktor.client.engine.okhttp.OkHttpEngine.executeHttpRequest(OkHttpEngine.kt:107)  at io.ktor.client.engine.okhttp.OkHttpEngine.execute(OkHttpEngine.kt:71)  at io.ktor.client.engine.HttpClientEngine$executeWithinCallContext$2.invokeSuspend(HttpClientEngine.kt:183)  at io.ktor.client.engine.HttpClientEngine.executeWithinCallContext(HttpClientEngine.kt:184)  at io.ktor.client.engine.HttpClientEngine$install$1.invokeSuspend(HttpClientEngine.kt:154)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.HttpSend$DefaultSender.execute(HttpSend.kt:141)  at io.ktor.client.plugins.HttpRedirectKt$HttpRedirect$2$1.invokeSuspend(HttpRedirect.kt:110)  at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52)  at io.ktor.client.plugins.HttpCallValidatorKt$HttpCallValidator$2$2.invokeSuspend(HttpCallValidator.kt:143)  at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52)  at io.ktor.client.plugins.HttpSend$Plugin$install$1.invokeSuspend(HttpSend.kt:107)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.DefaultTransformKt$defaultTransformers$1.invokeSuspend(DefaultTransform.kt:64)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invokeSuspend(KtorCallContexts.kt:88)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.RequestError$install$1.invokeSuspend(HttpCallValidator.kt:165)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invokeSuspend(HttpRequestLifecycle.kt:29)  at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend(HttpRequestLifecycle.kt:42)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.HttpClient.execute$ktor_client_core(HttpClient.kt:1420)  at io.ktor.client.statement.HttpStatement.fetchResponse(HttpStatement.kt:207)  at world.respect.datalayer.http.school.xapi.XapiStatementsResourceHttp.post(XapiStatementsResourceHttp.kt:129)  at world.respect.datalayer.repository.school.writequeue.DrainRemoteWriteQueueUseCase.invoke(DrainRemoteWriteQueueUseCase.kt:90)  at world.respect.lib.test.clientservertest.ClientServerDataSourceTestBuilder$clients$1$2.invokeSuspend(ClientServerDatasourceTest.kt:280)  Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [CoroutineId(229), "coroutine#229":StandaloneCoroutine{Cancelling}@5da0ffc1, Dispatchers.Default] Caused by: java.io.IOException: unexpected end of stream on http://localhost:37605/...  at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:252)  at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:116)  at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:97)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:98)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:232)  at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:580)  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)  at java.base/java.lang.Thread.run(Thread.java:840) Caused by: java.io.EOFException: \n not found: limit=0 content=…  at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:362)  at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:32)  at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:215)  ... 16 more 2026-09-16 22:59:28.002 [Test worker @coroutine#244] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-16 22:59:28.003 [Test worker @coroutine#244] INFO io.ktor.server.Application - Application started in 0.049 seconds. 2026-09-16 22:59:28.004 [DefaultDispatcher-worker-5 @coroutine#253] INFO io.ktor.server.Application - Responding at http://0.0.0.0:46719 2026-09-16 22:59:28.051 [Test worker @coroutine#244] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-16 22:59:28.051 [Test worker @coroutine#244] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false. 2026-09-16 22:59:28.053 [eventLoopGroupProxy-34-1 @call-handler#260] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi  /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements  /api/school/xapi/statements [(method:GET)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:GET)]  /api/school/xapi/statements [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/xapi/statements [(method:GET)] 2026-09-16 22:59:28.057 [Test worker @coroutine#244] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-16 22:59:28.057 [Test worker @coroutine#244] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-16 22:59:28.057 [Test worker @coroutine#244] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-16 22:59:28.058 [Test worker @coroutine#244] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class world.respect.lib.xapi.model.XapiStatementResult for http://localhost:46719/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false.