?zport = 39063 ?z23:09:57,412 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found logback-core version 1.6.1 ?z23:09:57,413 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4af0df05 - No custom configurators were discovered as a service. ?z23:09:57,413 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4af0df05 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator ?z23:09:57,413 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4af0df05 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator ?z23:09:57,415 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] ?z23:09:57,417 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/jenkins/.jenkins/workspace/main-offline-endtoend-test/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] ?z23:09:57,417 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@57ea113a - Resource [logback.xml] occurs multiple times on the classpath. ?z23:09:57,417 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@57ea113a - Resource [logback.xml] occurs at [file:/home/jenkins/.jenkins/workspace/main-offline-endtoend-test/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] ?z23:09:57,417 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@57ea113a - Resource [logback.xml] occurs at [jar:file:/home/jenkins/.jenkins/workspace/main-offline-endtoend-test/respect-server/build/libs/respect-server-1.0.34a.jar!/logback.xml] ?z23:09:57,466 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Scan attribute not set or set to unrecognized value. ?z23:09:57,470 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT] ?z23:09:57,470 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] ?z23:09:57,474 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property ?z23:09:57,496 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - NOTE: Writing to the console can be slow. Try to avoid logging to the ?z23:09:57,496 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - console in production environments, especially in high volume systems. ?z23:09:57,496 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also https://logback.qos.ch/codes.html#slowConsole ?z23:09:57,497 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to TRACE ?z23:09:57,497 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT] ?z23:09:57,498 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [io.netty] to INFO ?z23:09:57,498 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@acdb094 - End of configuration. ?z23:09:57,498 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@674bd420 - Registering current configuration as safe fallback point ?z23:09:57,501 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4af0df05 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 85 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY ?z ?z2026-08-26 23:09:57.658 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?zport = 36783 ?z2026-08-26 23:09:59.827 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?zport = 38853 ?z2026-08-26 23:10:00.889 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z2026-08-26 23:10:02.121 [Test worker @coroutine#62] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z2026-08-26 23:10:02.129 [Test worker @coroutine#62] INFO io.ktor.server.Application - Application started in 0.107 seconds. ?z2026-08-26 23:10:02.131 [DefaultDispatcher-worker-5 @coroutine#71] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36367 ?z2026-08-26 23:10:02.141 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36367/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:02.141 [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:36367/api/school/respect/schoolpermissiongrant. ?z2026-08-26 23:10:02.146 [eventLoopGroupProxy-13-1 @call-handler#74] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person ?z /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant ?z /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?z2026-08-26 23:10:02.163 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36367/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:02.163 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36367/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:02.163 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36367/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:02.165 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36367/api/school/respect/schoolpermissiongrant. ?z2026-08-26 23:10:02.237 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:02.238 [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:36367/api/school/respect/person?includeRelated=false. ?z2026-08-26 23:10:02.240 [eventLoopGroupProxy-13-1 @call-handler#80] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/person [(method:GET)] ?z2026-08-26 23:10:02.262 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:02.262 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:02.263 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:02.264 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36367/api/school/respect/person?includeRelated=false. ?z2026-08-26 23:10:02.272 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:02.272 [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:36367/api/school/respect/person?includeRelated=false. ?z!2026-08-26 23:10:02.274 [eventLoopGroupProxy-13-1 @call-handler#86] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z!/, segment:0 -> SUCCESS @ / ?z! /api, segment:1 -> SUCCESS @ /api ?z" /api/school, segment:2 -> SUCCESS @ /api/school ?z" /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z" /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z" /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z" /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z" /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ?z"Matched routes: ?z" "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z"Routing resolve result: ?z" SUCCESS @ /api/school/respect/person [(method:GET)] ?z#2026-08-26 23:10:02.276 [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]. ?z$2026-08-26 23:10:02.277 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36367/api/school/respect/person?includeRelated=false ?z$2026-08-26 23:10:02.277 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36367/api/school/respect/person?includeRelated=false ?z$2026-08-26 23:10:02.277 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36367/api/school/respect/person?includeRelated=false ?z2026-08-26 23:10:03.404 [Test worker @coroutine#90] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z2026-08-26 23:10:03.405 [Test worker @coroutine#90] INFO io.ktor.server.Application - Application started in 0.048 seconds. ?z2026-08-26 23:10:03.407 [DefaultDispatcher-worker-1 @coroutine#99] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41415 ?z2026-08-26 23:10:03.408 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41415/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:03.408 [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:41415/api/school/respect/schoolpermissiongrant. ?z2026-08-26 23:10:03.411 [eventLoopGroupProxy-16-1 @call-handler#102] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person ?z /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant ?z /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?z2026-08-26 23:10:03.413 [Test worker @coroutine#90] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41415/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:03.413 [Test worker @coroutine#90] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41415/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:03.414 [Test worker @coroutine#90] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41415/api/school/respect/schoolpermissiongrant ?z2026-08-26 23:10:03.414 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41415/api/school/respect/schoolpermissiongrant. ?z2026-08-26 23:10:03.464 [DefaultDispatcher-worker-5 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 ?z2026-08-26 23:10:03.464 [DefaultDispatcher-worker-5 @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:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. ?z2026-08-26 23:10:03.467 [eventLoopGroupProxy-16-1 @call-handler#112] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/person [(method:GET)] ?z2026-08-26 23:10:03.471 [DefaultDispatcher-worker-4 @coroutine#108] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 ?z2026-08-26 23:10:03.471 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 ?z2026-08-26 23:10:03.471 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 ?z2026-08-26 23:10:03.473 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. ?z2026-08-26 23:10:04.575 [Test worker @coroutine#117] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z2026-08-26 23:10:04.575 [Test worker @coroutine#117] INFO io.ktor.server.Application - Application started in 0.039 seconds. ?z!2026-08-26 23:10:04.577 [DefaultDispatcher-worker-3 @coroutine#126] INFO io.ktor.server.Application - Responding at http://0.0.0.0:40273 ?z$2026-08-26 23:10:04.580 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40273/api/school/respect/person?includeRelated=false ?z$2026-08-26 23:10:04.580 [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:40273/api/school/respect/person?includeRelated=false. ?z&2026-08-26 23:10:04.582 [eventLoopGroupProxy-19-1 @call-handler#130] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z&/, segment:0 -> SUCCESS @ / ?z& /api, segment:1 -> SUCCESS @ /api ?z& /api/school, segment:2 -> SUCCESS @ /api/school ?z& /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z& /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z& /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z& /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z&Matched routes: ?z& "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z&Routing resolve result: ?z& SUCCESS @ /api/school/respect/person [(method:GET)] ?z)2026-08-26 23:10:04.585 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40273/api/school/respect/person?includeRelated=false ?z)2026-08-26 23:10:04.585 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40273/api/school/respect/person?includeRelated=false ?z)2026-08-26 23:10:04.585 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40273/api/school/respect/person?includeRelated=false ?z*2026-08-26 23:10:04.586 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40273/api/school/respect/person?includeRelated=false. ?zY0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:04.485Z, stored=2026-08-26T19:10:04.623Z, 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=1787771404485, lastStored=1787771404623, etag=null, url=http://localhost:40273/api/school/respect/person?includeRelated=false, consistentThrough=2026-08-26T19:10:04.624473620Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:04.485Z, stored=2026-08-26T19:10:04.623Z, 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=1787771404485, lastStored=1787771404623, etag=null, url=null, consistentThrough=2026-08-26T19:10:04.624473620Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=null, remoteState=null), remoteState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:04.485Z, stored=2026-08-26T19:10:04.535Z, 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-08-26T19:10:04.484Z, stored=2026-08-26T19:10:04.577Z, 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=1787771404000, lastStored=-1, etag=null, url=http://localhost:40273/api/school/respect/person?includeRelated=false, consistentThrough=2026-08-26T19:10:04.582862340Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@95cecc5, permissionsLastModified=null), localState=null, remoteState=null)) ?z[2026-08-26 23:10:04.635 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false ?z[2026-08-26 23:10:04.635 [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:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false. ?z]2026-08-26 23:10:04.637 [eventLoopGroupProxy-19-1 @call-handler#136] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z]/, segment:0 -> SUCCESS @ / ?z] /api, segment:1 -> SUCCESS @ /api ?z] /api/school, segment:2 -> SUCCESS @ /api/school ?z] /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z] /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z] /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z] /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z]Matched routes: ?z] "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z]Routing resolve result: ?z] SUCCESS @ /api/school/respect/person [(method:GET)] ?z^2026-08-26 23:10:04.638 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false ?z^2026-08-26 23:10:04.638 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false ?z^2026-08-26 23:10:04.638 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false ?z_2026-08-26 23:10:04.639 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40273/api/school/respect/person?since=2026-08-26T19%3A10%3A04.582862340Z&includeRelated=false. ?z`Run time: 62.050793ms ?zŤ2026-08-26 23:10:05.731 [Test worker @coroutine#142] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?zŤ2026-08-26 23:10:05.732 [Test worker @coroutine#142] INFO io.ktor.server.Application - Application started in 0.038 seconds. ?zŦ2026-08-26 23:10:05.734 [DefaultDispatcher-worker-5 @coroutine#151] INFO io.ktor.server.Application - Responding at http://0.0.0.0:43227 ?z2026-08-26 23:10:05.776 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43227/api/school/respect/person ?z2026-08-26 23:10:05.776 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@44493746 for http://localhost:43227/api/school/respect/person ?z2026-08-26 23:10:05.776 [DefaultDispatcher-worker-5 @coroutine#149] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:43227/api/school/respect/person from class io.ktor.http.content.TextContent ?z2026-08-26 23:10:05.779 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z /api/school/respect/person [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:GET)] ?z /api/school/respect/person [(method:POST)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:POST)] ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "person" -> "(method:POST)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/person [(method:POST)] ?z2026-08-26 23:10:05.782 [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 ?z2026-08-26 23:10:05.784 [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]. ?z2026-08-26 23:10:05.784 [DefaultDispatcher-worker-1 @coroutine#149] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:43227/api/school/respect/person ?z2026-08-26 23:10:05.784 [DefaultDispatcher-worker-1 @coroutine#149] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:43227/api/school/respect/person ?z2026-08-26 23:10:05.784 [DefaultDispatcher-worker-1 @coroutine#149] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:43227/api/school/respect/person ?z,2026-08-26 23:10:06.892 [Test worker @coroutine#165] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z-2026-08-26 23:10:06.893 [Test worker @coroutine#165] INFO io.ktor.server.Application - Application started in 0.052 seconds. ?z/2026-08-26 23:10:06.895 [DefaultDispatcher-worker-1 @coroutine#174] INFO io.ktor.server.Application - Responding at http://0.0.0.0:42307 ?z02026-08-26 23:10:06.896 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42307/api/school/respect/schoolpermissiongrant ?z02026-08-26 23:10:06.896 [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:42307/api/school/respect/schoolpermissiongrant. ?z22026-08-26 23:10:06.898 [eventLoopGroupProxy-25-1 @call-handler#177] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] ?z2/, segment:0 -> SUCCESS @ / ?z2 /api, segment:1 -> SUCCESS @ /api ?z2 /api/school, segment:2 -> SUCCESS @ /api/school ?z2 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z2 /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person ?z2 /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant ?z2 /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?z2Matched routes: ?z2 "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" ?z2Routing resolve result: ?z2 SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] ?z42026-08-26 23:10:06.900 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42307/api/school/respect/schoolpermissiongrant ?z42026-08-26 23:10:06.900 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42307/api/school/respect/schoolpermissiongrant ?z42026-08-26 23:10:06.900 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42307/api/school/respect/schoolpermissiongrant ?z42026-08-26 23:10:06.900 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42307/api/school/respect/schoolpermissiongrant. ?z]2026-08-26 23:10:06.941 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42307/api/school/respect/person?includeRelated=false ?z^2026-08-26 23:10:06.942 [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:42307/api/school/respect/person?includeRelated=false. ?z_2026-08-26 23:10:06.943 [eventLoopGroupProxy-25-1 @call-handler#183] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z_/, segment:0 -> SUCCESS @ / ?z_ /api, segment:1 -> SUCCESS @ /api ?z_ /api/school, segment:2 -> SUCCESS @ /api/school ?z_ /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z_ /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z_ /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z_ /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z_ /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ?z_Matched routes: ?z_ "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z_Routing resolve result: ?z_ SUCCESS @ /api/school/respect/person [(method:GET)] ?zbAug 26, 2026 11:10:06 PM io.github.aakira.napier.DebugAntilog performLog ?zbFINE: [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) ?zd2026-08-26 23:10:06.948 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42307/api/school/respect/person?includeRelated=false ?zd2026-08-26 23:10:06.949 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42307/api/school/respect/person?includeRelated=false ?ze2026-08-26 23:10:06.949 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42307/api/school/respect/person?includeRelated=false ?ze2026-08-26 23:10:06.949 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42307/api/school/respect/person?includeRelated=false. ?z9Aug 26, 2026 11:10:08 PM io.github.aakira.napier.DebugAntilog performLog ?z9FINE: [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 ?z:Aug 26, 2026 11:10:08 PM io.github.aakira.napier.DebugAntilog performLog ?z:FINE: [DEBUG] HttpRequestBuilderExtKt$addCacheValidationHeaders - addCacheValidationHeaders = If-Modified-Since = Wed, 26 Aug 2026 19:10:06 GMT for http://localhost:42307/api/school/respect/person?includeRelated=false ?z:2026-08-26 23:10:08.954 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42307/api/school/respect/person?includeRelated=false ?z:2026-08-26 23:10:08.954 [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:42307/api/school/respect/person?includeRelated=false. ?z;2026-08-26 23:10:08.956 [eventLoopGroupProxy-25-1 @call-handler#190] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z;/, segment:0 -> SUCCESS @ / ?z; /api, segment:1 -> SUCCESS @ /api ?z; /api/school, segment:2 -> SUCCESS @ /api/school ?z; /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z; /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z; /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z; /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z; /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant ?z;Matched routes: ?z; "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z;Routing resolve result: ?z; SUCCESS @ /api/school/respect/person [(method:GET)] ?z<Aug 26, 2026 11:10:08 PM io.github.aakira.napier.DebugAntilog performLog ?z<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) ?z>2026-08-26 23:10:08.958 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42307/api/school/respect/person?includeRelated=false ?z>2026-08-26 23:10:08.958 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42307/api/school/respect/person?includeRelated=false ?z>2026-08-26 23:10:08.958 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42307/api/school/respect/person?includeRelated=false ?z>2026-08-26 23:10:08.959 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42307/api/school/respect/person?includeRelated=false. ?z֎2026-08-26 23:10:10.062 [Test worker @coroutine#196] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z֏2026-08-26 23:10:10.063 [Test worker @coroutine#196] INFO io.ktor.server.Application - Application started in 0.037 seconds. ?z֐2026-08-26 23:10:10.064 [DefaultDispatcher-worker-1 @coroutine#205] INFO io.ktor.server.Application - Responding at http://0.0.0.0:43845 ?z֒2026-08-26 23:10:10.067 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43845/api/school/respect/person?includeRelated=false ?z֓2026-08-26 23:10:10.067 [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:43845/api/school/respect/person?includeRelated=false. ?z֕2026-08-26 23:10:10.069 [eventLoopGroupProxy-28-1 @call-handler#209] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z֕/, segment:0 -> SUCCESS @ / ?z֕ /api, segment:1 -> SUCCESS @ /api ?z֕ /api/school, segment:2 -> SUCCESS @ /api/school ?z֕ /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z֕ /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z֕ /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z֕ /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?z֕Matched routes: ?z֕ "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?z֕Routing resolve result: ?z֕ SUCCESS @ /api/school/respect/person [(method:GET)] ?z֕Aug 26, 2026 11:10:10 PM io.github.aakira.napier.DebugAntilog performLog ?z֕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) ?z֙2026-08-26 23:10:10.073 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:43845/api/school/respect/person?includeRelated=false ?z֙2026-08-26 23:10:10.073 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:43845/api/school/respect/person?includeRelated=false ?z֙2026-08-26 23:10:10.073 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:43845/api/school/respect/person?includeRelated=false ?z֚2026-08-26 23:10:10.074 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:43845/api/school/respect/person?includeRelated=false. ?z0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:09.965Z, stored=2026-08-26T19:10:10.111Z, 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=1787771409965, lastStored=1787771410111, etag=null, url=http://localhost:43845/api/school/respect/person?includeRelated=false, consistentThrough=2026-08-26T19:10:10.112023775Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:09.965Z, stored=2026-08-26T19:10:10.111Z, 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=1787771409965, lastStored=1787771410111, etag=null, url=null, consistentThrough=2026-08-26T19:10:10.112023775Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=null, remoteState=null), remoteState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-08-26T19:10:09.965Z, stored=2026-08-26T19:10:10.025Z, 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-08-26T19:10:09.963Z, stored=2026-08-26T19:10:10.065Z, 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=1787771410000, lastStored=-1, etag=null, url=http://localhost:43845/api/school/respect/person?includeRelated=false, consistentThrough=2026-08-26T19:10:10.069963513Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@780ee3ad, permissionsLastModified=null), localState=null, remoteState=null)) ?zAug 26, 2026 11:10:10 PM io.github.aakira.napier.DebugAntilog performLog ?zFINE: [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 ?z2026-08-26 23:10:10.115 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false ?z2026-08-26 23:10:10.115 [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:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false. ?z2026-08-26 23:10:10.116 [eventLoopGroupProxy-28-1 @call-handler#216] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ?z/, segment:0 -> SUCCESS @ / ?z /api, segment:1 -> SUCCESS @ /api ?z /api/school, segment:2 -> SUCCESS @ /api/school ?z /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ?z /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ?z /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ?z /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ?zMatched routes: ?z "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" ?zRouting resolve result: ?z SUCCESS @ /api/school/respect/person [(method:GET)] ?zAug 26, 2026 11:10:10 PM io.github.aakira.napier.DebugAntilog performLog ?zFINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=2026-08-26T19:10:10.069963513Z, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) ?z2026-08-26 23:10:10.118 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false ?z2026-08-26 23:10:10.118 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false ?z2026-08-26 23:10:10.118 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false ?z2026-08-26 23:10:10.119 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:43845/api/school/respect/person?since=2026-08-26T19%3A10%3A10.069963513Z&includeRelated=false. ?zRun time: 54.524949ms ?z2026-08-26 23:10:11.204 [Test worker @coroutine#222] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z2026-08-26 23:10:11.205 [Test worker @coroutine#222] INFO io.ktor.server.Application - Application started in 0.041 seconds. ?z2026-08-26 23:10:11.206 [DefaultDispatcher-worker-5 @coroutine#232] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36539 ?z2026-08-26 23:10:11.208 [Test worker @coroutine#222] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d ?z2026-08-26 23:10:11.208 [Test worker @coroutine#222] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d. ?z 2026-08-26 23:10:11.211 [eventLoopGroupProxy-31-1 @call-handler#235] TRACE io.ktor.server.routing.Routing - Trace for [playlist, 5a2d8816-848a-4def-826d-b682fefbe58d] ?z /, segment:0 -> SUCCESS @ / ?z /playlist, segment:1 -> SUCCESS @ /playlist ?z  /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[5a2d8816-848a-4def-826d-b682fefbe58d]] @ /playlist/{uuid} ?z  /playlist/{uuid} [(method:GET)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:GET)] ?z  /playlist/{uuid} [(method:POST)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:POST)] ?z Matched routes: ?z "" -> "playlist" -> "{uuid}" -> "(method:GET)" ?z Routing resolve result: ?z  SUCCESS; Parameters [uuid=[5a2d8816-848a-4def-826d-b682fefbe58d]] @ /playlist/{uuid} [(method:GET)] ?z2026-08-26 23:10:11.217 [Test worker @coroutine#222] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d ?z2026-08-26 23:10:11.217 [Test worker @coroutine#222] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d ?z2026-08-26 23:10:11.217 [Test worker @coroutine#222] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d ?z2026-08-26 23:10:11.217 [Test worker @coroutine#222] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class world.respect.lib.opds.model.OpdsFeed for http://localhost:36539/playlist/5a2d8816-848a-4def-826d-b682fefbe58d. ?z߄2026-08-26 23:10:12.356 [Test worker @coroutine#239] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z߅2026-08-26 23:10:12.357 [Test worker @coroutine#239] INFO io.ktor.server.Application - Application started in 0.038 seconds. ?z߆2026-08-26 23:10:12.358 [DefaultDispatcher-worker-3 @coroutine#248] INFO io.ktor.server.Application - Responding at http://0.0.0.0:38381 ?z߭2026-08-26 23:10:12.397 [DefaultDispatcher-worker-1 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z߭2026-08-26 23:10:12.397 [DefaultDispatcher-worker-1 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@7845b57a for http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z߭2026-08-26 23:10:12.398 [DefaultDispatcher-worker-1 @coroutine#246] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 from class io.ktor.http.content.TextContent ?z߯2026-08-26 23:10:12.399 [eventLoopGroupProxy-34-1 @call-handler#255] TRACE io.ktor.server.routing.Routing - Trace for [playlist, 95ce98c4-a11e-42d3-a268-5bec6c025da7] ?z߯/, segment:0 -> SUCCESS @ / ?z߯ /playlist, segment:1 -> SUCCESS @ /playlist ?z߯ /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[95ce98c4-a11e-42d3-a268-5bec6c025da7]] @ /playlist/{uuid} ?z߯ /playlist/{uuid} [(method:GET)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:GET)] ?z߯ /playlist/{uuid} [(method:POST)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:POST)] ?z߯Matched routes: ?z߯ "" -> "playlist" -> "{uuid}" -> "(method:POST)" ?z߯Routing resolve result: ?z߯ SUCCESS; Parameters [uuid=[95ce98c4-a11e-42d3-a268-5bec6c025da7]] @ /playlist/{uuid} [(method:POST)] ?z߰2026-08-26 23:10:12.400 [eventLoopGroupProxy-34-1 @call-handler#255] TRACE i.k.server.engine.DefaultTransform - No Default Transformations found for class io.ktor.utils.io.ByteChannel and expected type TypeInfo(world.respect.lib.opds.model.OpdsFeed) for call /playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z߱2026-08-26 23:10:12.401 [eventLoopGroupProxy-34-1 @call-handler#255] TRACE i.k.s.p.c.ContentNegotiation - Skipping response body transformation from HttpStatusCode to OutgoingContent for the POST /playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 request because the HttpStatusCode type is ignored. See [ContentNegotiationConfig::ignoreType]. ?z߱2026-08-26 23:10:12.401 [DefaultDispatcher-worker-4 @coroutine#246] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z߱2026-08-26 23:10:12.401 [DefaultDispatcher-worker-4 @coroutine#246] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z߱2026-08-26 23:10:12.401 [DefaultDispatcher-worker-4 @coroutine#246] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:38381/playlist/95ce98c4-a11e-42d3-a268-5bec6c025da7 ?z 2026-08-26 23:10:13.515 [Test worker @coroutine#260] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z 2026-08-26 23:10:13.517 [Test worker @coroutine#260] INFO io.ktor.server.Application - Application started in 0.039 seconds. ?z2026-08-26 23:10:13.518 [DefaultDispatcher-worker-5 @coroutine#269] INFO io.ktor.server.Application - Responding at http://0.0.0.0:43239 ?z^2026-08-26 23:10:13.598 [DefaultDispatcher-worker-4 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43239/api/school/xapi/statements ?z_2026-08-26 23:10:13.599 [DefaultDispatcher-worker-4 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@48e992b2 for http://localhost:43239/api/school/xapi/statements ?z_2026-08-26 23:10:13.599 [DefaultDispatcher-worker-4 @coroutine#267] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:43239/api/school/xapi/statements from class io.ktor.http.content.TextContent ?za2026-08-26 23:10:13.602 [eventLoopGroupProxy-37-1 @call-handler#278] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] ?zb/, segment:0 -> SUCCESS @ / ?zb /api, segment:1 -> SUCCESS @ /api ?zb /api/school, segment:2 -> SUCCESS @ /api/school ?zb /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi ?zb /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements ?zb /api/school/xapi/statements [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:GET)] ?zb /api/school/xapi/statements [(method:POST)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:POST)] ?zbMatched routes: ?zb "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:POST)" ?zbRouting resolve result: ?zb SUCCESS @ /api/school/xapi/statements [(method:POST)] ?zb2026-08-26 23:10:13.602 [eventLoopGroupProxy-37-1 @call-handler#278] 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 ?zn2026-08-26 23:10:13.614 [DefaultDispatcher-worker-3 @coroutine#267] TRACE i.k.client.plugins.HttpCallValidator - Processing exception java.io.IOException: unexpected end of stream on http://localhost:43239/... for request http://localhost:43239/api/school/xapi/statements ?zqException in thread "DefaultDispatcher-worker-3 @coroutine#267" java.io.IOException: unexpected end of stream on http://localhost:43239/... ?zq at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42) ?zq at io.ktor.client.engine.okhttp.OkHttpEngine.executeHttpRequest(OkHttpEngine.kt:107) ?zq at io.ktor.client.engine.okhttp.OkHttpEngine.execute(OkHttpEngine.kt:71) ?zq at io.ktor.client.engine.HttpClientEngine$executeWithinCallContext$2.invokeSuspend(HttpClientEngine.kt:183) ?zq at io.ktor.client.engine.HttpClientEngine.executeWithinCallContext(HttpClientEngine.kt:184) ?zq at io.ktor.client.engine.HttpClientEngine$install$1.invokeSuspend(HttpClientEngine.kt:154) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.plugins.HttpSend$DefaultSender.execute(HttpSend.kt:141) ?zq at io.ktor.client.plugins.HttpRedirectKt$HttpRedirect$2$1.invokeSuspend(HttpRedirect.kt:110) ?zq at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52) ?zq at io.ktor.client.plugins.HttpCallValidatorKt$HttpCallValidator$2$2.invokeSuspend(HttpCallValidator.kt:143) ?zq at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52) ?zq at io.ktor.client.plugins.HttpSend$Plugin$install$1.invokeSuspend(HttpSend.kt:107) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.plugins.DefaultTransformKt$defaultTransformers$1.invokeSuspend(DefaultTransform.kt:64) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invokeSuspend(KtorCallContexts.kt:88) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.plugins.RequestError$install$1.invokeSuspend(HttpCallValidator.kt:165) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invokeSuspend(HttpRequestLifecycle.kt:29) ?zq at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend(HttpRequestLifecycle.kt:42) ?zq at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) ?zq at io.ktor.client.HttpClient.execute$ktor_client_core(HttpClient.kt:1420) ?zq at io.ktor.client.statement.HttpStatement.fetchResponse(HttpStatement.kt:207) ?zq at world.respect.datalayer.http.school.xapi.XapiStatementsResourceHttp.post(XapiStatementsResourceHttp.kt:129) ?zq at world.respect.datalayer.repository.school.writequeue.DrainRemoteWriteQueueUseCase.invoke(DrainRemoteWriteQueueUseCase.kt:90) ?zq at world.respect.lib.test.clientservertest.ClientServerDataSourceTestBuilder$clients$1$2.invokeSuspend(ClientServerDatasourceTest.kt:280) ?zq Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [CoroutineId(267), "coroutine#267":StandaloneCoroutine{Cancelling}@37eb6c81, Dispatchers.Default] ?zqCaused by: java.io.IOException: unexpected end of stream on http://localhost:43239/... ?zq at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:252) ?zq at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:116) ?zq at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:97) ?zq at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) ?zq at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34) ?zq at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) ?zq at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:98) ?zq at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) ?zq at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) ?zq at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) ?zr at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72) ?zr at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) ?zr at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:232) ?zr at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:580) ?zr at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ?zr at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ?zr at java.base/java.lang.Thread.run(Thread.java:840) ?zrCaused by: java.io.EOFException: \n not found: limit=0 content=… ?zr at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:362) ?zr at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:32) ?zr at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:215) ?zr ... 16 more ?z 2026-08-26 23:10:14.793 [Test worker @coroutine#282] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ?z 2026-08-26 23:10:14.794 [Test worker @coroutine#282] INFO io.ktor.server.Application - Application started in 0.038 seconds. ?z 2026-08-26 23:10:14.795 [DefaultDispatcher-worker-4 @coroutine#291] INFO io.ktor.server.Application - Responding at http://0.0.0.0:40701 ?z82026-08-26 23:10:14.840 [Test worker @coroutine#282] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false ?z82026-08-26 23:10:14.841 [Test worker @coroutine#282] TRACE i.k.c.p.c.ContentNegotiation - Body type class io.ktor.client.utils.EmptyContent is in ignored types. Skipping ContentNegotiation for http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false. ?z;2026-08-26 23:10:14.843 [eventLoopGroupProxy-40-1 @call-handler#298] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] ?z;/, segment:0 -> SUCCESS @ / ?z; /api, segment:1 -> SUCCESS @ /api ?z; /api/school, segment:2 -> SUCCESS @ /api/school ?z; /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi ?z; /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements ?z; /api/school/xapi/statements [(method:GET)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:GET)] ?z; /api/school/xapi/statements [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:POST)] ?z;Matched routes: ?z; "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:GET)" ?z;Routing resolve result: ?z; SUCCESS @ /api/school/xapi/statements [(method:GET)] ?z>2026-08-26 23:10:14.846 [Test worker @coroutine#282] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false ?z>2026-08-26 23:10:14.846 [Test worker @coroutine#282] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false ?z>2026-08-26 23:10:14.846 [Test worker @coroutine#282] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false ?z?2026-08-26 23:10:14.847 [Test worker @coroutine#282] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class world.respect.lib.xapi.model.XapiStatementResult for http://localhost:40701/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false.