Uport = 36215 V212:05:13,822 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found logback-core version 1.6.1 V212:05:13,823 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - No custom configurators were discovered as a service. V212:05:13,823 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator V212:05:13,824 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator V212:05:13,826 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] V212:05:13,827 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/jenkins/.jenkins/workspace/main-login-error-test-end-to-end/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] V212:05:13,828 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs multiple times on the classpath. V212:05:13,828 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs at [jar:file:/home/jenkins/.jenkins/workspace/main-login-error-test-end-to-end/respect-server/build/libs/respect-server-1.0.38.jar!/logback.xml] V212:05:13,828 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@2ceb80a1 - Resource [logback.xml] occurs at [file:/home/jenkins/.jenkins/workspace/main-login-error-test-end-to-end/respect-datalayer-repository/build/processedResources/jvm/test/logback.xml] V212:05:13,876 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Scan attribute not set or set to unrecognized value. V212:05:13,879 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT] V212:05:13,879 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] V212:05:13,881 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property V212:05:13,902 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - NOTE: Writing to the console can be slow. Try to avoid logging to the V212:05:13,902 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - console in production environments, especially in high volume systems. V212:05:13,902 |-INFO in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also https://logback.qos.ch/codes.html#slowConsole V212:05:13,902 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to TRACE V212:05:13,903 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT] V212:05:13,903 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [io.netty] to INFO V212:05:13,903 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@4b45dcb8 - End of configuration. V212:05:13,903 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7216fb24 - Registering current configuration as safe fallback point V212:05:13,905 |-INFO in ch.qos.logback.classic.util.ContextInitializer@2b0f373b - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 79 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY V3 V2026-09-18 12:05:14.041 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. ^port = 35357 ^2026-09-18 12:05:16.085 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. bport = 35469 b2026-09-18 12:05:17.173 [Test worker] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. g2026-09-18 12:05:18.442 [Test worker @coroutine#62] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. g2026-09-18 12:05:18.450 [Test worker @coroutine#62] INFO io.ktor.server.Application - Application started in 0.118 seconds. g2026-09-18 12:05:18.452 [DefaultDispatcher-worker-1 @coroutine#71] INFO io.ktor.server.Application - Responding at http://0.0.0.0:35365 h2026-09-18 12:05:18.465 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:35365/api/school/respect/schoolpermissiongrant h2026-09-18 12:05:18.465 [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:35365/api/school/respect/schoolpermissiongrant. h2026-09-18 12:05:18.469 [eventLoopGroupProxy-13-1 @call-handler#74] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] h/, segment:0 -> SUCCESS @ / h /api, segment:1 -> SUCCESS @ /api h /api/school, segment:2 -> SUCCESS @ /api/school h /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect h /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person h /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant h /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] hMatched routes: h "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" hRouting resolve result: h SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] h2026-09-18 12:05:18.483 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:35365/api/school/respect/schoolpermissiongrant h2026-09-18 12:05:18.483 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:35365/api/school/respect/schoolpermissiongrant h2026-09-18 12:05:18.483 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:35365/api/school/respect/schoolpermissiongrant h2026-09-18 12:05:18.485 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:35365/api/school/respect/schoolpermissiongrant. hT2026-09-18 12:05:18.549 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:35365/api/school/respect/person?includeRelated=false hT2026-09-18 12:05:18.549 [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:35365/api/school/respect/person?includeRelated=false. hV2026-09-18 12:05:18.551 [eventLoopGroupProxy-13-1 @call-handler#80] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] hV/, segment:0 -> SUCCESS @ / hV /api, segment:1 -> SUCCESS @ /api hV /api/school, segment:2 -> SUCCESS @ /api/school hV /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect hV /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person hV /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] hV /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] hV /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant hVMatched routes: hV "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" hVRouting resolve result: hV SUCCESS @ /api/school/respect/person [(method:GET)] hk2026-09-18 12:05:18.572 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:35365/api/school/respect/person?includeRelated=false hl2026-09-18 12:05:18.573 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:35365/api/school/respect/person?includeRelated=false hl2026-09-18 12:05:18.573 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:35365/api/school/respect/person?includeRelated=false hm2026-09-18 12:05:18.574 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:35365/api/school/respect/person?includeRelated=false. hr2026-09-18 12:05:18.579 [Test worker @coroutine#62] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:35365/api/school/respect/person?includeRelated=false hs2026-09-18 12:05:18.579 [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:35365/api/school/respect/person?includeRelated=false. ht2026-09-18 12:05:18.581 [eventLoopGroupProxy-13-1 @call-handler#86] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] ht/, segment:0 -> SUCCESS @ / ht /api, segment:1 -> SUCCESS @ /api ht /api/school, segment:2 -> SUCCESS @ /api/school ht /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect ht /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person ht /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] ht /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] ht /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant htMatched routes: ht "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" htRouting resolve result: ht SUCCESS @ /api/school/respect/person [(method:GET)] hv2026-09-18 12:05:18.583 [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]. hv2026-09-18 12:05:18.583 [Test worker @coroutine#62] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:35365/api/school/respect/person?includeRelated=false hw2026-09-18 12:05:18.584 [Test worker @coroutine#62] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:35365/api/school/respect/person?includeRelated=false hw2026-09-18 12:05:18.584 [Test worker @coroutine#62] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:35365/api/school/respect/person?includeRelated=false l2026-09-18 12:05:19.680 [Test worker @coroutine#90] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. l2026-09-18 12:05:19.681 [Test worker @coroutine#90] INFO io.ktor.server.Application - Application started in 0.04 seconds. l2026-09-18 12:05:19.682 [DefaultDispatcher-worker-4 @coroutine#99] INFO io.ktor.server.Application - Responding at http://0.0.0.0:43295 l2026-09-18 12:05:19.683 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43295/api/school/respect/schoolpermissiongrant l2026-09-18 12:05:19.683 [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:43295/api/school/respect/schoolpermissiongrant. l2026-09-18 12:05:19.686 [eventLoopGroupProxy-16-1 @call-handler#102] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, schoolpermissiongrant] l/, segment:0 -> SUCCESS @ / l /api, segment:1 -> SUCCESS @ /api l /api/school, segment:2 -> SUCCESS @ /api/school l /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect l /api/school/respect/person, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/person l /api/school/respect/schoolpermissiongrant, segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant l /api/school/respect/schoolpermissiongrant [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] lMatched routes: l "" -> "api" -> "school" -> "respect" -> "schoolpermissiongrant" -> "(method:GET)" lRouting resolve result: l SUCCESS @ /api/school/respect/schoolpermissiongrant [(method:GET)] l2026-09-18 12:05:19.688 [Test worker @coroutine#90] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:43295/api/school/respect/schoolpermissiongrant l2026-09-18 12:05:19.688 [Test worker @coroutine#90] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:43295/api/school/respect/schoolpermissiongrant l2026-09-18 12:05:19.688 [Test worker @coroutine#90] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:43295/api/school/respect/schoolpermissiongrant l2026-09-18 12:05:19.688 [Test worker @coroutine#90] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:43295/api/school/respect/schoolpermissiongrant. l2026-09-18 12:05:19.737 [DefaultDispatcher-worker-3 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 l2026-09-18 12:05:19.738 [DefaultDispatcher-worker-3 @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:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. l2026-09-18 12:05:19.739 [eventLoopGroupProxy-16-1 @call-handler#112] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] l/, segment:0 -> SUCCESS @ / l /api, segment:1 -> SUCCESS @ /api l /api/school, segment:2 -> SUCCESS @ /api/school l /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect l /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person l /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] l /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] l /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant lMatched routes: l "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" lRouting resolve result: l SUCCESS @ /api/school/respect/person [(method:GET)] l2026-09-18 12:05:19.742 [DefaultDispatcher-worker-4 @coroutine#108] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 l2026-09-18 12:05:19.742 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 l2026-09-18 12:05:19.742 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100 l2026-09-18 12:05:19.743 [DefaultDispatcher-worker-4 @coroutine#108] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:43295/api/school/respect/person?includeDeleted=true&includeRelated=false&offset=0&limit=100. qa2026-09-18 12:05:20.865 [Test worker @coroutine#117] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. qb2026-09-18 12:05:20.866 [Test worker @coroutine#117] INFO io.ktor.server.Application - Application started in 0.04 seconds. qc2026-09-18 12:05:20.867 [DefaultDispatcher-worker-3 @coroutine#126] INFO io.ktor.server.Application - Responding at http://0.0.0.0:41913 qf2026-09-18 12:05:20.870 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41913/api/school/respect/person?includeRelated=false qf2026-09-18 12:05:20.870 [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:41913/api/school/respect/person?includeRelated=false. qh2026-09-18 12:05:20.872 [eventLoopGroupProxy-19-1 @call-handler#130] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] qh/, segment:0 -> SUCCESS @ / qh /api, segment:1 -> SUCCESS @ /api qh /api/school, segment:2 -> SUCCESS @ /api/school qh /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect qh /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person qh /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] qh /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] qhMatched routes: qh "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" qhRouting resolve result: qh SUCCESS @ /api/school/respect/person [(method:GET)] ql2026-09-18 12:05:20.876 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41913/api/school/respect/person?includeRelated=false ql2026-09-18 12:05:20.876 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41913/api/school/respect/person?includeRelated=false ql2026-09-18 12:05:20.876 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41913/api/school/respect/person?includeRelated=false qm2026-09-18 12:05:20.877 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41913/api/school/respect/person?includeRelated=false. q0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-18T08:05:20.754Z, stored=2026-09-18T08:05:20.915Z, 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=1789718720754, lastStored=1789718720915, etag=null, url=http://localhost:41913/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-18T08:05:20.917284624Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-18T08:05:20.754Z, stored=2026-09-18T08:05:20.915Z, 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=1789718720754, lastStored=1789718720915, etag=null, url=null, consistentThrough=2026-09-18T08:05:20.917284624Z, 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-18T08:05:20.754Z, stored=2026-09-18T08:05:20.825Z, 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-18T08:05:20.753Z, stored=2026-09-18T08:05:20.868Z, 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=1789718720000, lastStored=-1, etag=null, url=http://localhost:41913/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-18T08:05:20.873155907Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@646e6d07, permissionsLastModified=null), localState=null, remoteState=null)) q2026-09-18 12:05:20.930 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false q2026-09-18 12:05:20.930 [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:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false. q2026-09-18 12:05:20.932 [eventLoopGroupProxy-19-1 @call-handler#136] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] q/, segment:0 -> SUCCESS @ / q /api, segment:1 -> SUCCESS @ /api q /api/school, segment:2 -> SUCCESS @ /api/school q /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect q /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person q /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)] q /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] qMatched routes: q "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" qRouting resolve result: q SUCCESS @ /api/school/respect/person [(method:GET)] q2026-09-18 12:05:20.933 [Test worker @coroutine#117] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false q2026-09-18 12:05:20.934 [Test worker @coroutine#117] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false q2026-09-18 12:05:20.934 [Test worker @coroutine#117] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false q2026-09-18 12:05:20.934 [Test worker @coroutine#117] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:41913/api/school/respect/person?since=2026-09-18T08%3A05%3A20.873155907Z&includeRelated=false. qRun time: 67.032710ms u2026-09-18 12:05:22.033 [Test worker @coroutine#142] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. u2026-09-18 12:05:22.034 [Test worker @coroutine#142] INFO io.ktor.server.Application - Application started in 0.039 seconds. u2026-09-18 12:05:22.035 [DefaultDispatcher-worker-4 @coroutine#151] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36417 v2026-09-18 12:05:22.079 [DefaultDispatcher-worker-3 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36417/api/school/respect/person v2026-09-18 12:05:22.079 [DefaultDispatcher-worker-3 @coroutine#149] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@58adf4e8 for http://localhost:36417/api/school/respect/person v 2026-09-18 12:05:22.080 [DefaultDispatcher-worker-3 @coroutine#149] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:36417/api/school/respect/person from class io.ktor.http.content.TextContent v$2026-09-18 12:05:22.084 [eventLoopGroupProxy-22-1 @call-handler#160] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] v$/, segment:0 -> SUCCESS @ / v$ /api, segment:1 -> SUCCESS @ /api v$ /api/school, segment:2 -> SUCCESS @ /api/school v$ /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect v$ /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person v$ /api/school/respect/person [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:GET)] v$ /api/school/respect/person [(method:POST)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:POST)] v$Matched routes: v$ "" -> "api" -> "school" -> "respect" -> "person" -> "(method:POST)" v$Routing resolve result: v$ SUCCESS @ /api/school/respect/person [(method:POST)] v(2026-09-18 12:05:22.088 [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 v)2026-09-18 12:05:22.089 [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]. v*2026-09-18 12:05:22.090 [DefaultDispatcher-worker-6 @coroutine#149] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36417/api/school/respect/person v*2026-09-18 12:05:22.091 [DefaultDispatcher-worker-6 @coroutine#149] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36417/api/school/respect/person v+2026-09-18 12:05:22.091 [DefaultDispatcher-worker-6 @coroutine#149] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36417/api/school/respect/person z{2026-09-18 12:05:23.195 [Test worker @coroutine#165] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. z|2026-09-18 12:05:23.196 [Test worker @coroutine#165] INFO io.ktor.server.Application - Application started in 0.04 seconds. z}2026-09-18 12:05:23.197 [DefaultDispatcher-worker-3 @coroutine#174] INFO io.ktor.server.Application - Responding at http://0.0.0.0:40157 z~2026-09-18 12:05:23.198 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40157/api/school/respect/schoolpermissiongrant z~2026-09-18 12:05:23.198 [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:40157/api/school/respect/schoolpermissiongrant. z2026-09-18 12:05:23.200 [eventLoopGroupProxy-25-1 @call-handler#177] 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-09-18 12:05:23.202 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40157/api/school/respect/schoolpermissiongrant z2026-09-18 12:05:23.203 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40157/api/school/respect/schoolpermissiongrant z2026-09-18 12:05:23.203 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40157/api/school/respect/schoolpermissiongrant z2026-09-18 12:05:23.203 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40157/api/school/respect/schoolpermissiongrant. z2026-09-18 12:05:23.245 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40157/api/school/respect/person?includeRelated=false z2026-09-18 12:05:23.245 [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:40157/api/school/respect/person?includeRelated=false. z2026-09-18 12:05:23.246 [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 zMatched routes: z "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" zRouting resolve result: z SUCCESS @ /api/school/respect/person [(method:GET)] zSep 18, 2026 12:05:23 PM io.github.aakira.napier.DebugAntilog performLog zFINE: [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) z2026-09-18 12:05:23.251 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40157/api/school/respect/person?includeRelated=false z2026-09-18 12:05:23.251 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40157/api/school/respect/person?includeRelated=false z2026-09-18 12:05:23.251 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40157/api/school/respect/person?includeRelated=false z2026-09-18 12:05:23.252 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40157/api/school/respect/person?includeRelated=false. Sep 18, 2026 12:05:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] DelegatedInvalidationPagingSource$onSrcInvalidated - RPaging/DelegatedInvalidationPagingSource(extra=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))) src invalidated Sep 18, 2026 12:05:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] HttpRequestBuilderExtKt$addCacheValidationHeaders - addCacheValidationHeaders = If-Modified-Since = Fri, 18 Sep 2026 08:05:23 GMT for http://localhost:40157/api/school/respect/person?includeRelated=false 2026-09-18 12:05:25.257 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:40157/api/school/respect/person?includeRelated=false 2026-09-18 12:05:25.257 [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:40157/api/school/respect/person?includeRelated=false. 2026-09-18 12:05:25.259 [eventLoopGroupProxy-25-1 @call-handler#190] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)]  /api/school/respect/schoolpermissiongrant, segment:3 -> FAILURE "Selector didn't match" @ /api/school/respect/schoolpermissiongrant Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 18, 2026 12:05:25 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-18 12:05:25.261 [Test worker @coroutine#165] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:40157/api/school/respect/person?includeRelated=false 2026-09-18 12:05:25.261 [Test worker @coroutine#165] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:40157/api/school/respect/person?includeRelated=false 2026-09-18 12:05:25.261 [Test worker @coroutine#165] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:40157/api/school/respect/person?includeRelated=false 2026-09-18 12:05:25.262 [Test worker @coroutine#165] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:40157/api/school/respect/person?includeRelated=false. 2026-09-18 12:05:26.369 [Test worker @coroutine#196] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-18 12:05:26.370 [Test worker @coroutine#196] INFO io.ktor.server.Application - Application started in 0.039 seconds. 2026-09-18 12:05:26.371 [DefaultDispatcher-worker-3 @coroutine#205] INFO io.ktor.server.Application - Responding at http://0.0.0.0:36983 2026-09-18 12:05:26.373 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36983/api/school/respect/person?includeRelated=false 2026-09-18 12:05:26.373 [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:36983/api/school/respect/person?includeRelated=false. 2026-09-18 12:05:26.376 [eventLoopGroupProxy-28-1 @call-handler#209] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 18, 2026 12:05:26 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-18 12:05:26.379 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36983/api/school/respect/person?includeRelated=false 2026-09-18 12:05:26.379 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36983/api/school/respect/person?includeRelated=false 2026-09-18 12:05:26.379 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36983/api/school/respect/person?includeRelated=false 2026-09-18 12:05:26.380 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36983/api/school/respect/person?includeRelated=false. 0DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-18T08:05:26.269Z, stored=2026-09-18T08:05:26.417Z, 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=1789718726269, lastStored=1789718726417, etag=null, url=http://localhost:36983/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-18T08:05:26.418498968Z, validationInfoKey=0, varyHeader=null, headers=null, permissionsLastModified=null), localState=DataReadyState(data=[Person(guid=4242, userActive=true, status=ACTIVE, lastModified=2026-09-18T08:05:26.269Z, stored=2026-09-18T08:05:26.417Z, 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=1789718726269, lastStored=1789718726417, etag=null, url=null, consistentThrough=2026-09-18T08:05:26.418498968Z, 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-18T08:05:26.269Z, stored=2026-09-18T08:05:26.330Z, 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-18T08:05:26.267Z, stored=2026-09-18T08:05:26.371Z, 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=1789718726000, lastStored=-1, etag=null, url=http://localhost:36983/api/school/respect/person?includeRelated=false, consistentThrough=2026-09-18T08:05:26.376439982Z, validationInfoKey=7092960727423664838, varyHeader=Authorization, headers=io.ktor.client.engine.okhttp.OkUtilsKt$fromOkHttp$1@29aa4bc9, permissionsLastModified=null), localState=null, remoteState=null)) Sep 18, 2026 12:05:26 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] DelegatedInvalidationPagingSource$onSrcInvalidated - RPaging/DelegatedInvalidationPagingSource(extra=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=null, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))) src invalidated 2026-09-18 12:05:26.422 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false 2026-09-18 12:05:26.422 [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:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false. 2026-09-18 12:05:26.423 [eventLoopGroupProxy-28-1 @call-handler#216] TRACE io.ktor.server.routing.Routing - Trace for [api, school, respect, person] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/respect, segment:3 -> SUCCESS @ /api/school/respect  /api/school/respect/person, segment:4 -> SUCCESS @ /api/school/respect/person  /api/school/respect/person [(method:GET)], segment:4 -> SUCCESS @ /api/school/respect/person [(method:GET)]  /api/school/respect/person [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/respect/person [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "respect" -> "person" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/respect/person [(method:GET)] Sep 18, 2026 12:05:26 PM io.github.aakira.napier.DebugAntilog performLog FINE: [DEBUG] MapPagingSource$load - MapPagingSource(tag=PersonDataSourceDb/listAsPagingSource(params=GetListParams(common=GetListCommonParams(guid=null, searchQuery=null, since=2026-09-18T08:05:26.376439982Z, sinceIfPermissionsNotChangedSince=null, includeDeleted=null), filterByClazzUid=null, filterByEnrolmentRole=null, filterByName=null, filterByPersonStatus=null, filterByPersonRole=null, includeRelated=false, inClassOnDay=null))): load Refresh(key=0, loadSize=1000) 2026-09-18 12:05:26.425 [Test worker @coroutine#196] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false 2026-09-18 12:05:26.425 [Test worker @coroutine#196] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false 2026-09-18 12:05:26.425 [Test worker @coroutine#196] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false 2026-09-18 12:05:26.425 [Test worker @coroutine#196] TRACE i.k.c.p.c.ContentNegotiation - Response body was converted to class java.util.ArrayList for http://localhost:36983/api/school/respect/person?since=2026-09-18T08%3A05%3A26.376439982Z&includeRelated=false. Run time: 54.635381ms x2026-09-18 12:05:27.544 [Test worker @coroutine#222] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. y2026-09-18 12:05:27.546 [Test worker @coroutine#222] INFO io.ktor.server.Application - Application started in 0.053 seconds. z2026-09-18 12:05:27.547 [DefaultDispatcher-worker-3 @coroutine#232] INFO io.ktor.server.Application - Responding at http://0.0.0.0:42525 |2026-09-18 12:05:27.549 [Test worker @coroutine#222] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:42525/playlist/327942fd-a751-44c6-a535-37c560fff192 |2026-09-18 12:05:27.549 [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:42525/playlist/327942fd-a751-44c6-a535-37c560fff192. 2026-09-18 12:05:27.551 [eventLoopGroupProxy-31-1 @call-handler#235] TRACE io.ktor.server.routing.Routing - Trace for [playlist, 327942fd-a751-44c6-a535-37c560fff192] /, segment:0 -> SUCCESS @ /  /playlist, segment:1 -> SUCCESS @ /playlist  /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[327942fd-a751-44c6-a535-37c560fff192]] @ /playlist/{uuid}  /playlist/{uuid} [(method:GET)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:GET)]  /playlist/{uuid} [(method:POST)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:POST)] Matched routes:  "" -> "playlist" -> "{uuid}" -> "(method:GET)" Routing resolve result:  SUCCESS; Parameters [uuid=[327942fd-a751-44c6-a535-37c560fff192]] @ /playlist/{uuid} [(method:GET)] 2026-09-18 12:05:27.557 [Test worker @coroutine#222] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:42525/playlist/327942fd-a751-44c6-a535-37c560fff192 2026-09-18 12:05:27.557 [Test worker @coroutine#222] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:42525/playlist/327942fd-a751-44c6-a535-37c560fff192 2026-09-18 12:05:27.557 [Test worker @coroutine#222] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:42525/playlist/327942fd-a751-44c6-a535-37c560fff192 2026-09-18 12:05:27.557 [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:42525/playlist/327942fd-a751-44c6-a535-37c560fff192. 2026-09-18 12:05:28.707 [Test worker @coroutine#239] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-18 12:05:28.707 [Test worker @coroutine#239] INFO io.ktor.server.Application - Application started in 0.043 seconds. 2026-09-18 12:05:28.708 [DefaultDispatcher-worker-5 @coroutine#248] INFO io.ktor.server.Application - Responding at http://0.0.0.0:38521 52026-09-18 12:05:28.758 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab 52026-09-18 12:05:28.758 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@6a6d0e3f for http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab 52026-09-18 12:05:28.758 [DefaultDispatcher-worker-6 @coroutine#246] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab from class io.ktor.http.content.TextContent 82026-09-18 12:05:28.760 [eventLoopGroupProxy-34-1 @call-handler#255] TRACE io.ktor.server.routing.Routing - Trace for [playlist, 675cf15f-6cf1-47f3-b743-1af39c8ec7ab] 8/, segment:0 -> SUCCESS @ / 8 /playlist, segment:1 -> SUCCESS @ /playlist 8 /playlist/{uuid}, segment:2 -> SUCCESS; Parameters [uuid=[675cf15f-6cf1-47f3-b743-1af39c8ec7ab]] @ /playlist/{uuid} 8 /playlist/{uuid} [(method:GET)], segment:2 -> FAILURE "Selector didn't match" @ /playlist/{uuid} [(method:GET)] 8 /playlist/{uuid} [(method:POST)], segment:2 -> SUCCESS @ /playlist/{uuid} [(method:POST)] 8Matched routes: 8 "" -> "playlist" -> "{uuid}" -> "(method:POST)" 8Routing resolve result: 8 SUCCESS; Parameters [uuid=[675cf15f-6cf1-47f3-b743-1af39c8ec7ab]] @ /playlist/{uuid} [(method:POST)] 82026-09-18 12:05:28.761 [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/675cf15f-6cf1-47f3-b743-1af39c8ec7ab 92026-09-18 12:05:28.762 [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/675cf15f-6cf1-47f3-b743-1af39c8ec7ab request because the HttpStatusCode type is ignored. See [ContentNegotiationConfig::ignoreType]. :2026-09-18 12:05:28.762 [DefaultDispatcher-worker-5 @coroutine#246] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab :2026-09-18 12:05:28.762 [DefaultDispatcher-worker-5 @coroutine#246] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab :2026-09-18 12:05:28.762 [DefaultDispatcher-worker-5 @coroutine#246] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:38521/playlist/675cf15f-6cf1-47f3-b743-1af39c8ec7ab 2026-09-18 12:05:29.878 [Test worker @coroutine#260] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-18 12:05:29.880 [Test worker @coroutine#260] INFO io.ktor.server.Application - Application started in 0.049 seconds. 2026-09-18 12:05:29.881 [DefaultDispatcher-worker-4 @coroutine#269] INFO io.ktor.server.Application - Responding at http://0.0.0.0:44273 2026-09-18 12:05:29.969 [DefaultDispatcher-worker-3 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:44273/api/school/xapi/statements 2026-09-18 12:05:29.970 [DefaultDispatcher-worker-3 @coroutine#267] TRACE i.k.c.p.c.ContentNegotiation - Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@6680484f for http://localhost:44273/api/school/xapi/statements 2026-09-18 12:05:29.970 [DefaultDispatcher-worker-3 @coroutine#267] TRACE i.k.c.plugins.defaultTransformers - Transformed with default transformers request body for http://localhost:44273/api/school/xapi/statements from class io.ktor.http.content.TextContent 2026-09-18 12:05:29.973 [eventLoopGroupProxy-37-1 @call-handler#278] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi  /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements  /api/school/xapi/statements [(method:GET)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:GET)]  /api/school/xapi/statements [(method:POST)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:POST)" Routing resolve result:  SUCCESS @ /api/school/xapi/statements [(method:POST)] 2026-09-18 12:05:29.973 [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 2026-09-18 12:05:29.984 [DefaultDispatcher-worker-1 @coroutine#267] TRACE i.k.client.plugins.HttpCallValidator - Processing exception java.io.IOException: unexpected end of stream on http://localhost:44273/... for request http://localhost:44273/api/school/xapi/statements Exception in thread "DefaultDispatcher-worker-1 @coroutine#267" java.io.IOException: unexpected end of stream on http://localhost:44273/...  at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)  at io.ktor.client.engine.okhttp.OkHttpEngine.executeHttpRequest(OkHttpEngine.kt:107)  at io.ktor.client.engine.okhttp.OkHttpEngine.execute(OkHttpEngine.kt:71)  at io.ktor.client.engine.HttpClientEngine$executeWithinCallContext$2.invokeSuspend(HttpClientEngine.kt:183)  at io.ktor.client.engine.HttpClientEngine.executeWithinCallContext(HttpClientEngine.kt:184)  at io.ktor.client.engine.HttpClientEngine$install$1.invokeSuspend(HttpClientEngine.kt:154)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.HttpSend$DefaultSender.execute(HttpSend.kt:141)  at io.ktor.client.plugins.HttpRedirectKt$HttpRedirect$2$1.invokeSuspend(HttpRedirect.kt:110)  at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52)  at io.ktor.client.plugins.HttpCallValidatorKt$HttpCallValidator$2$2.invokeSuspend(HttpCallValidator.kt:143)  at io.ktor.client.plugins.api.Send$install$1.invokeSuspend(CommonHooks.kt:52)  at io.ktor.client.plugins.HttpSend$Plugin$install$1.invokeSuspend(HttpSend.kt:107)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.DefaultTransformKt$defaultTransformers$1.invokeSuspend(DefaultTransform.kt:64)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invokeSuspend(KtorCallContexts.kt:88)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.RequestError$install$1.invokeSuspend(HttpCallValidator.kt:165)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invokeSuspend(HttpRequestLifecycle.kt:29)  at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend(HttpRequestLifecycle.kt:42)  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)  at io.ktor.client.HttpClient.execute$ktor_client_core(HttpClient.kt:1420)  at io.ktor.client.statement.HttpStatement.fetchResponse(HttpStatement.kt:207)  at world.respect.datalayer.http.school.xapi.XapiStatementsResourceHttp.post(XapiStatementsResourceHttp.kt:129)  at world.respect.datalayer.repository.school.writequeue.DrainRemoteWriteQueueUseCase.invoke(DrainRemoteWriteQueueUseCase.kt:90)  at world.respect.lib.test.clientservertest.ClientServerDataSourceTestBuilder$clients$1$2.invokeSuspend(ClientServerDatasourceTest.kt:280)  Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [CoroutineId(267), "coroutine#267":StandaloneCoroutine{Cancelling}@3c33451e, Dispatchers.Default] Caused by: java.io.IOException: unexpected end of stream on http://localhost:44273/...  at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:252)  at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:116)  at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:97)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:98)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72)  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:332)  at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:232)  at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:580)  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)  at java.base/java.lang.Thread.run(Thread.java:840) Caused by: java.io.EOFException: \n not found: limit=0 content=…  at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:362)  at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:32)  at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:215)  ... 16 more 2026-09-18 12:05:31.190 [Test worker @coroutine#282] INFO io.ktor.server.Application - Autoreload is disabled because the development mode is off. 2026-09-18 12:05:31.190 [Test worker @coroutine#282] INFO io.ktor.server.Application - Application started in 0.037 seconds. 2026-09-18 12:05:31.191 [DefaultDispatcher-worker-6 @coroutine#291] INFO io.ktor.server.Application - Responding at http://0.0.0.0:35395 2026-09-18 12:05:31.239 [Test worker @coroutine#282] TRACE i.k.c.p.c.ContentNegotiation - Adding Accept=application/json header for http://localhost:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-18 12:05:31.239 [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:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false. 2026-09-18 12:05:31.242 [eventLoopGroupProxy-40-1 @call-handler#298] TRACE io.ktor.server.routing.Routing - Trace for [api, school, xapi, statements] /, segment:0 -> SUCCESS @ /  /api, segment:1 -> SUCCESS @ /api  /api/school, segment:2 -> SUCCESS @ /api/school  /api/school/xapi, segment:3 -> SUCCESS @ /api/school/xapi  /api/school/xapi/statements, segment:4 -> SUCCESS @ /api/school/xapi/statements  /api/school/xapi/statements [(method:GET)], segment:4 -> SUCCESS @ /api/school/xapi/statements [(method:GET)]  /api/school/xapi/statements [(method:POST)], segment:4 -> FAILURE "Selector didn't match" @ /api/school/xapi/statements [(method:POST)] Matched routes:  "" -> "api" -> "school" -> "xapi" -> "statements" -> "(method:GET)" Routing resolve result:  SUCCESS @ /api/school/xapi/statements [(method:GET)] 2026-09-18 12:05:31.246 [Test worker @coroutine#282] TRACE io.ktor.client.plugins.SaveBody - Saving body for http://localhost:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-18 12:05:31.246 [Test worker @coroutine#282] TRACE i.k.client.plugins.HttpCallValidator - Validating response for request http://localhost:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-18 12:05:31.246 [Test worker @coroutine#282] TRACE i.k.c.p.DefaultResponseValidation - Skipping default response validation for http://localhost:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false 2026-09-18 12:05:31.247 [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:35395/api/school/xapi/statements?statementId=6690e6c9-3ef0-4ed3-8b37-7f3964730bee&related_activities=false&related_agents=false&format=exact&attachments=false&ascending=false.