1ӯport = 36017 121:09:24,541 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found logback-core version 1.6.1 121:09:24,542 |-INFO in ch.qos.logback.classic.util.ContextInitializer@54c62d71 - No custom configurators were discovered as a service. 121:09:24,542 |-INFO in ch.qos.logback.classic.util.ContextInitializer@54c62d71 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator 121:09:24,542 |-INFO in ch.qos.logback.classic.util.ContextInitializer@54c62d71 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator 121:09:24,544 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 121:09:24,545 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/jenkins/.jenkins/workspace/RESPECT-end-to-end/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] 121:09:24,545 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@65045a87 - Resource [logback.xml] occurs multiple times on the classpath. 121:09:24,545 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@65045a87 - Resource [logback.xml] occurs at [file:/home/jenkins/.jenkins/workspace/RESPECT-end-to-end/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] 121:09:24,545 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@65045a87 - Resource [logback.xml] occurs at [jar:file:/home/jenkins/.jenkins/workspace/RESPECT-end-to-end/respect-server/build/libs/respect-server-1.0.45.jar!/logback.xml] 121:09:24,599 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Scan attribute not set or set to unrecognized value. 121:09:24,602 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT] 121:09:24,602 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 121:09:24,605 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 121:09:24,621 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - NOTE: Writing to the console can be slow. Try to avoid logging to the 121:09:24,621 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - console in production environments, especially in high volume systems. 121:09:24,621 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also https://logback.qos.ch/codes.html#slowConsole 121:09:24,621 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to TRACE 121:09:24,622 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT] 121:09:24,622 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [io.netty] to INFO 121:09:24,622 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@47f4e407 - End of configuration. 121:09:24,622 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@2d1dee39 - Registering current configuration as safe fallback point 121:09:24,624 |-INFO in ch.qos.logback.classic.util.ContextInitializer@54c62d71 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 81 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY 1 1ԏ2026-09-16 21:09:24.750 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 1ܓport = 39475 1ܔ2026-09-16 21:09:26.804 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 1port = 34387 12026-09-16 21:09:27.865 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 12026-09-16 21:09:29.128 [Test worker @coroutine#62] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 12026-09-16 21:09:29.135 [Test worker @coroutine#62] INFO io.ktor.server.Application - Application started in 0.106 seconds. 12026-09-16 21:09:29.137 [DefaultDispatcher-worker-4 @coroutine#71] INFO io.ktor.server.Application - Responding at http://0.0.0.0:42913 12026-09-16 21:09:29.146 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42913/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:29.147 [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:42913/api/school/respect/schoolpermissiongrant. 12026-09-16 21:09:29.151 [eventLoopGroupProxy-13-1 @call-handler#74] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person 1 /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant 1 /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 12026-09-16 21:09:29.165 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42913/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:29.165 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42913/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:29.166 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42913/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:29.168 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42913/api/school/respect/schoolpermissiongrant. 12026-09-16 21:09:29.231 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42913/api/school/respect/person?includeRelated=false 12026-09-16 21:09:29.232 [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:42913/api/school/respect/person?includeRelated=false. 12026-09-16 21:09:29.233 [eventLoopGroupProxy-13-1 @call-handler#80] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1 /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1 /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1 /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/person [(method:GET)] 1%2026-09-16 21:09:29.253 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42913/api/school/respect/person?includeRelated=false 1%2026-09-16 21:09:29.254 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42913/api/school/respect/person?includeRelated=false 1%2026-09-16 21:09:29.254 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42913/api/school/respect/person?includeRelated=false 1'2026-09-16 21:09:29.255 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:42913/api/school/respect/person?includeRelated=false. 1,2026-09-16 21:09:29.260 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42913/api/school/respect/person?includeRelated=false 1,2026-09-16 21:09:29.260 [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:42913/api/school/respect/person?includeRelated=false. 1-2026-09-16 21:09:29.262 [eventLoopGroupProxy-13-1 @call-handler#86] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1-/, segment:0 -> SUCCESS @ / 1- /api, segment:1 -> SUCCESS @ /api 1- /api/school, segment:2 -> SUCCESS @ /api/school 1- /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1- /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1- /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1- /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1- /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant 1-Matched routes: 1- "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1.Routing resolve result: 1. SUCCESS @ /api/school/respect/person [(method:GET)] 1/2026-09-16 21:09:29.263 [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]. 1/2026-09-16 21:09:29.264 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42913/api/school/respect/person?includeRelated=false 1/2026-09-16 21:09:29.264 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42913/api/school/respect/person?includeRelated=false 1/2026-09-16 21:09:29.264 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42913/api/school/respect/person?includeRelated=false 12026-09-16 21:09:30.376 [Test worker @coroutine#90] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 12026-09-16 21:09:30.377 [Test worker @coroutine#90] INFO io.ktor.server.Application - Application started in 0.038 seconds. 12026-09-16 21:09:30.379 [DefaultDispatcher-worker-1 @coroutine#99] INFO io.ktor.server.Application - Responding at http://0.0.0.0:34415 12026-09-16 21:09:30.379 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:34415/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:30.379 [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:34415/api/school/respect/schoolpermissiongrant. 12026-09-16 21:09:30.382 [eventLoopGroupProxy-16-1 @call-handler#102] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person 1 /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant 1 /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 12026-09-16 21:09:30.384 [Test worker @coroutine#90] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:34415/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:30.384 [Test worker @coroutine#90] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:34415/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:30.384 [Test worker @coroutine#90] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:34415/api/school/respect/schoolpermissiongrant 12026-09-16 21:09:30.384 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:34415/api/school/respect/schoolpermissiongrant. 12026-09-16 21:09:30.432 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 12026-09-16 21:09:30.432 [DefaultDispatcher-worker-4 @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:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. 12026-09-16 21:09:30.433 [eventLoopGroupProxy-16-1 @call-handler#112] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1 /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1 /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1 /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/person [(method:GET)] 12026-09-16 21:09:30.437 [DefaultDispatcher-worker-3 @coroutine#108] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 12026-09-16 21:09:30.437 [DefaultDispatcher-worker-3 @coroutine#108] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 12026-09-16 21:09:30.437 [DefaultDispatcher-worker-3 @coroutine#108] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 12026-09-16 21:09:30.438 [DefaultDispatcher-worker-3 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:34415/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. 12026-09-16 21:09:31.551 [Test worker @coroutine#117] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 12026-09-16 21:09:31.552 [Test worker @coroutine#117] INFO io.ktor.server.Application - Application started in 0.038 seconds. 1 2026-09-16 21:09:31.553 [DefaultDispatcher-worker-5 @coroutine#126] INFO io.ktor.server.Application - Responding at http://0.0.0.0:40409 1#2026-09-16 21:09:31.556 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40409/api/school/respect/person?includeRelated=false 1#2026-09-16 21:09:31.556 [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:40409/api/school/respect/person?includeRelated=false. 1%2026-09-16 21:09:31.558 [eventLoopGroupProxy-19-1 @call-handler#130] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1%/, segment:0 -> SUCCESS @ / 1% /api, segment:1 -> SUCCESS @ /api 1% /api/school, segment:2 -> SUCCESS @ /api/school 1% /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1% /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1% /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1% /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1%Matched routes: 1% "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1%Routing resolve result: 1% SUCCESS @ /api/school/respect/person [(method:GET)] 1)2026-09-16 21:09:31.561 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40409/api/school/respect/person?includeRelated=false 1)2026-09-16 21:09:31.562 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40409/api/school/respect/person?includeRelated=false 1)2026-09-16 21:09:31.562 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40409/api/school/respect/person?includeRelated=false 1*2026-09-16 21:09:31.562 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40409/api/school/respect/person?includeRelated=false. 1`0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T17:09:31.447Z, stored=2026-09-16T17:09:31.608Z, 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=1789578571447, lastStored=1789578571608, etag=null, url=http://localhost:40409/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T17:09:31.608970065Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T17:09:31.447Z, stored=2026-09-16T17:09:31.608Z, 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=1789578571447, lastStored=1789578571608, etag=null, url=null, consistentThrough=2026-09-16T17:09:31.608970065Z, 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-16T17:09:31.447Z, stored=2026-09-16T17:09:31.513Z, 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-16T17:09:31.445Z, stored=2026-09-16T17:09:31.554Z, 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=1789578571000, lastStored=-1, etag=null, url=http://localhost:40409/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T17:09:31.559015604Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@29c244e, permissionsLastModified=null), localState=null, remoteState=null)) 1b2026-09-16 21:09:31.619 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false 1b2026-09-16 21:09:31.619 [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:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false. 1c2026-09-16 21:09:31.620 [eventLoopGroupProxy-19-1 @call-handler#136] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1d/, segment:0 -> SUCCESS @ / 1d /api, segment:1 -> SUCCESS @ /api 1d /api/school, segment:2 -> SUCCESS @ /api/school 1d /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1d /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1d /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1d /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1dMatched routes: 1d "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1dRouting resolve result: 1d SUCCESS @ /api/school/respect/person [(method:GET)] 1e2026-09-16 21:09:31.622 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false 1e2026-09-16 21:09:31.622 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false 1e2026-09-16 21:09:31.622 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false 1f2026-09-16 21:09:31.622 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40409/api/school/respect/person?since=2026-09-16T17%3A09%3A31.559015604Z&includeRelated=false. 1fRun time: 69.296457ms 12026-09-16 21:09:32.731 [Test worker @coroutine#142] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 12026-09-16 21:09:32.732 [Test worker @coroutine#142] INFO io.ktor.server.Application - Application started in 0.039 seconds. 12026-09-16 21:09:32.733 [DefaultDispatcher-worker-4 @coroutine#151] INFO io.ktor.server.Application - Responding at http://0.0.0.0:44771 12026-09-16 21:09:32.778 [DefaultDispatcher-worker-1 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:44771/api/school/respect/person 12026-09-16 21:09:32.778 [DefaultDispatcher-worker-1 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@19a17c17 for http://localhost:44771/api/school/respect/person 12026-09-16 21:09:32.778 [DefaultDispatcher-worker-1 @coroutine#149] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:44771/api/school/respect/person from class io.ktor.http.content.TextContent 12026-09-16 21:09:32.782 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1 /api/school/respect/person [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:GET)] 1 /api/school/respect/person [(method:POST)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:POST)] 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:POST)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/person [(method:POST)] 12026-09-16 21:09:32.785 [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 12026-09-16 21:09:32.787 [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]. 12026-09-16 21:09:32.787 [DefaultDispatcher-worker-4 @coroutine#149] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:44771/api/school/respect/person 12026-09-16 21:09:32.787 [DefaultDispatcher-worker-4 @coroutine#149] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:44771/api/school/respect/person 12026-09-16 21:09:32.787 [DefaultDispatcher-worker-4 @coroutine#149] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:44771/api/school/respect/person 192026-09-16 21:09:33.882 [Test worker @coroutine#165] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 1:2026-09-16 21:09:33.883 [Test worker @coroutine#165] INFO io.ktor.server.Application - Application started in 0.038 seconds. 1;2026-09-16 21:09:33.884 [DefaultDispatcher-worker-4 @coroutine#174] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36193 1<2026-09-16 21:09:33.885 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36193/api/school/respect/schoolpermissiongrant 1<2026-09-16 21:09:33.885 [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:36193/api/school/respect/schoolpermissiongrant. 1>2026-09-16 21:09:33.887 [eventLoopGroupProxy-25-1 @call-handler#177] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] 1>/, segment:0 -> SUCCESS @ / 1> /api, segment:1 -> SUCCESS @ /api 1> /api/school, segment:2 -> SUCCESS @ /api/school 1> /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1? /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person 1? /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant 1? /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 1?Matched routes: 1? "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" 1?Routing resolve result: 1? SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] 1@2026-09-16 21:09:33.889 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36193/api/school/respect/schoolpermissiongrant 1@2026-09-16 21:09:33.889 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36193/api/school/respect/schoolpermissiongrant 1@2026-09-16 21:09:33.889 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36193/api/school/respect/schoolpermissiongrant 1A2026-09-16 21:09:33.889 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36193/api/school/respect/schoolpermissiongrant. 12026-09-16 21:09:34.012 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36193/api/school/respect/person?includeRelated=false 12026-09-16 21:09:34.012 [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:36193/api/school/respect/person?includeRelated=false. 12026-09-16 21:09:34.014 [eventLoopGroupProxy-25-1 @call-handler#183] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 1/, segment:0 -> SUCCESS @ / 1 /api, segment:1 -> SUCCESS @ /api 1 /api/school, segment:2 -> SUCCESS @ /api/school 1 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 1 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 1 /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 1 /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 1 /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant 1Matched routes: 1 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 1Routing resolve result: 1 SUCCESS @ /api/school/respect/person [(method:GET)] 1Sep 16, 2026 9:09:34 PM io.github.aakira.napier.DebugAntilog performLog 1FINE: [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) 12026-09-16 21:09:34.019 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36193/api/school/respect/person?includeRelated=false 12026-09-16 21:09:34.019 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36193/api/school/respect/person?includeRelated=false 12026-09-16 21:09:34.019 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36193/api/school/respect/person?includeRelated=false 12026-09-16 21:09:34.020 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36193/api/school/respect/person?includeRelated=false. 2Sep 16, 2026 9:09:36 PM io.github.aakira.napier.DebugAntilog performLog 2FINE: [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 2Sep 16, 2026 9:09:36 PM io.github.aakira.napier.DebugAntilog performLog 2FINE: [DEBUG] HttpRequestBuilderExtKt$addCacheValidationHeaders - addCacheValidationHeaders = If-Modified-Since = Wed, 16 Sep 2026 17:09:34 GMT for http://localhost:36193/api/school/respect/person?includeRelated=false 22026-09-16 21:09:36.026 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36193/api/school/respect/person?includeRelated=false 22026-09-16 21:09:36.026 [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:36193/api/school/respect/person?includeRelated=false. 22026-09-16 21:09:36.027 [eventLoopGroupProxy-25-1 @call-handler#190] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 2/, segment:0 -> SUCCESS @ / 2 /api, segment:1 -> SUCCESS @ /api 2 /api/school, segment:2 -> SUCCESS @ /api/school 2 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 2 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 2 /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 2 /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 2 /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant 2Matched routes: 2 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 2Routing resolve result: 2 SUCCESS @ /api/school/respect/person [(method:GET)] 2Sep 16, 2026 9:09:36 PM io.github.aakira.napier.DebugAntilog performLog 2FINE: [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) 22026-09-16 21:09:36.029 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36193/api/school/respect/person?includeRelated=false 22026-09-16 21:09:36.030 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36193/api/school/respect/person?includeRelated=false 22026-09-16 21:09:36.030 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36193/api/school/respect/person?includeRelated=false 22026-09-16 21:09:36.030 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36193/api/school/respect/person?includeRelated=false. 22026-09-16 21:09:37.143 [Test worker @coroutine#196] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 22026-09-16 21:09:37.144 [Test worker @coroutine#196] INFO io.ktor.server.Application - Application started in 0.043 seconds. 22026-09-16 21:09:37.145 [DefaultDispatcher-worker-5 @coroutine#205] INFO io.ktor.server.Application - Responding at http://0.0.0.0:39049 22026-09-16 21:09:37.148 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:39049/api/school/respect/person?includeRelated=false 22026-09-16 21:09:37.148 [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:39049/api/school/respect/person?includeRelated=false. 22026-09-16 21:09:37.150 [eventLoopGroupProxy-28-1 @call-handler#209] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 2/, segment:0 -> SUCCESS @ / 2 /api, segment:1 -> SUCCESS @ /api 2 /api/school, segment:2 -> SUCCESS @ /api/school 2 /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 2 /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 2 /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 2 /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 2Matched routes: 2 "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 2Routing resolve result: 2 SUCCESS @ /api/school/respect/person [(method:GET)] 2Sep 16, 2026 9:09:37 PM io.github.aakira.napier.DebugAntilog performLog 2FINE: [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) 22026-09-16 21:09:37.154 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:39049/api/school/respect/person?includeRelated=false 22026-09-16 21:09:37.154 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:39049/api/school/respect/person?includeRelated=false 22026-09-16 21:09:37.154 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:39049/api/school/respect/person?includeRelated=false 22026-09-16 21:09:37.155 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:39049/api/school/respect/person?includeRelated=false. 2+0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T17:09:37.037Z, stored=2026-09-16T17:09:37.194Z, 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=1789578577037, lastStored=1789578577194, etag=null, url=http://localhost:39049/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T17:09:37.195234270Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-16T17:09:37.037Z, stored=2026-09-16T17:09:37.194Z, 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=1789578577037, lastStored=1789578577194, etag=null, url=null, consistentThrough=2026-09-16T17:09:37.195234270Z, 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-16T17:09:37.037Z, stored=2026-09-16T17:09:37.100Z, 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-16T17:09:37.035Z, stored=2026-09-16T17:09:37.146Z, 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=1789578577000, lastStored=-1, etag=null, url=http://localhost:39049/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-16T17:09:37.151194215Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@66b31d46, permissionsLastModified=null), localState=null, remoteState=null)) 2,Sep 16, 2026 9:09:37 PM io.github.aakira.napier.DebugAntilog performLog 2,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 2-2026-09-16 21:09:37.198 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false 2-2026-09-16 21:09:37.198 [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:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false. 2.2026-09-16 21:09:37.199 [eventLoopGroupProxy-28-1 @call-handler#216] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] 2//, segment:0 -> SUCCESS @ / 2/ /api, segment:1 -> SUCCESS @ /api 2/ /api/school, segment:2 -> SUCCESS @ /api/school 2/ /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect 2/ /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person 2/ /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] 2/ /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] 2/Matched routes: 2/ "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" 2/Routing resolve result: 2/ SUCCESS @ /api/school/respect/person [(method:GET)] 2/Sep 16, 2026 9:09:37 PM io.github.aakira.napier.DebugAntilog performLog 2/FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=2026-09-16T17:09:37.151194215Z, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 202026-09-16 21:09:37.201 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false 202026-09-16 21:09:37.201 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false 202026-09-16 21:09:37.201 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false 212026-09-16 21:09:37.202 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:39049/api/school/respect/person?since=2026-09-16T17%3A09%3A37.151194215Z&includeRelated=false. 22Run time: 56.291490ms 2 2026-09-16 21:09:38.317 [Test worker @coroutine#222] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2 2026-09-16 21:09:38.318 [Test worker @coroutine#222] INFO io.ktor.server.Application - Application started in 0.045 seconds. 2 2026-09-16 21:09:38.319 [DefaultDispatcher-worker-5 @coroutine#232] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36071 2 2026-09-16 21:09:38.321 [Test worker @coroutine#222] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46 2 2026-09-16 21:09:38.321 [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:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46. 2 2026-09-16 21:09:38.323 [eventLoopGroupProxy-31-1 @call-handler#235] TRACE io.ktor.server.routing.Routing - Trace for [playlist, adb42bca-aa63-4381-89ac-8e66e8340f46] 2 /, segment:0 -> SUCCESS @ / 2 /playlist, segment:1 -> SUCCESS @ /playlist 2  /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[adb42bca-aa63-4381-89ac-8e66e8340f46]] @ /playlist/{uuid} 2  /playlist/{uuid} [(method:GET)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:GET)] 2  /playlist/{uuid} [(method:POST)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:POST)] 2 Matched routes: 2 "" -> "playlist" -> "{uuid}" -> "(method:GET)" 2 Routing resolve result: 2  SUCCESS; Parameters [uuid=[adb42bca-aa63-4381-89ac-8e66e8340f46]] @ /playlist/{uuid} [(method:GET)] 2 2026-09-16 21:09:38.329 [Test worker @coroutine#222] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46 2 2026-09-16 21:09:38.329 [Test worker @coroutine#222] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46 2 2026-09-16 21:09:38.329 [Test worker @coroutine#222] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46 2 2026-09-16 21:09:38.329 [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:36071/playlist/adb42bca-aa63-4381-89ac-8e66e8340f46. 2 2026-09-16 21:09:39.466 [Test worker @coroutine#239] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2 2026-09-16 21:09:39.466 [Test worker @coroutine#239] INFO io.ktor.server.Application - Application started in 0.038 seconds. 2 2026-09-16 21:09:39.467 [DefaultDispatcher-worker-4 @coroutine#248] INFO io.ktor.server.Application - Responding at http://0.0.0.0:39585 232026-09-16 21:09:39.507 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 232026-09-16 21:09:39.508 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@67e12de8 for http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 232026-09-16 21:09:39.508 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a from class io.ktor.http.content.TextContent 252026-09-16 21:09:39.510 [eventLoopGroupProxy-34-1 @call-handler#255] TRACE io.ktor.server.routing.Routing - Trace for [playlist, ffa85226-e49d-461b-9cf2-0d69e0f7b74a] 25/, segment:0 -> SUCCESS @ / 26 /playlist, segment:1 -> SUCCESS @ /playlist 26 /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[ffa85226-e49d-461b-9cf2-0d69e0f7b74a]] @ /playlist/{uuid} 26 /playlist/{uuid} [(method:GET)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:GET)] 26 /playlist/{uuid} [(method:POST)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:POST)] 26Matched routes: 26 "" -> "playlist" -> "{uuid}" -> "(method:POST)" 26Routing resolve result: 26 SUCCESS; Parameters [uuid=[ffa85226-e49d-461b-9cf2-0d69e0f7b74a]] @ /playlist/{uuid} [(method:POST)] 262026-09-16 21:09:39.510 [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/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 272026-09-16 21:09:39.511 [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/ffa85226-e49d-461b-9cf2-0d69e0f7b74a request because the HttpStatusCode type is ignored. See [ContentNegotiationConfig::ignoreType]. 282026-09-16 21:09:39.512 [DefaultDispatcher-worker-2 @coroutine#246] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 282026-09-16 21:09:39.512 [DefaultDispatcher-worker-2 @coroutine#246] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 282026-09-16 21:09:39.512 [DefaultDispatcher-worker-2 @coroutine#246] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:39585/playlist/ffa85226-e49d-461b-9cf2-0d69e0f7b74a 22026-09-16 21:09:40.627 [Test worker @coroutine#260] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 22026-09-16 21:09:40.629 [Test worker @coroutine#260] INFO io.ktor.server.Application - Application started in 0.05 seconds. 22026-09-16 21:09:40.630 [DefaultDispatcher-worker-4 @coroutine#269] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41623 22026-09-16 21:09:40.717 [DefaultDispatcher-worker-1 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41623/api/school/xapi/statements 22026-09-16 21:09:40.719 [DefaultDispatcher-worker-1 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@3414f116 for http://localhost:41623/api/school/xapi/statements 22026-09-16 21:09:40.719 [DefaultDispatcher-worker-1 @coroutine#267] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:41623/api/school/xapi/statements from class io.ktor.http.content.TextContent 22026-09-16 21:09:40.721 [eventLoopGroupProxy-37-1 @call-handler#278] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] 2/, segment:0 -> SUCCESS @ / 2 /api, segment:1 -> SUCCESS @ /api 2 /api/school, segment:2 -> SUCCESS @ /api/school 2 /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi 2 /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements 2 /api/school/xapi/statements [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:GET)] 2 /api/school/xapi/statements [(method:POST)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:POST)] 2Matched routes: 2 "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:POST)" 2Routing resolve result: 2 SUCCESS @ /api/school/xapi/statements [(method:POST)] 22026-09-16 21:09:40.722 [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 22026-09-16 21:09:40.732 [DefaultDispatcher-worker-2 @coroutine#267] TRACE i.k.client.plugins.HttpCallValidator - Processing exception java.io.IOException: unexpected end of stream on http://localhost:41623/... for request http://localhost:41623/api/school/xapi/statements 2Exception in thread "DefaultDispatcher-worker-2 @coroutine#267" java.io.IOException: unexpected end of stream on http://localhost:41623/... 2 at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42) 2 at io.ktor.client.engine.okhttp.OkHttpEngine.executeHttpRequest(OkHttpEngine.kt:107) 2 at io.ktor.client.engine.okhttp.OkHttpEngine.execute(OkHttpEngine.kt:71) 2 at io.ktor.client.engine.HttpClientEngine$executeWithinCallContext$2.invokeSuspend(HttpClientEngine.kt:183) 2 at io.ktor.client.engine.HttpClientEngine.executeWithinCallContext(HttpClientEngine.kt:184) 2 at io.ktor.client.engine.HttpClientEngine$install$1.invokeSuspend(HttpClientEngine.kt:154) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.plugins.HttpSend$DefaultSender.execute(HttpSend.kt:141) 2 at io.ktor.client.plugins.HttpRedirectKt$HttpRedirect$2$1.invokeSuspend(HttpRedirect.kt:110) 2 at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52) 2 at io.ktor.client.plugins.HttpCallValidatorKt$HttpCallValidator$2$2.invokeSuspend(HttpCallValidator.kt:143) 2 at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52) 2 at io.ktor.client.plugins.HttpSend$Plugin$install$1.invokeSuspend(HttpSend.kt:107) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.plugins.DefaultTransformKt$defaultTransformers$1.invokeSuspend(DefaultTransform.kt:64) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invokeSuspend(KtorCallContexts.kt:88) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.plugins.RequestError$install$1.invokeSuspend(HttpCallValidator.kt:165) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invokeSuspend(HttpRequestLifecycle.kt:29) 2 at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend(HttpRequestLifecycle.kt:42) 2 at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79) 2 at io.ktor.client.HttpClient.execute$ktor_client_core(HttpClient.kt:1420) 2 at io.ktor.client.statement.HttpStatement.fetchResponse(HttpStatement.kt:207) 2 at world.respect.datalayer.http.school.xapi.XapiStatementsResourceHttp.post(XapiStatementsResourceHttp.kt:129) 2 at world.respect.datalayer.repository.school.writequeue.DrainRemoteWriteQueueUseCase.invoke(DrainRemoteWriteQueueUseCase.kt:90) 2 at world.respect.lib.test.clientservertest.ClientServerDataSourceTestBuilder$clients$1$2.invokeSuspend(ClientServerDatasourceTest.kt:280) 2 Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [CoroutineId(267), "coroutine#267":StandaloneCoroutine{Cancelling}@72c40b88, Dispatchers.Default] 2Caused by: java.io.IOException: unexpected end of stream on http://localhost:41623/... 2 at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:252) 2 at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:116) 2 at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:97) 2 at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) 2 at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34) 2 at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) 2 at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:98) 2 at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) 2 at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) 2 at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) 2 at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72) 2 at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332) 2 at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:232) 2 at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:580) 2 at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) 2 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) 2 at java.base/java.lang.Thread.run(Thread.java:840) 2Caused by: java.io.EOFException: \n not found: limit=0 content=… 2 at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:362) 2 at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:32) 2 at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:215) 2 ... 16 more 22026-09-16 21:09:41.933 [Test worker @coroutine#282] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 22026-09-16 21:09:41.934 [Test worker @coroutine#282] INFO io.ktor.server.Application - Application started in 0.047 seconds. 22026-09-16 21:09:41.935 [DefaultDispatcher-worker-1 @coroutine#291] INFO io.ktor.server.Application - Responding at http://0.0.0.0:46717 22026-09-16 21:09:41.982 [Test worker @coroutine#282] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 22026-09-16 21:09:41.982 [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:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false. 22026-09-16 21:09:41.984 [eventLoopGroupProxy-40-1 @call-handler#298] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] 2/, segment:0 -> SUCCESS @ / 2 /api, segment:1 -> SUCCESS @ /api 2 /api/school, segment:2 -> SUCCESS @ /api/school 2 /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi 2 /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements 2 /api/school/xapi/statements [(method:GET)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:GET)] 2 /api/school/xapi/statements [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:POST)] 2Matched routes: 2 "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:GET)" 2Routing resolve result: 2 SUCCESS @ /api/school/xapi/statements [(method:GET)] 22026-09-16 21:09:41.988 [Test worker @coroutine#282] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 22026-09-16 21:09:41.988 [Test worker @coroutine#282] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 22026-09-16 21:09:41.988 [Test worker @coroutine#282] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 22026-09-16 21:09:41.989 [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:46717/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false.