[INFO]
[INFO] ----------< org.eclipse.sensinact.gateway.nthbnd:mqtt-agent >-----------
[INFO] Building sensiNact IoT Gateway - MQTT Northbound Agent Instance 2.0-SNAPSHOT [72/120]
[INFO] --------------------------------[ jar ]---------------------------------
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-antrun-plugin/1.8/maven-antrun-plugin-1.8.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-antrun-plugin/1.8/maven-antrun-plugin-1.8.pom (3.3 kB at 221 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-plugins/27/maven-plugins-27.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-plugins/27/maven-plugins-27.pom (11 kB at 812 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-antrun-plugin/1.8/maven-antrun-plugin-1.8.jar
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/maven/plugins/maven-antrun-plugin/1.8/maven-antrun-plugin-1.8.jar (36 kB at 2.6 MB/s)
[INFO]
[INFO] --- maven-clean-plugin:3.1.0:clean (default-clean) @ mqtt-agent ---
[INFO]
[INFO] --- maven-enforcer-plugin:3.0.0-M3:enforce (enforce) @ mqtt-agent ---
[INFO]
[INFO] --- maven-resources-plugin:3.1.0:copy-resources (generate-test-resources) @ mqtt-agent ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/src/test/resources
[INFO]
[INFO] --- directory-maven-plugin:0.3.1:highest-basedir (directories) @ mqtt-agent ---
[INFO] Highest basedir set to: /var/jenkins_home/jobs/Eclipse Sensinact/workspace
[INFO]
[INFO] --- maven-resources-plugin:3.1.0:resources (default-resources) @ mqtt-agent ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO]
[INFO] --- maven-compiler-plugin:3.8.1:compile (default-compile) @ mqtt-agent ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 2 source files to /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/classes
[INFO]
[INFO] --- bnd-maven-plugin:6.1.0-SNAPSHOT:bnd-process (default) @ mqtt-agent ---
[INFO]
[INFO] --- maven-antrun-plugin:1.8:run (keystoreCopy) @ mqtt-agent ---
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/junit/junit/3.8.1/junit-3.8.1.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/junit/junit/3.8.1/junit-3.8.1.pom (998 B at 77 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/codehaus/plexus/plexus-utils/3.0.20/plexus-utils-3.0.20.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/codehaus/plexus/plexus-utils/3.0.20/plexus-utils-3.0.20.pom (3.8 kB at 272 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant/1.9.4/ant-1.9.4.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant/1.9.4/ant-1.9.4.pom (9.6 kB at 740 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-parent/1.9.4/ant-parent-1.9.4.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-parent/1.9.4/ant-parent-1.9.4.pom (5.6 kB at 374 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-launcher/1.9.4/ant-launcher-1.9.4.pom
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-launcher/1.9.4/ant-launcher-1.9.4.pom (2.3 kB at 167 kB/s)
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/junit/junit/3.8.1/junit-3.8.1.jar
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/codehaus/plexus/plexus-utils/3.0.20/plexus-utils-3.0.20.jar
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant/1.9.4/ant-1.9.4.jar
[INFO] Downloading from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-launcher/1.9.4/ant-launcher-1.9.4.jar
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant-launcher/1.9.4/ant-launcher-1.9.4.jar (18 kB at 511 kB/s)
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/junit/junit/3.8.1/junit-3.8.1.jar (121 kB at 3.2 MB/s)
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/codehaus/plexus/plexus-utils/3.0.20/plexus-utils-3.0.20.jar (243 kB at 4.8 MB/s)
[INFO] Downloaded from repo1.maven.org: https://repo1.maven.org/maven2/org/apache/ant/ant/1.9.4/ant-1.9.4.jar (2.0 MB at 23 MB/s)
[INFO] Executing tasks
main:
[mkdir] Created dir: /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/felix/tmp
[copy] Copying 1 file to /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/felix/bundle
[INFO] Executed tasks
[INFO]
[INFO] --- maven-resources-plugin:3.1.0:testResources (default-testResources) @ mqtt-agent ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.8.1:testCompile (default-testCompile) @ mqtt-agent ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 1 source file to /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/test-classes
[INFO]
[INFO] --- bnd-maven-plugin:6.1.0-SNAPSHOT:bnd-process-tests (bnd-process-tests) @ mqtt-agent ---
[INFO]
[INFO] --- maven-surefire-plugin:2.22.2:test (default-test) @ mqtt-agent ---
[INFO] Tests are skipped.
[INFO]
[INFO] --- maven-jar-plugin:3.2.0:jar (default-jar) @ mqtt-agent ---
[INFO] Building jar: /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/mqtt-agent-2.0-SNAPSHOT.jar
[INFO]
[INFO] --- maven-jar-plugin:3.2.0:test-jar (test-jar) @ mqtt-agent ---
[INFO] Building jar: /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/target/mqtt-agent-2.0-SNAPSHOT-tests.jar
[INFO]
[INFO] --- bnd-resolver-maven-plugin:6.1.0-SNAPSHOT:resolve (resolve-test) @ mqtt-agent ---
[INFO] Resolving /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/tests.bndrun:
[INFO] -runbundles: org.osgi.util.function;version='[1.1.0,1.1.1)',org.osgi.util.promise;version='[1.1.1,1.1.2)',junit-platform-commons;version='[1.7.2,1.7.3)',junit-jupiter-api;version='[5.7.2,5.7.3)',junit-jupiter-engine;version='[5.7.2,5.7.3)',junit-platform-engine;version='[1.7.2,1.7.3)',junit-platform-launcher;version='[1.7.2,1.7.3)',org.opentest4j;version='[1.2.0,1.2.1)',junit-jupiter-params;version='[5.7.2,5.7.3)',org.apache.felix.scr;version='[2.1.16,2.1.17)',org.osgi.test.common;version='[1.0.1,1.0.2)',org.osgi.test.junit5;version='[1.0.1,1.0.2)',ch.qos.logback.core;version='[1.2.3,1.2.4)',log4j;version='[1.2.17,1.2.18)',slf4j.api;version='[1.7.30,1.7.31)',org.eclipse.sensinact.gateway.sensinact-common;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-core;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-datastore-api;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-generic;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-signature-validator-api;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-utils;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-security-none;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-signature-validator-mock;version='[2.0.0,2.0.1)',org.apache.felix.framework.security;version='[2.8.1,2.8.2)',org.osgi.service.component;version='[1.4.0,1.4.1)',org.apache.felix.configadmin;version='[1.9.16,1.9.17)',org.osgi.test.junit5.cm;version='[1.0.1,1.0.2)',org.apache.felix.http.jetty;version='[4.1.10,4.1.11)',org.apache.felix.http.servlet-api;version='[1.1.4,1.1.5)',json;version='[20190722.0.0,20190722.0.1)',org.eclipse.paho.client.mqttv3;version='[1.2.2,1.2.3)',org.eclipse.sensinact.gateway.nthbnd.mqtt-agent;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.nthbnd.mqtt-agent-tests;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.nthbnd.mqtt-generic-agent;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.simulated.devices.slider;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.tools.mqtt-server;version='[2.0.0,2.0.1)',ch.qos.logback.classic;version='[1.2.3,1.2.4)',org.osgi.util.converter;version='[1.0.8,1.0.9)'
[INFO]
[INFO] --- bnd-testing-maven-plugin:6.1.0-SNAPSHOT:testing (testing) @ mqtt-agent ---
[INFO] Matching glob *
[INFO] Testing /var/jenkins_home/jobs/Eclipse Sensinact/workspace/platform/northbound/mqtt/mqtt-agent/tests.bndrun:
[INFO] -runbundles: org.osgi.util.function;version='[1.1.0,1.1.1)',org.osgi.util.promise;version='[1.1.1,1.1.2)',junit-platform-commons;version='[1.7.2,1.7.3)',junit-jupiter-api;version='[5.7.2,5.7.3)',junit-jupiter-engine;version='[5.7.2,5.7.3)',junit-platform-engine;version='[1.7.2,1.7.3)',junit-platform-launcher;version='[1.7.2,1.7.3)',org.opentest4j;version='[1.2.0,1.2.1)',junit-jupiter-params;version='[5.7.2,5.7.3)',org.apache.felix.scr;version='[2.1.16,2.1.17)',org.osgi.test.common;version='[1.0.1,1.0.2)',org.osgi.test.junit5;version='[1.0.1,1.0.2)',ch.qos.logback.core;version='[1.2.3,1.2.4)',log4j;version='[1.2.17,1.2.18)',slf4j.api;version='[1.7.30,1.7.31)',org.eclipse.sensinact.gateway.sensinact-common;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-core;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-datastore-api;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-generic;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-signature-validator-api;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-utils;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-security-none;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.sensinact-signature-validator-mock;version='[2.0.0,2.0.1)',org.apache.felix.framework.security;version='[2.8.1,2.8.2)',org.osgi.service.component;version='[1.4.0,1.4.1)',org.apache.felix.configadmin;version='[1.9.16,1.9.17)',org.osgi.test.junit5.cm;version='[1.0.1,1.0.2)',org.apache.felix.http.jetty;version='[4.1.10,4.1.11)',org.apache.felix.http.servlet-api;version='[1.1.4,1.1.5)',json;version='[20190722.0.0,20190722.0.1)',org.eclipse.paho.client.mqttv3;version='[1.2.2,1.2.3)',org.eclipse.sensinact.gateway.nthbnd.mqtt-agent;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.nthbnd.mqtt-agent-tests;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.nthbnd.mqtt-generic-agent;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.simulated.devices.slider;version='[2.0.0,2.0.1)',org.eclipse.sensinact.gateway.tools.mqtt-server;version='[2.0.0,2.0.1)',ch.qos.logback.classic;version='[1.2.3,1.2.4)',org.osgi.util.converter;version='[1.0.8,1.0.9)'
16:52:31.770 [main] DEBUG org.eclipse.jetty.util.log - Logging to Logger[org.eclipse.jetty.util.log] via org.eclipse.jetty.util.log.Slf4jLog
16:52:31.773 [main] INFO org.eclipse.jetty.util.log - Logging initialized @911ms to org.eclipse.jetty.util.log.Slf4jLog
16:52:31.780 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - QueuedThreadPool[qtp442199874]@1a5b6f42{STOPPED,8<=0<=200,i=0,r=-1,q=0}[NO_TRY] added {org.eclipse.jetty.util.thread.ThreadPoolBudget@78fa769e,POJO}
16:52:31.783 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STOPPED}[9.4.42.v20210604] added {QueuedThreadPool[qtp442199874]@1a5b6f42{STOPPED,8<=0<=200,i=0,r=-1,q=0}[NO_TRY],AUTO}
16:52:31.785 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HashLoginService@18ece7f4[null] added {org.eclipse.jetty.security.DefaultIdentityService@3cce57c7,POJO}
16:52:31.786 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HashLoginService@18ece7f4[OSGi HTTP Service Realm] added {UserStore@1cf56a1c{STOPPED},AUTO}
16:52:31.786 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STOPPED}[9.4.42.v20210604] added {HashLoginService@18ece7f4[OSGi HTTP Service Realm],AUTO}
16:52:31.797 [main] DEBUG org.eclipse.jetty.server.handler.ContextHandlerCollection - ->[{o.e.j.s.ServletContextHandler@791d1f8b{/,null,STOPPED},[o.e.j.s.ServletContextHandler@791d1f8b{/,null,STOPPED}]}]
16:52:31.797 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ContextHandlerCollection@2415fc55{STOPPED} added {o.e.j.s.ServletContextHandler@791d1f8b{/,null,STOPPED},AUTO}
16:52:31.799 [main] DEBUG org.eclipse.jetty.util.DecoratedObjectFactory - Adding Decorator: org.eclipse.jetty.util.DeprecationWarning@205d38da
16:52:31.803 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - o.e.j.s.ServletContextHandler@791d1f8b{/,null,STOPPED} added {org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=-1,MANAGED}
16:52:31.806 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=-1 added {ServletHandler@7a3793c7{STOPPED},MANAGED}
16:52:31.806 [main] DEBUG org.eclipse.jetty.server.session - Sessions created by this manager are immortal (default maxInactiveInterval=0)
16:52:31.807 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0 added {org.apache.felix.http.base.internal.EventDispatcher@39d76cb5,UNMANAGED}
16:52:31.809 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServletHandler@7a3793c7{STOPPED} added {org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED},AUTO}
16:52:31.809 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServletHandler@7a3793c7{STOPPED} added {[/*]=>org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499,POJO}
16:52:31.810 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STOPPED}[9.4.42.v20210604] added {ContextHandlerCollection@2415fc55{STOPPED},MANAGED}
16:52:31.810 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting Server@5852c06f{STOPPED}[9.4.42.v20210604]
16:52:31.811 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STARTING}[9.4.42.v20210604] added {ErrorHandler@a37aefe{STOPPED},AUTO}
16:52:31.812 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.42.v20210604; built: 2021-06-04T17:33:38.939Z; git: 5cd5e6d2375eeab146813b0de9f19eda6ab6e6cb; jvm 1.8.0_272-b10
16:52:31.824 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting Server@5852c06f{STARTING}[9.4.42.v20210604]
16:52:31.825 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting QueuedThreadPool[qtp442199874]@1a5b6f42{STOPPED,8<=0<=200,i=0,r=-1,q=0}[NO_TRY]
16:52:31.826 [main] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@1e81f160{s=0/12,p=0}
16:52:31.826 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=0<=200,i=0,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}] added {ReservedThreadExecutor@1e81f160{s=0/12,p=0},AUTO}
16:52:31.826 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ReservedThreadExecutor@1e81f160{s=0/12,p=0}
16:52:31.831 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @969ms ReservedThreadExecutor@1e81f160{s=0/12,p=0}
16:52:31.831 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-33,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-34,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-35,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-36,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-37,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-38,5,main]
16:52:31.832 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-39,5,main]
16:52:31.832 [qtp442199874-33] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=3<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.832 [qtp442199874-34] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=3<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.833 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp442199874-40,5,main]
16:52:31.833 [qtp442199874-37] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=7<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.833 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @971ms QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.833 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting HashLoginService@18ece7f4[OSGi HTTP Service Realm]
16:52:31.833 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting UserStore@1cf56a1c{STOPPED}
16:52:31.833 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @972ms UserStore@1cf56a1c{STARTED}
16:52:31.833 [qtp442199874-35] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=7<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.834 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @972ms HashLoginService@18ece7f4[OSGi HTTP Service Realm]
16:52:31.834 [qtp442199874-36] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.834 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ContextHandlerCollection@2415fc55{STOPPED}
16:52:31.834 [qtp442199874-39] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.834 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting ContextHandlerCollection@2415fc55{STARTING}
16:52:31.834 [qtp442199874-40] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.834 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting o.e.j.s.ServletContextHandler@791d1f8b{/,null,STOPPED}
16:52:31.834 [qtp442199874-38] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp442199874]@1a5b6f42{STARTING,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.835 [main] DEBUG org.eclipse.jetty.http.PreEncodedHttpField - HttpField encoders loaded: []
16:52:31.841 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting o.e.j.s.ServletContextHandler@791d1f8b{/,null,STARTING}
16:52:31.841 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0
16:52:31.843 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0 added {org.eclipse.jetty.server.session.DefaultSessionCache@1205bd62[evict=-1,removeUnloadable=false,saveOnCreate=false,saveOnInactiveEvict=false],AUTO}
16:52:31.844 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.session.DefaultSessionCache@1205bd62[evict=-1,removeUnloadable=false,saveOnCreate=false,saveOnInactiveEvict=false] added {org.eclipse.jetty.server.session.NullSessionDataStore@4032d386[passivating=false,graceSec=3600],AUTO}
16:52:31.845 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting DefaultSessionIdManager@55cf0d14{STOPPED}[worker=null]
16:52:31.845 [main] INFO org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0
16:52:31.845 [main] INFO org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
16:52:31.845 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - DefaultSessionIdManager@55cf0d14{STARTING}[worker=node0] added {HouseKeeper@b83a9be{STOPPED}[interval=600000, ownscheduler=false],MANAGED}
16:52:31.845 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting HouseKeeper@b83a9be{STOPPED}[interval=600000, ownscheduler=false]
16:52:31.846 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ScheduledExecutorScheduler@2b175c00{STOPPED}
16:52:31.846 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @985ms ScheduledExecutorScheduler@2b175c00{STARTED}
16:52:31.846 [main] DEBUG org.eclipse.jetty.server.session - Using own scheduler for scavenging
16:52:31.847 [main] INFO org.eclipse.jetty.server.session - node0 Scavenging every 600000ms
16:52:31.847 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @985ms HouseKeeper@b83a9be{STARTED}[interval=600000, ownscheduler=true]
16:52:31.847 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @985ms DefaultSessionIdManager@55cf0d14{STARTED}[worker=node0]
16:52:31.847 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STARTING}[9.4.42.v20210604] added {DefaultSessionIdManager@55cf0d14{STARTED}[worker=node0],MANAGED}
16:52:31.847 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0 added {DefaultSessionIdManager@55cf0d14{STARTED}[worker=node0],UNMANAGED}
16:52:31.848 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ScheduledExecutorScheduler@1f75a668{STOPPED}
16:52:31.848 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @986ms ScheduledExecutorScheduler@1f75a668{STARTED}
16:52:31.848 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0
16:52:31.848 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ServletHandler@7a3793c7{STOPPED}
16:52:31.850 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Path=/*[EMBEDDED:null] mapped to servlet=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499[EMBEDDED:null]
16:52:31.851 [main] DEBUG org.eclipse.jetty.http.pathmap.PathMappings - Added MappedResource[pathSpec=ServletPathSpec@5fa{/*},resource=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}] to PathMappings[size=1]
16:52:31.851 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - filterNameMap={}
16:52:31.851 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - pathFilters=null
16:52:31.851 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletFilterMap=null
16:52:31.852 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletPathMap=PathMappings[size=1]
16:52:31.852 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletNameMap={org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}}
16:52:31.852 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Adding Default404Servlet to ServletHandler@7a3793c7{STARTING}
16:52:31.852 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServletHandler@7a3793c7{STARTING} added {org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED},AUTO}
16:52:31.852 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServletHandler@7a3793c7{STARTING} added {[/]=>org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224,POJO}
16:52:31.852 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Path=/*[EMBEDDED:null] mapped to servlet=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499[EMBEDDED:null]
16:52:31.852 [main] DEBUG org.eclipse.jetty.http.pathmap.PathMappings - Added MappedResource[pathSpec=ServletPathSpec@5fa{/*},resource=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}] to PathMappings[size=1]
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Path=/[EMBEDDED:null] mapped to servlet=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224[EMBEDDED:null]
16:52:31.853 [main] DEBUG org.eclipse.jetty.http.pathmap.PathMappings - Added MappedResource[pathSpec=ServletPathSpec@4e{/},resource=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}] to PathMappings[size=2]
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - filterNameMap={}
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - pathFilters=null
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletFilterMap=null
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletPathMap=PathMappings[size=2]
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletNameMap={org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}, org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}}
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Path=/*[EMBEDDED:null] mapped to servlet=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499[EMBEDDED:null]
16:52:31.853 [main] DEBUG org.eclipse.jetty.http.pathmap.PathMappings - Added MappedResource[pathSpec=ServletPathSpec@5fa{/*},resource=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}] to PathMappings[size=1]
16:52:31.853 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - Path=/[EMBEDDED:null] mapped to servlet=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224[EMBEDDED:null]
16:52:31.854 [main] DEBUG org.eclipse.jetty.http.pathmap.PathMappings - Added MappedResource[pathSpec=ServletPathSpec@4e{/},resource=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}] to PathMappings[size=2]
16:52:31.854 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - filterNameMap={}
16:52:31.854 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - pathFilters=null
16:52:31.854 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletFilterMap=null
16:52:31.854 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletPathMap=PathMappings[size=2]
16:52:31.854 [main] DEBUG org.eclipse.jetty.servlet.ServletHandler - servletNameMap={org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499=org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}, org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224=org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}}
16:52:31.854 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting ServletHandler@7a3793c7{STARTING}
16:52:31.854 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @992ms ServletHandler@7a3793c7{STARTED}
16:52:31.854 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting org.eclipse.jetty.server.session.DefaultSessionCache@1205bd62[evict=-1,removeUnloadable=false,saveOnCreate=false,saveOnInactiveEvict=false]
16:52:31.854 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting org.eclipse.jetty.server.session.NullSessionDataStore@4032d386[passivating=false,graceSec=3600]
16:52:31.854 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @993ms org.eclipse.jetty.server.session.NullSessionDataStore@4032d386[passivating=false,graceSec=3600]
16:52:31.854 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @993ms org.eclipse.jetty.server.session.DefaultSessionCache@1205bd62[evict=-1,removeUnloadable=false,saveOnCreate=false,saveOnInactiveEvict=false]
16:52:31.855 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @993ms org.eclipse.jetty.server.session.SessionHandler1856158867==dftMaxIdleSec=0
16:52:31.857 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}
16:52:31.857 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @996ms org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499==org.apache.felix.http.base.internal.dispatch.DispatcherServlet@2b588c04{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STARTED}
16:52:31.859 [main] DEBUG org.eclipse.jetty.servlet.ServletHolder - Servlet.init null for org.apache.felix.http.base.internal.dispatch.DispatcherServlet-7f8a9499
16:52:31.859 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STOPPED}
16:52:31.859 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @997ms org.eclipse.jetty.servlet.ServletHandler$Default404Servlet-6aa61224==org.eclipse.jetty.servlet.ServletHandler$Default404Servlet@fa7ac5d7{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:null,STARTED}
16:52:31.859 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@791d1f8b{/,null,AVAILABLE}
16:52:31.860 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @998ms o.e.j.s.ServletContextHandler@791d1f8b{/,null,AVAILABLE}
16:52:31.860 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @998ms ContextHandlerCollection@2415fc55{STARTED}
16:52:31.860 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ErrorHandler@a37aefe{STOPPED}
16:52:31.860 [main] DEBUG org.eclipse.jetty.server.handler.AbstractHandler - starting ErrorHandler@a37aefe{STARTING}
16:52:31.860 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @998ms ErrorHandler@a37aefe{STARTED}
16:52:31.860 [main] INFO org.eclipse.jetty.server.Server - Started @998ms
16:52:31.860 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @998ms Server@5852c06f{STARTED}[9.4.42.v20210604]
16:52:31.860 [main] INFO org.eclipse.jetty.server.session - node0 Scavenging every 660000ms
16:52:31.865 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HttpConnectionFactory@60b4beb4[HTTP/1.1] added {HttpConfiguration@7fcf2fc1{32768/8192,8192/8192,https://:0,[]},POJO}
16:52:31.873 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{null, ()}{0.0.0.0:0} added {Server@5852c06f{STARTED}[9.4.42.v20210604],UNMANAGED}
16:52:31.874 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{null, ()}{0.0.0.0:0} added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.874 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{null, ()}{0.0.0.0:0} added {ScheduledExecutorScheduler@2d778add{STOPPED},AUTO}
16:52:31.874 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{null, ()}{0.0.0.0:0} added {org.eclipse.jetty.io.ArrayByteBufferPool@73302995,POJO}
16:52:31.874 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{null, (http/1.1)}{0.0.0.0:0} added {HttpConnectionFactory@60b4beb4[HTTP/1.1],AUTO}
16:52:31.874 [main] DEBUG org.eclipse.jetty.server.AbstractConnector - ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:0} added HttpConnectionFactory@60b4beb4[HTTP/1.1]
16:52:31.876 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:0} added {SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:0},MANAGED}
16:52:31.877 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STARTED}[9.4.42.v20210604] added {ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898},UNMANAGED}
16:52:31.877 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898}
16:52:31.881 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {sun.nio.ch.ServerSocketChannelImpl[/0.0.0.0:8898],POJO}
16:52:31.881 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ScheduledExecutorScheduler@2d778add{STOPPED}
16:52:31.881 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1020ms ScheduledExecutorScheduler@2d778add{STARTED}
16:52:31.881 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting HttpConnectionFactory@60b4beb4[HTTP/1.1]
16:52:31.882 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1020ms HttpConnectionFactory@60b4beb4[HTTP/1.1]
16:52:31.882 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898}
16:52:31.890 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.888Z added {SelectorProducer@6d167f58,POJO}
16:52:31.890 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.89Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.890 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.89Z created
16:52:31.891 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@12359a82{STOPPED} id=0 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.89Z,MANAGED}
16:52:31.891 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@12359a82{STOPPED} id=0 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.891 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.891Z added {SelectorProducer@479460a6,POJO}
16:52:31.891 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.891Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.892 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.891Z created
16:52:31.892 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@7164ca4c{STOPPED} id=1 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.892Z,MANAGED}
16:52:31.892 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@7164ca4c{STOPPED} id=1 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.892 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.892Z added {SelectorProducer@5be46f9d,POJO}
16:52:31.893 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.892Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.893 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.893Z created
16:52:31.893 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@3f91b517{STOPPED} id=2 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.893Z,MANAGED}
16:52:31.893 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@3f91b517{STOPPED} id=2 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.893 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.893Z added {SelectorProducer@7a220c9a,POJO}
16:52:31.894 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.894Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.894 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.894Z created
16:52:31.894 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@2421cc4{STOPPED} id=3 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.894Z,MANAGED}
16:52:31.894 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@2421cc4{STOPPED} id=3 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.895 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.895Z added {SelectorProducer@59a008ba,POJO}
16:52:31.895 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.895Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.895 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.895Z created
16:52:31.895 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@338c99c8{STOPPED} id=4 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.895Z,MANAGED}
16:52:31.896 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@338c99c8{STOPPED} id=4 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.896 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.896Z added {SelectorProducer@58ce9668,POJO}
16:52:31.896 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.896Z added {QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}],UNMANAGED}
16:52:31.896 [main] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.896Z created
16:52:31.897 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@172b013{STOPPED} id=5 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.897Z,MANAGED}
16:52:31.897 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {ManagedSelector@172b013{STOPPED} id=5 keys=-1 selected=-1 updates=0,AUTO}
16:52:31.897 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@12359a82{STOPPED} id=0 keys=-1 selected=-1 updates=0
16:52:31.897 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.897Z
16:52:31.897 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1036ms EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.897Z
16:52:31.899 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@1fa1cab1 startThread=0
16:52:31.899 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@70f02c32 on ManagedSelector@12359a82{STARTING} id=0 keys=0 selected=0 updates=0
16:52:31.899 [qtp442199874-33] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@1fa1cab1 in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.900 [qtp442199874-33] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@1583741e/SelectorProducer@6d167f58/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.899Z tryProduce false
16:52:31.901 [qtp442199874-33] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.901 [qtp442199874-33] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@70f02c32
16:52:31.902 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1040ms ManagedSelector@12359a82{STARTED} id=0 keys=0 selected=0 updates=0
16:52:31.902 [qtp442199874-33] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.902 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@7164ca4c{STOPPED} id=1 keys=-1 selected=-1 updates=0
16:52:31.902 [qtp442199874-33] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@273527b2 waiting with 0 keys
16:52:31.902 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.902Z
16:52:31.902 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1040ms EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.902Z
16:52:31.902 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@62010f5c startThread=0
16:52:31.902 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@51fadaff on ManagedSelector@7164ca4c{STARTING} id=1 keys=0 selected=0 updates=0
16:52:31.902 [qtp442199874-34] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@62010f5c in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=6,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.903 [qtp442199874-34] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@68df9280/SelectorProducer@479460a6/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=6,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.903Z tryProduce false
16:52:31.903 [qtp442199874-34] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.903 [qtp442199874-34] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@51fadaff
16:52:31.903 [qtp442199874-34] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.903 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1042ms ManagedSelector@7164ca4c{STARTED} id=1 keys=0 selected=0 updates=0
16:52:31.903 [qtp442199874-34] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@6c118677 waiting with 0 keys
16:52:31.903 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@3f91b517{STOPPED} id=2 keys=-1 selected=-1 updates=0
16:52:31.903 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=6,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.903Z
16:52:31.904 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1042ms EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=6,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.904Z
16:52:31.904 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@401f7633 startThread=0
16:52:31.904 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@31ff43be on ManagedSelector@3f91b517{STARTING} id=2 keys=0 selected=0 updates=0
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@401f7633 in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=5,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@4f3bbf68/SelectorProducer@5be46f9d/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=5,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.904Z tryProduce false
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@31ff43be
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.904 [qtp442199874-37] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@50edbfab waiting with 0 keys
16:52:31.904 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1043ms ManagedSelector@3f91b517{STARTED} id=2 keys=0 selected=0 updates=0
16:52:31.904 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@2421cc4{STOPPED} id=3 keys=-1 selected=-1 updates=0
16:52:31.904 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=5,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.904Z
16:52:31.905 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1043ms EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=5,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.904Z
16:52:31.905 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@5b6ec132 startThread=0
16:52:31.905 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@5c44c582 on ManagedSelector@2421cc4{STARTING} id=3 keys=0 selected=0 updates=0
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@5b6ec132 in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=4,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@68702e03/SelectorProducer@7a220c9a/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=4,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.905Z tryProduce false
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@5c44c582
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.905 [qtp442199874-35] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@706947e9 waiting with 0 keys
16:52:31.905 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1044ms ManagedSelector@2421cc4{STARTED} id=3 keys=0 selected=0 updates=0
16:52:31.906 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@338c99c8{STOPPED} id=4 keys=-1 selected=-1 updates=0
16:52:31.906 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=4,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.906Z
16:52:31.906 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1044ms EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=4,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.906Z
16:52:31.906 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@67d18ed7 startThread=0
16:52:31.906 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@2c78d320 on ManagedSelector@338c99c8{STARTING} id=4 keys=0 selected=0 updates=0
16:52:31.906 [qtp442199874-36] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@67d18ed7 in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.907 [qtp442199874-36] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@30c93896/SelectorProducer@59a008ba/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.906Z tryProduce false
16:52:31.907 [qtp442199874-36] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.907 [qtp442199874-36] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@2c78d320
16:52:31.907 [qtp442199874-36] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.907 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1045ms ManagedSelector@338c99c8{STARTED} id=4 keys=0 selected=0 updates=0
16:52:31.907 [qtp442199874-36] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@16b90ca9 waiting with 0 keys
16:52:31.907 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@172b013{STOPPED} id=5 keys=-1 selected=-1 updates=0
16:52:31.907 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.907Z
16:52:31.907 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1046ms EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.907Z
16:52:31.907 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@132e0cc startThread=0
16:52:31.908 [main] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change lazy=false org.eclipse.jetty.io.ManagedSelector$Start@7b205dbd on ManagedSelector@172b013{STARTING} id=5 keys=0 selected=0 updates=0
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$42/189207010@132e0cc in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=2,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@21ba0741/SelectorProducer@58ce9668/IDLE/p=false/QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=2,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-11-24T16:52:31.908Z tryProduce false
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@7b205dbd
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
16:52:31.908 [qtp442199874-39] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@73b3507a waiting with 0 keys
16:52:31.908 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1047ms ManagedSelector@172b013{STARTED} id=5 keys=0 selected=0 updates=0
16:52:31.908 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1047ms SelectorManager@ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898}
16:52:31.909 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898} added {acceptor-0@6cc558c6,POJO}
16:52:31.909 [main] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue acceptor-0@6cc558c6 startThread=0
16:52:31.909 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898}
16:52:31.909 [main] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @1047ms ServerConnector@20c0a64d{HTTP/1.1, (http/1.1)}{0.0.0.0:8898}
16:52:31.909 [qtp442199874-40] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run acceptor-0@6cc558c6 in QueuedThreadPool[qtp442199874]@1a5b6f42{STARTED,8<=8<=200,i=1,r=-1,q=0}[ReservedThreadExecutor@1e81f160{s=0/12,p=0}]
[INFO] Started Jetty 9.4.42.v20210604 at port(s) HTTP:8898 on context path / [minThreads=8,maxThreads=200,acceptors=1,selectors=6]
16:52:31.921 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - Server@5852c06f{STARTED}[9.4.42.v20210604] added {org.apache.felix.http.jetty.internal.RequestLogTracker@c9d0d6,POJO}
16:52:31.929 [main] DEBUG org.eclipse.sensinact.gateway.common.bundle.AbstractActivator - Starting introspection in bundle %s
16:52:31.934 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - check bundle: %s
16:52:31.936 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.SignedBundle - Better performance, data found (signatureFile)
16:52:31.936 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.SignatureFile - Looking for Manifest hash header [%s]
16:52:31.936 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - %s %s is valid? %s
16:52:32.032 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler.policiesStart(org.xml.sax.Attributes)
16:52:32.033 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler.policiesEnd()
16:52:32.037 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.ResourceInfoDefinition.identifierEnd()
16:52:32.041 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.AttributeDefinition.valueEnd()
16:52:32.041 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.ResourceInfoDefinition.attributeEnd()
16:52:32.041 [main] DEBUG org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler - org.eclipse.sensinact.gateway.generic.parser.XmlResourceConfigHandler.resourceInfoEnd()
16:52:32.046 [main] INFO org.eclipse.sensinact.gateway.generic.ExtModelConfiguration - ExtModelConfiguration initialized...
16:52:32.098 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - pre-processing done
16:52:32.110 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - check bundle: %s
16:52:32.136 [main] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - check bundle: %s
16:52:32.147 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - '%s' resource registered
16:52:32.149 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - '%s' resource registered
16:52:32.149 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - '%s' resource registered
16:52:32.150 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - '%s' resource registered
16:52:32.152 [main] INFO org.eclipse.sensinact.gateway.core.ServiceProviderImpl - New service discovered for '%s' service provider : %s
16:52:32.154 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - '%s' resource registered
16:52:32.154 [main] DEBUG org.eclipse.sensinact.gateway.core.ResourceImpl - %s already started
16:52:32.155 [main] DEBUG org.eclipse.sensinact.gateway.core.ServiceProviderImpl - ServiceProvider '%s' started
16:52:32.155 [main] DEBUG org.eclipse.sensinact.gateway.generic.Connector - Service provider discovered : slider
16:52:32.156 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - post-processing done
16:52:32.654 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.agent.mqtt.inst.internal.NorthboundBroker - Starting MQTT Agent point to server %s with prefix %s and qos %s
16:52:32.655 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.agent.mqtt.generic.internal.GenericMqttAgent - Connecting to broker tcp://127.0.0.1:1884 with QoS 1 and prefix /
16:52:32.655 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - check bundle: %s
16:52:32.656 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.SignedBundle - Better performance, data found (signatureFile)
16:52:32.656 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.SignatureFile - Looking for Manifest hash header [%s]
16:52:32.656 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.agent.broker~ag1)] DEBUG org.eclipse.sensinact.gateway.security.signature.internal.BundleValidationImpl - %s %s is valid? %s
16:52:32.715 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO org.sensinact.mqtt.server.internal.SensiNactServer - Persistent store file: null
16:52:32.780 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] DEBUG io.moquette.spi.impl.subscriptions.SubscriptionsStore - init invoked
16:52:32.781 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - retrieveAllSubscriptions returning subs []
16:52:32.781 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] DEBUG io.moquette.spi.impl.subscriptions.SubscriptionsStore - Reloading all stored subscriptions...subscription tree before
16:52:32.782 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO io.moquette.spi.impl.SensiNactProtocolProcessorBootstrapper - Starting without ACL definition
Nov 24, 2021 4:52:32 PM io.netty.bootstrap.AbstractBootstrap setChannelOption
WARNING: Unknown channel option 'TCP_NODELAY' for channel '[id: 0x6bc14598]'
16:52:32.924 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO io.moquette.server.netty.NettyAcceptor - Server binded host: , port: 1884
16:52:32.928 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO io.moquette.server.netty.NettyAcceptor - WebSocket is disabled
16:52:38.311 [Thread-14] INFO messageLogger - C->B CONNECT client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.311 [Thread-14] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type CONNECT
16:52:38.311 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - CONNECT for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.312 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Connect with keepAlive 60 s
16:52:38.312 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Connect create session <[id: 0xc78e39dc, L:/127.0.0.1:1884 - R:/127.0.0.1:56108]>
16:52:38.314 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Create persistent session for clientID <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.314 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - createNewSession for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b> with clean flag <true>
16:52:38.314 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - clientID 6a7c6545-04d9-4518-b076-ad49ffa4e56b is a newcome, creating it's empty subscriptions set
16:52:38.321 [Thread-14] INFO io.moquette.spi.ClientSession - cleaning old saved subscriptions for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.321 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - wipeSubscriptions
16:52:38.322 [Thread-14] DEBUG io.moquette.spi.ClientSession - Wiped subscriptions for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.324 [Thread-14] DEBUG io.moquette.spi.ClientSession - Removed messages in session for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.324 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Created session for client ID <6a7c6545-04d9-4518-b076-ad49ffa4e56b> with clean session true
16:52:38.325 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - Connection established
16:52:38.325 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - CONNECT processed
16:52:38.326 [Thread-14] INFO messageLogger - C->B SUBSCRIBE <6a7c6545-04d9-4518-b076-ad49ffa4e56b> to topics [[qos=1, topicFilter='/slider/cursor/position']]
16:52:38.326 [Thread-14] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type SUBSCRIBE
16:52:38.326 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - SUBSCRIBE client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:38.326 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - SUBSCRIBE client <6a7c6545-04d9-4518-b076-ad49ffa4e56b> on server 1884 packetID 1
16:52:38.327 [Thread-14] INFO io.moquette.spi.ClientSession - <6a7c6545-04d9-4518-b076-ad49ffa4e56b> subscribed to the topic filter </slider/cursor/position> with QoS 1 - LEAST_ONE
16:52:38.330 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - subscriptions_6a7c6545-04d9-4518-b076-ad49ffa4e56b: {}
16:52:38.330 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - addNewSubscription invoked with subscription [filter:/slider/cursor/position, cliID: 6a7c6545-04d9-4518-b076-ad49ffa4e56b, qos: LEAST_ONE, active: true]
16:52:38.331 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - SUBACK for packetID 1
16:52:38.331 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Persisting subscription [filter:/slider/cursor/position, cliID: 6a7c6545-04d9-4518-b076-ad49ffa4e56b, qos: LEAST_ONE, active: true]
16:52:38.331 [Thread-14] DEBUG io.moquette.spi.impl.subscriptions.SubscriptionsStore - root ref io.moquette.spi.impl.subscriptions.TreeNode@1dbc88a0, original root was io.moquette.spi.impl.subscriptions.TreeNode@5d76f2e6
16:52:38.332 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Publish persisted messages in session [filter:/slider/cursor/position, cliID: 6a7c6545-04d9-4518-b076-ad49ffa4e56b, qos: LEAST_ONE, active: true]
16:52:38.332 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBMessagesStore - searchMatching scanning all retained messages, presents are 0
16:52:38.333 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Found 0 messages to republish
16:52:38.363 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - pre-processing done
16:52:38.364 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - post-processing done
16:52:38.570 [Stack Engine Worker Thread] DEBUG org.eclipse.sensinact.gateway.agent.mqtt.inst.internal.SnaEventEventHandler - Event received update:{"notification":{"name":"position","type":"int","value":5,"timestamp":1637772758363},"type":"ATTRIBUTE_VALUE_UPDATED","uri":"/slider/cursor/position/value"}
16:52:38.880 [Thread-21] INFO messageLogger - C->B CONNECT client <paho14325821422064532>
16:52:38.881 [Thread-21] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type CONNECT
16:52:38.881 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - CONNECT for client <paho14325821422064532>
16:52:38.881 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Connect with keepAlive 60 s
16:52:38.881 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Connect create session <[id: 0x7e5bfcd1, L:/127.0.0.1:1884 - R:/127.0.0.1:56114]>
16:52:38.882 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Create persistent session for clientID <paho14325821422064532>
16:52:38.882 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - createNewSession for client <paho14325821422064532> with clean flag <true>
16:52:38.882 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - clientID paho14325821422064532 is a newcome, creating it's empty subscriptions set
16:52:38.883 [Thread-21] INFO io.moquette.spi.ClientSession - cleaning old saved subscriptions for client <paho14325821422064532>
16:52:38.883 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - wipeSubscriptions
16:52:38.884 [Thread-21] DEBUG io.moquette.spi.ClientSession - Wiped subscriptions for client <paho14325821422064532>
16:52:38.889 [Thread-21] DEBUG io.moquette.spi.ClientSession - Removed messages in session for client <paho14325821422064532>
16:52:38.890 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Created session for client ID <paho14325821422064532> with clean session true
16:52:38.890 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - Connection established
16:52:38.890 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - CONNECT processed
16:52:38.891 [Thread-21] DEBUG io.moquette.parser.netty.PublishDecoder - decode invoked with buffer PooledUnsafeDirectByteBuf(ridx: 1, widx: 30, cap: 1024)
16:52:38.891 [Thread-21] INFO messageLogger - C->B PUBLISH <paho14325821422064532> to topics </slider/cursor/position>
16:52:38.891 [Thread-21] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type PUBLISH
16:52:38.891 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - PUB --PUBLISH--> SRV executePublish invoked with io.moquette.parser.proto.messages.PublishMessage@24996c6
16:52:38.892 [Thread-21] DEBUG io.moquette.spi.impl.Qos1PublishHandler - publish2Subscribers_qos1 republishing to existing subscribers that matches the topic /slider/cursor/position
16:52:38.894 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - subscriptions_6a7c6545-04d9-4518-b076-ad49ffa4e56b: {/slider/cursor/position=[filter:/slider/cursor/position, cliID: 6a7c6545-04d9-4518-b076-ad49ffa4e56b, qos: LEAST_ONE, active: true]}
16:52:38.894 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBMessagesStore - storePublishForFuture store evt PublishEvent{m_msgID=1, clientID='paho14325821422064532', m_retain=false, m_qos=LEAST_ONE, m_topic='/slider/cursor/position'}
16:52:38.895 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBMessagesStore - storePublishForFuture guid <MessageGUID{guid='8cc206ea-1939-432d-b8ce-e58d137a9256'}>
16:52:38.897 [Thread-21] DEBUG io.moquette.spi.impl.MessagesPublisher - Broker republishing to client <6a7c6545-04d9-4518-b076-ad49ffa4e56b> topicFilter </slider/cursor/position> qos <LEAST_ONE>, active true
16:52:38.908 [Thread-21] INFO io.moquette.spi.persistence.MapDBSessionsStore - storing inflight clientID <6a7c6545-04d9-4518-b076-ad49ffa4e56b> messageID 1 guid <MessageGUID{guid='8cc206ea-1939-432d-b8ce-e58d137a9256'}>
16:52:38.909 [Thread-21] INFO io.moquette.spi.impl.PersistentQueueMessageSender - send publish message to <6a7c6545-04d9-4518-b076-ad49ffa4e56b> on topic </slider/cursor/position>
16:52:38.909 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - directSend invoked clientId <6a7c6545-04d9-4518-b076-ad49ffa4e56b> on topic </slider/cursor/position> QoS LEAST_ONE retained false messageID 1
16:52:38.910 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - content <5>
16:52:38.910 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - channel is writable
16:52:38.910 [Thread-21] DEBUG io.moquette.spi.impl.Qos1PublishHandler - clientIDs are {paho14325821422064532=ConnectionDescriptor{clientID=paho14325821422064532, cleanSession=true, state=ESTABLISHED}, 6a7c6545-04d9-4518-b076-ad49ffa4e56b=ConnectionDescriptor{clientID=6a7c6545-04d9-4518-b076-ad49ffa4e56b, cleanSession=true, state=ESTABLISHED}}
16:52:38.911 [Thread-21] INFO messageLogger - C<-B PUBACK <paho14325821422064532> packetID <1>
16:52:38.911 [Thread-14] INFO messageLogger - C<-B PUBLISH <6a7c6545-04d9-4518-b076-ad49ffa4e56b> to topics </slider/cursor/position>
16:52:38.911 [Thread-21] INFO io.moquette.spi.impl.Qos1PublishHandler - server 1884 replying with PubAck to MSG ID 1
[/slider/cursor/position]5
16:52:38.913 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - pre-processing done
16:52:38.915 [main] DEBUG org.eclipse.sensinact.gateway.generic.DefaultConnectorCustomizer - post-processing done
16:52:38.916 [Thread-14] INFO messageLogger - C->B PUBACK <6a7c6545-04d9-4518-b076-ad49ffa4e56b> packetID <1>
16:52:38.916 [Thread-14] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type PUBACK
16:52:38.917 [Thread-14] INFO io.moquette.spi.persistence.MapDBSessionsStore - inflight messageID 1 guid <MessageGUID{guid='8cc206ea-1939-432d-b8ce-e58d137a9256'}>
16:52:38.917 [Thread-14] INFO io.moquette.spi.persistence.MapDBSessionsStore - acknowledging inflight clientID <6a7c6545-04d9-4518-b076-ad49ffa4e56b> messageID 1
16:52:39.116 [Stack Engine Worker Thread] DEBUG org.eclipse.sensinact.gateway.agent.mqtt.inst.internal.SnaEventEventHandler - Event received update:{"notification":{"name":"position","type":"int","value":45,"timestamp":1637772758913},"type":"ATTRIBUTE_VALUE_UPDATED","uri":"/slider/cursor/position/value"}
16:52:39.118 [Thread-21] DEBUG io.moquette.parser.netty.PublishDecoder - decode invoked with buffer PooledUnsafeDirectByteBuf(ridx: 1, widx: 31, cap: 512)
16:52:39.118 [Thread-21] INFO messageLogger - C->B PUBLISH <paho14325821422064532> to topics </slider/cursor/position>
16:52:39.118 [Thread-21] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type PUBLISH
16:52:39.118 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - PUB --PUBLISH--> SRV executePublish invoked with io.moquette.parser.proto.messages.PublishMessage@240c5438
16:52:39.118 [Thread-21] DEBUG io.moquette.spi.impl.Qos1PublishHandler - publish2Subscribers_qos1 republishing to existing subscribers that matches the topic /slider/cursor/position
16:52:39.119 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - subscriptions_6a7c6545-04d9-4518-b076-ad49ffa4e56b: {/slider/cursor/position=[filter:/slider/cursor/position, cliID: 6a7c6545-04d9-4518-b076-ad49ffa4e56b, qos: LEAST_ONE, active: true]}
16:52:39.119 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBMessagesStore - storePublishForFuture store evt PublishEvent{m_msgID=2, clientID='paho14325821422064532', m_retain=false, m_qos=LEAST_ONE, m_topic='/slider/cursor/position'}
16:52:39.119 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBMessagesStore - storePublishForFuture guid <MessageGUID{guid='1663917c-0357-438f-b2bb-75675b3cb501'}>
16:52:39.120 [Thread-21] DEBUG io.moquette.spi.impl.MessagesPublisher - Broker republishing to client <6a7c6545-04d9-4518-b076-ad49ffa4e56b> topicFilter </slider/cursor/position> qos <LEAST_ONE>, active true
16:52:39.120 [Thread-21] INFO io.moquette.spi.persistence.MapDBSessionsStore - storing inflight clientID <6a7c6545-04d9-4518-b076-ad49ffa4e56b> messageID 1 guid <MessageGUID{guid='1663917c-0357-438f-b2bb-75675b3cb501'}>
16:52:39.122 [Thread-21] INFO io.moquette.spi.impl.PersistentQueueMessageSender - send publish message to <6a7c6545-04d9-4518-b076-ad49ffa4e56b> on topic </slider/cursor/position>
16:52:39.122 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - directSend invoked clientId <6a7c6545-04d9-4518-b076-ad49ffa4e56b> on topic </slider/cursor/position> QoS LEAST_ONE retained false messageID 1
16:52:39.122 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - content <45>
16:52:39.122 [Thread-21] DEBUG io.moquette.spi.impl.PersistentQueueMessageSender - channel is writable
16:52:39.122 [Thread-21] DEBUG io.moquette.spi.impl.Qos1PublishHandler - clientIDs are {paho14325821422064532=ConnectionDescriptor{clientID=paho14325821422064532, cleanSession=true, state=ESTABLISHED}, 6a7c6545-04d9-4518-b076-ad49ffa4e56b=ConnectionDescriptor{clientID=6a7c6545-04d9-4518-b076-ad49ffa4e56b, cleanSession=true, state=ESTABLISHED}}
16:52:39.123 [Thread-21] INFO messageLogger - C<-B PUBACK <paho14325821422064532> packetID <2>
16:52:39.123 [Thread-14] INFO messageLogger - C<-B PUBLISH <6a7c6545-04d9-4518-b076-ad49ffa4e56b> to topics </slider/cursor/position>
16:52:39.123 [Thread-21] INFO io.moquette.spi.impl.Qos1PublishHandler - server 1884 replying with PubAck to MSG ID 2
[/slider/cursor/position]45
16:52:39.125 [Thread-14] INFO messageLogger - C->B PUBACK <6a7c6545-04d9-4518-b076-ad49ffa4e56b> packetID <1>
16:52:39.125 [Thread-14] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type PUBACK
16:52:39.125 [Thread-14] INFO io.moquette.spi.persistence.MapDBSessionsStore - inflight messageID 1 guid <MessageGUID{guid='1663917c-0357-438f-b2bb-75675b3cb501'}>
16:52:39.125 [Thread-14] INFO io.moquette.spi.persistence.MapDBSessionsStore - acknowledging inflight clientID <6a7c6545-04d9-4518-b076-ad49ffa4e56b> messageID 1
16:52:39.129 [Thread-14] DEBUG io.moquette.parser.netty.DisconnectDecoder - Decoding disconnect
16:52:39.129 [Thread-14] INFO messageLogger - C->B DISCONNECT <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.130 [Thread-14] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type DISCONNECT
16:52:39.131 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - cleaning old saved subscriptions for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.131 [Thread-14] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - wipeSubscriptions
16:52:39.134 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Wiped subscriptions for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.134 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Removing messages in session's queue for client <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.135 [Thread-14] DEBUG io.moquette.spi.impl.ProtocolProcessor - Removed messages in session for client's queue <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.136 [Thread-21] DEBUG io.moquette.parser.netty.DisconnectDecoder - Decoding disconnect
16:52:39.137 [Thread-21] INFO messageLogger - C->B DISCONNECT <paho14325821422064532>
16:52:39.137 [Thread-14] INFO io.moquette.spi.impl.ProtocolProcessor - DISCONNECT client <6a7c6545-04d9-4518-b076-ad49ffa4e56b> finished
16:52:39.137 [Thread-21] INFO io.moquette.server.netty.NettyMQTTHandler - Received a message of type DISCONNECT
16:52:39.137 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - cleaning old saved subscriptions for client <paho14325821422064532>
16:52:39.137 [Thread-21] DEBUG io.moquette.spi.persistence.MapDBSessionsStore - wipeSubscriptions
16:52:39.137 [Thread-14] INFO messageLogger - Channel closed <6a7c6545-04d9-4518-b076-ad49ffa4e56b>
16:52:39.137 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Wiped subscriptions for client <paho14325821422064532>
16:52:39.137 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Removing messages in session's queue for client <paho14325821422064532>
16:52:39.137 [Thread-21] DEBUG io.moquette.spi.impl.ProtocolProcessor - Removed messages in session for client's queue <paho14325821422064532>
16:52:39.138 [Thread-21] INFO io.moquette.spi.impl.ProtocolProcessor - DISCONNECT client <paho14325821422064532> finished
16:52:39.138 [Thread-21] INFO messageLogger - Channel closed <paho14325821422064532>
16:52:39.139 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO org.sensinact.mqtt.server.internal.SensiNactServer - Server stopping...
16:52:39.346 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO io.moquette.server.netty.NettyAcceptor - Msg read: 18, msg wrote: 14
16:52:39.347 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO io.moquette.server.netty.NettyAcceptor - Bytes read: 376, bytes wrote: 3420
16:52:39.355 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] DEBUG io.moquette.spi.persistence.MapDBPersistentStore - closed disk storage
16:52:39.356 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] DEBUG io.moquette.spi.persistence.MapDBPersistentStore - Persistence commit scheduler is shutdown
16:52:39.356 [CM Event Dispatcher (Fire ConfigurationEvent: pid=mqtt.server~ag1)] INFO org.sensinact.mqtt.server.internal.SensiNactServer - Server stopped
[INFO] No Errors