[INFO] Scanning for projects... [WARNING] [WARNING] Some problems were encountered while building the effective model for nz.co.fortytwo.signalk.server:signalk-server:jar:0.0.1-SNAPSHOT [WARNING] 'dependencies.dependency.systemPath' for javax.jmdns:jmdns:jar should not point at files within the project directory, ${project.basedir}/src/main/release/jmdns-3.4.2-SNAPSHOT.jar will be unresolvable by dependent projects @ line 358, column 25 [WARNING] 'build.plugins.plugin.version' for org.codehaus.mojo:exec-maven-plugin is missing. @ line 376, column 12 [WARNING] 'build.plugins.plugin.version' for org.apache.maven.plugins:maven-surefire-plugin is missing. @ line 364, column 12 [WARNING] 'build.plugins.plugin.version' for org.mortbay.jetty:jetty-maven-plugin is missing. @ line 384, column 12 [WARNING] [WARNING] It is highly recommended to fix these problems because they threaten the stability of your build. [WARNING] [WARNING] For this reason, future Maven versions might no longer support building such malformed projects. [WARNING] [INFO] [INFO] ------------------------------------------------------------------------ [INFO] Building signalk-server 0.0.1-SNAPSHOT [INFO] ------------------------------------------------------------------------ [INFO] [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ signalk-server --- [WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent! [INFO] Copying 3 resources [INFO] [INFO] --- maven-compiler-plugin:3.0:compile (default-compile) @ signalk-server --- [INFO] Nothing to compile - all classes are up to date [INFO] [INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ signalk-server --- [WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent! [INFO] Copying 23 resources [INFO] [INFO] --- maven-compiler-plugin:3.0:testCompile (default-testCompile) @ signalk-server --- [INFO] Changes detected - recompiling the module! [WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent! [INFO] Compiling 19 source files to /Users/jeremy/IdeaProjects/SignalK/signalk-server-java/target/test-classes [INFO] [INFO] --- maven-surefire-plugin:2.12.4:test (default-test) @ signalk-server --- [INFO] Surefire report directory: /Users/jeremy/IdeaProjects/SignalK/signalk-server-java/target/surefire-reports ------------------------------------------------------- T E S T S ------------------------------------------------------- Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=32m; support was removed in 8.0 Running nz.co.fortytwo.signalk.server.RestApiTest 2016-01-13 20:40:08,989 [ main] SignalKModelFactory INFO Checking for previous config: /Users/jeremy/IdeaProjects/SignalK/signalk-server-java/./conf/signalk-config.json 2016-01-13 20:40:09,042 [ main] SignalKModelFactory INFO Saved config loaded from ./conf/signalk-config.json 2016-01-13 20:40:09,042 [ main] SignalKModelFactory INFO self set to: motu 2016-01-13 20:40:09,601 [ main] RestApiTest INFO ******************************************************************************** 2016-01-13 20:40:09,602 [ main] RestApiTest INFO Testing: shouldGetJsonResponse(nz.co.fortytwo.signalk.server.RestApiTest) 2016-01-13 20:40:09,602 [ main] RestApiTest INFO ******************************************************************************** 2016-01-13 20:40:09,602 [ main] RestApiTest DEBUG setUp test 2016-01-13 20:40:09,617 [ main] RestApiTest DEBUG Using jndi.properties from classpath root 2016-01-13 20:40:09,855 [ main] DefaultTypeConverter INFO Loaded 210 type converters 2016-01-13 20:40:09,900 [ main] ManagementContext DEBUG Creating RMIRegistry on port 1099 2016-01-13 20:40:09,914 [ main] ManagementContext DEBUG Probably not using JRE 1.4: mx4j.tools.naming.NamingService 2016-01-13 20:40:09,915 [ main] ManagementContext DEBUG Created JMXConnectorServer javax.management.remote.rmi.RMIConnectorServer@7770f470 2016-01-13 20:40:09,916 [ JMX connector] ManagementContext DEBUG Starting JMXConnectorServer... 2016-01-13 20:40:09,956 [ main] BrokerService INFO Using Persistence Adapter: MemoryPersistenceAdapter 2016-01-13 20:40:10,004 [ JMX connector] ManagementContext INFO JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi 2016-01-13 20:40:10,093 [ main] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.Connection 2016-01-13 20:40:10,099 [ main] TaskRunnerFactory DEBUG Initialized TaskRunnerFactory[ActiveMQ BrokerService[localhost] Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@72cde7cc[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:40:10,109 [ main] BrokerService INFO Apache ActiveMQ 5.11.1 (localhost, ID:Jeremys-iMac.local-62260-1452746409970-0:1) is starting 2016-01-13 20:40:10,120 [ main] TransportConnector DEBUG Publishing: tcp://localhost:61616 for broker transport URI: tcp://localhost:61616 2016-01-13 20:40:10,120 [ main] TransportConnector DEBUG Publishing: ws://localhost:61614 for broker transport URI: ws://localhost:61614 2016-01-13 20:40:10,120 [ main] TransportConnector DEBUG Publishing: stomp+nio://0.0.0.0:61613 for broker transport URI: stomp+nio://0.0.0.0:61613?transport.hbGracePeriodMultiplier=1.5 2016-01-13 20:40:10,121 [ main] TransportConnector DEBUG Publishing: mqtt+nio://0.0.0.0:1883 for broker transport URI: mqtt+nio://0.0.0.0:1883 2016-01-13 20:40:10,121 [ main] TransportServerThreadSupport INFO Listening for connections at: tcp://localhost:61616 2016-01-13 20:40:10,121 [ main] TransportConnector INFO Connector tcp://localhost:61616 started {} 2016-01-13 20:40:10,161 [ main] Server INFO jetty-8.1.16.v20140903 2016-01-13 20:40:10,212 [ main] AbstractConnector INFO Started SelectChannelConnector@localhost:61614 2016-01-13 20:40:10,212 [ main] WSTransportServer INFO Listening for connections at ws://localhost:61614 2016-01-13 20:40:10,212 [ main] TransportConnector INFO Connector ws://localhost:61614 started 2016-01-13 20:40:10,217 [ main] TransportServerThreadSupport INFO Listening for connections at: stomp+nio://Jeremys-iMac.local:61613?transport.hbGracePeriodMultiplier=1.5 2016-01-13 20:40:10,217 [ main] TransportConnector INFO Connector stomp+nio://0.0.0.0:61613?transport.hbGracePeriodMultiplier=1.5 started 2016-01-13 20:40:10,220 [ main] TransportServerThreadSupport INFO Listening for connections at: mqtt+nio://Jeremys-iMac.local:1883 2016-01-13 20:40:10,221 [ main] TransportConnector INFO Connector mqtt+nio://0.0.0.0:1883 started 2016-01-13 20:40:10,221 [ main] BrokerService INFO Apache ActiveMQ 5.11.1 (localhost, ID:Jeremys-iMac.local-62260-1452746409970-0:1) started 2016-01-13 20:40:10,221 [ main] BrokerService INFO For help or more information please see: http://activemq.apache.org 2016-01-13 20:40:10,222 [ main] BrokerService WARN Memory Usage for the Broker (1024 mb) is more than the maximum available for the JVM: 455 mb - resetting to 70% of maximum available: 318 mb 2016-01-13 20:40:10,228 [ main] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.MasterBroker 2016-01-13 20:40:10,230 [ main] SignalKCamelTestSupport DEBUG Started broker 2016-01-13 20:40:10,233 [ main] RouteManager INFO Websocket port:3000 2016-01-13 20:40:10,233 [ main] RouteManager INFO Signalk REST API port:8080 2016-01-13 20:40:10,233 [ main] RestApiTest DEBUG Using created route builder: Routes: [] 2016-01-13 20:40:10,238 [ main] SignalKModelFactory INFO Checking for previous state: /Users/jeremy/IdeaProjects/SignalK/signalk-server-java/./conf/self.json 2016-01-13 20:40:10,239 [ main] SignalKModelFactory INFO Saved state loaded from ./conf/self.json 2016-01-13 20:41:19,564 [ main] InternalLoggerFactory DEBUG Using SLF4J as the default logging framework 2016-01-13 20:41:19,566 [ main] PlatformDependent0 DEBUG java.nio.Buffer.address: available 2016-01-13 20:41:19,567 [ main] PlatformDependent0 DEBUG sun.misc.Unsafe.theUnsafe: available 2016-01-13 20:41:19,567 [ main] PlatformDependent0 DEBUG sun.misc.Unsafe.copyMemory: available 2016-01-13 20:41:19,567 [ main] PlatformDependent0 DEBUG java.nio.Bits.unaligned: true 2016-01-13 20:41:19,568 [ main] PlatformDependent DEBUG Java version: 8 2016-01-13 20:41:19,569 [ main] PlatformDependent DEBUG -Dio.netty.noUnsafe: false 2016-01-13 20:41:19,569 [ main] PlatformDependent DEBUG sun.misc.Unsafe: available 2016-01-13 20:41:19,569 [ main] PlatformDependent DEBUG -Dio.netty.noJavassist: false 2016-01-13 20:41:19,570 [ main] PlatformDependent DEBUG Javassist: unavailable 2016-01-13 20:41:19,570 [ main] PlatformDependent DEBUG You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes. Please check the configuration for better performance. 2016-01-13 20:41:19,570 [ main] PlatformDependent DEBUG -Dio.netty.tmpdir: /var/folders/z4/l31nzs996rl_yftg0rr864d00000gn/T (java.io.tmpdir) 2016-01-13 20:41:19,570 [ main] PlatformDependent DEBUG -Dio.netty.bitMode: 64 (sun.arch.data.model) 2016-01-13 20:41:19,570 [ main] PlatformDependent DEBUG -Dio.netty.noPreferDirect: false 2016-01-13 20:41:19,575 [ main] MultithreadEventLoopGroup DEBUG -Dio.netty.eventLoopThreads: 16 2016-01-13 20:41:19,588 [ main] NioEventLoop DEBUG -Dio.netty.noKeySetOptimization: false 2016-01-13 20:41:19,588 [ main] NioEventLoop DEBUG -Dio.netty.selectorAutoRebuildThreshold: 512 2016-01-13 20:41:19,602 [ main] SedaEndpoint INFO Endpoint Endpoint[seda://inputData?purgeWhenStopping=true&size=100] is using shared queue: seda://inputData with size: 100 2016-01-13 20:41:19,611 [ main] ThreadLocalRandom DEBUG -Dio.netty.initialSeedUniquifier: 0xf22bda4a3d5a715e (took 0 ms) 2016-01-13 20:41:19,629 [ main] ByteBufUtil DEBUG -Dio.netty.allocator.type: unpooled 2016-01-13 20:41:19,629 [ main] ByteBufUtil DEBUG -Dio.netty.threadLocalDirectBufferSize: 65536 2016-01-13 20:41:19,631 [ main] NetUtil DEBUG Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1) 2016-01-13 20:41:19,631 [ main] NetUtil DEBUG /proc/sys/net/core/somaxconn: 128 (non-existent) 2016-01-13 20:41:19,638 [ main] NettyServer INFO Server listening on TCP /0:0:0:0:0:0:0:0:55555 2016-01-13 20:41:19,650 [ nioEventLoopGroup-2-2] CamelUdpNettyHandler DEBUG channelActive:/0:0:0:0:0:0:0:0:55554 2016-01-13 20:41:19,650 [ main] NettyServer INFO Server listening on UDP /0:0:0:0:0:0:0:0:55554 2016-01-13 20:41:19,653 [ main] NettyServer INFO Server listening on TCP /0:0:0:0:0:0:0:0:55557 2016-01-13 20:41:19,654 [ main] NettyServer INFO Server listening on UDP /0:0:0:0:0:0:0:0:55556 2016-01-13 20:41:19,654 [ nioEventLoopGroup-4-2] CamelUdpNettyHandler DEBUG channelActive:/0:0:0:0:0:0:0:0:55556 2016-01-13 20:41:19,683 [ main] SedaEndpoint INFO Endpoint Endpoint[seda://nmeaOutput?purgeWhenStopping=true&size=100] is using shared queue: seda://nmeaOutput with size: 100 2016-01-13 20:41:19,683 [ main] SedaEndpoint INFO Endpoint Endpoint[seda://commonOut?purgeWhenStopping=true&size=100] is using shared queue: seda://commonOut with size: 100 2016-01-13 20:41:19,766 [ main] Filter DEBUG Parsed filter: ($['Heading']EXISTStrue && $['Reference']=='Magnetic') 2016-01-13 20:41:19,767 [ main] Filter DEBUG Parsed filter: $['Variation']EXISTStrue 2016-01-13 20:41:19,768 [ main] PathCompiler DEBUG Using cached path: $.fields.User_IDtrue[] 2016-01-13 20:41:19,770 [ main] Filter DEBUG Parsed filter: $['COG_Reference']=='True' 2016-01-13 20:41:19,770 [ main] PathCompiler DEBUG Using cached path: $.COG_Referencefalse[] 2016-01-13 20:41:19,770 [ main] Filter DEBUG Parsed filter: $['COG_Reference']=='Magnetic' 2016-01-13 20:41:19,771 [ main] PathCompiler DEBUG Using cached path: $.fields.User_IDtrue[] 2016-01-13 20:41:19,771 [ main] PathCompiler DEBUG Using cached path: $.fields.SOGtrue[] 2016-01-13 20:41:19,771 [ main] PathCompiler DEBUG Using cached path: $.fields.Longitudetrue[] 2016-01-13 20:41:19,771 [ main] PathCompiler DEBUG Using cached path: $.fields.Latitudetrue[] 2016-01-13 20:41:19,772 [ main] PathCompiler DEBUG Using cached path: $.COG_Referencefalse[] 2016-01-13 20:41:19,772 [ main] Filter DEBUG Parsed filter: $['COG_Reference']=='True' 2016-01-13 20:41:19,772 [ main] PathCompiler DEBUG Using cached path: $.fields.SOGtrue[] 2016-01-13 20:41:19,772 [ main] PathCompiler DEBUG Using cached path: $.COG_Referencefalse[] 2016-01-13 20:41:19,772 [ main] Filter DEBUG Parsed filter: ($['Set']EXISTStrue && $['COG_Reference']=='True') 2016-01-13 20:41:19,773 [ main] PathCompiler DEBUG Using cached path: $.fields.User_IDtrue[] 2016-01-13 20:41:19,773 [ main] PathCompiler DEBUG Using cached path: $.fields.COGtrue[] 2016-01-13 20:41:19,773 [ main] PathCompiler DEBUG Using cached path: $.fields.SOGtrue[] 2016-01-13 20:41:19,773 [ main] PathCompiler DEBUG Using cached path: $.fields.Longitudetrue[] 2016-01-13 20:41:19,773 [ main] PathCompiler DEBUG Using cached path: $.fields.Latitudetrue[] 2016-01-13 20:41:19,775 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,775 [ main] Filter DEBUG Parsed filter: $['Reference']=='Apparent' 2016-01-13 20:41:19,775 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,775 [ main] Filter DEBUG Parsed filter: $['Reference']=='True_(boat_referenced)' 2016-01-13 20:41:19,776 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,776 [ main] Filter DEBUG Parsed filter: $['Reference']=='True_(ground_referenced_to_North)' 2016-01-13 20:41:19,776 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,776 [ main] Filter DEBUG Parsed filter: $['Reference']=='Apparent' 2016-01-13 20:41:19,776 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,776 [ main] Filter DEBUG Parsed filter: $['Reference']=='True_(boat_referenced)' 2016-01-13 20:41:19,777 [ main] PathCompiler DEBUG Using cached path: $.Referencefalse[] 2016-01-13 20:41:19,777 [ main] Filter DEBUG Parsed filter: $['Reference']=='True_(ground_referenced_to_North)' 2016-01-13 20:41:19,778 [ main] Filter DEBUG Parsed filter: $['Position']EXISTStrue 2016-01-13 20:41:19,778 [ main] Filter DEBUG Parsed filter: $['Set_Reference']=='True' 2016-01-13 20:41:19,778 [ main] PathCompiler DEBUG Using cached path: $.fields.Drifttrue[] 2016-01-13 20:41:19,779 [ main] PathCompiler DEBUG Using cached path: $.fields.User_IDtrue[] 2016-01-13 20:41:19,779 [ main] PathCompiler DEBUG Using cached path: $.fields.Nametrue[] 2016-01-13 20:41:19,886 [ main] SignalKCamelTestSupport$1 INFO Serving static files from /Users/jeremy/IdeaProjects/SignalK/signalk-server-java/./signalk-static 2016-01-13 20:41:19,947 [ main] DefaultCamelContext INFO Apache Camel 2.15.2 (CamelContext: camel-1) is starting 2016-01-13 20:41:19,947 [ main] DefaultManagementStrategy INFO JMX is disabled 2016-01-13 20:41:19,988 [ main] SedaEndpoint INFO Endpoint Endpoint[seda://websockets?purgeWhenStopping=true&size=100] is using shared queue: seda://websockets with size: 100 2016-01-13 20:41:19,993 [ main] SedaEndpoint INFO Endpoint Endpoint[seda://tcp?purgeWhenStopping=true&size=100] is using shared queue: seda://tcp with size: 100 2016-01-13 20:41:20,088 [ ActiveMQ NIO Worker 2] StompInactivityMonitor DEBUG Stomp Inactivity Monitor read check interval: 0ms, write check interval: 0ms 2016-01-13 20:41:20,088 [ ActiveMQ NIO Worker 2] ProtocolConverter DEBUG Stomp Connect heartbeat conf RW[0,0] 2016-01-13 20:41:20,090 [ ActiveMQ NIO Worker 2] TransportConnection DEBUG Setting up new connection id: ID:Jeremys-iMac.local-62260-1452746409970-2:1, address: tcp://127.0.0.1:62311, info: ConnectionInfo {commandId = 0, responseRequired = true, connectionId = ID:Jeremys-iMac.local-62260-1452746409970-2:1, clientId = ID:Jeremys-iMac.local-62260-1452746409970-2:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} 2016-01-13 20:41:20,122 [ main] DefaultHttpParams DEBUG Set parameter http.useragent = Jakarta Commons-HttpClient/3.1 2016-01-13 20:41:20,122 [ main] DefaultHttpParams DEBUG Set parameter http.protocol.version = HTTP/1.1 2016-01-13 20:41:20,123 [ main] DefaultHttpParams DEBUG Set parameter http.connection-manager.class = class org.apache.commons.httpclient.SimpleHttpConnectionManager 2016-01-13 20:41:20,123 [ main] DefaultHttpParams DEBUG Set parameter http.protocol.cookie-policy = default 2016-01-13 20:41:20,123 [ main] DefaultHttpParams DEBUG Set parameter http.protocol.element-charset = US-ASCII 2016-01-13 20:41:20,123 [ main] DefaultHttpParams DEBUG Set parameter http.protocol.content-charset = ISO-8859-1 2016-01-13 20:41:20,124 [ main] DefaultHttpParams DEBUG Set parameter http.method.retry-handler = org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@21d8bcbe 2016-01-13 20:41:20,124 [ main] DefaultHttpParams DEBUG Set parameter http.dateparser.patterns = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-MMM-yy HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, dd-MMM-yyyy HH:mm:ss z, EEE, dd-MMM-yyyy HH-mm-ss z, EEE, dd MMM yy HH:mm:ss z, EEE dd-MMM-yyyy HH:mm:ss z, EEE dd MMM yyyy HH:mm:ss z, EEE dd-MMM-yyyy HH-mm-ss z, EEE dd-MMM-yy HH:mm:ss z, EEE dd MMM yy HH:mm:ss z, EEE,dd-MMM-yy HH:mm:ss z, EEE,dd-MMM-yyyy HH:mm:ss z, EEE, dd-MM-yyyy HH:mm:ss z] 2016-01-13 20:41:20,137 [ ActiveMQ NIO Worker 2] StompInactivityMonitor DEBUG Stomp Inactivity Monitor read check interval: 0ms, write check interval: 0ms 2016-01-13 20:41:20,137 [ ActiveMQ NIO Worker 2] ProtocolConverter DEBUG Stomp Connect heartbeat conf RW[0,0] 2016-01-13 20:41:20,137 [ ActiveMQ NIO Worker 2] TransportConnection DEBUG Setting up new connection id: ID:Jeremys-iMac.local-62260-1452746409970-2:2, address: tcp://127.0.0.1:62312, info: ConnectionInfo {commandId = 0, responseRequired = true, connectionId = ID:Jeremys-iMac.local-62260-1452746409970-2:2, clientId = ID:Jeremys-iMac.local-62260-1452746409970-2:2, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} 2016-01-13 20:41:20,143 [ main] DefaultCamelContext INFO AllowUseOriginalMessage is enabled. If access to the original message is not needed, then its recommended to turn this option off as it may improve performance. 2016-01-13 20:41:20,143 [ main] DefaultCamelContext INFO StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html 2016-01-13 20:41:20,149 [ main] WebsocketComponent WARN JMX disabled in CamelContext. Jetty JMX extensions will remain disabled. 2016-01-13 20:41:20,156 [ main] WebsocketComponent INFO Jetty Server starting on host: 0.0.0.0:3000 2016-01-13 20:41:20,156 [ main] Server INFO jetty-8.1.16.v20140903 2016-01-13 20:41:20,160 [ main] AbstractConnector INFO Started SelectChannelConnector@0.0.0.0:3000 2016-01-13 20:41:20,168 [ main] MQTTEndpoint INFO Connecting to tcp://0.0.0.0:1883?publishTopicName=signalk.dlq using 10 seconds timeout 2016-01-13 20:41:20,180 [ ActiveMQ NIO Worker 2] ThreadPoolUtils DEBUG Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@3dc114ce[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: true took: 0.000 seconds. 2016-01-13 20:41:20,180 [ ActiveMQ NIO Worker 2] MQTTProtocolConverter DEBUG MQTT Client 0a000143f369569726f0 requests heart beat of 30000 ms 2016-01-13 20:41:20,180 [ ActiveMQ NIO Worker 2] MQTTProtocolConverter DEBUG MQTT Client 0a000143f369569726f0 established heart beat of 30000 ms (30000 ms + 15000 ms grace period) 2016-01-13 20:41:20,181 [ ActiveMQ NIO Worker 2] TransportConnection DEBUG Setting up new connection id: ID:Jeremys-iMac.local-62260-1452746409970-5:1, address: tcp://10.0.1.67:62313, info: ConnectionInfo {commandId = 0, responseRequired = true, connectionId = ID:Jeremys-iMac.local-62260-1452746409970-5:1, clientId = 0a000143f369569726f0, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} 2016-01-13 20:41:20,184 [ ActiveMQ NIO Worker 2] MQTTProtocolConverter DEBUG MQTT Using subscription strategy: mqtt-default-subscriptions 2016-01-13 20:41:20,185 [ ActiveMQ NIO Worker 2] MQTTProtocolConverter DEBUG MQTT Client 0a000143f369569726f0 connected. (version: 3) 2016-01-13 20:41:20,187 [ hawtdispatch-DEFAULT-4] MQTTEndpoint WARN No topic subscriptions were specified in configuration 2016-01-13 20:41:20,187 [ hawtdispatch-DEFAULT-4] MQTTEndpoint INFO MQTT Connection connected to tcp://0.0.0.0:1883?publishTopicName=signalk.dlq 2016-01-13 20:41:20,192 [ main] DefaultCamelContext INFO Route: INPUT started and consuming from: Endpoint[seda://inputData?purgeWhenStopping=true&size=100] 2016-01-13 20:41:20,192 [ main] DefaultCamelContext INFO Route: Websocket Tx started and consuming from: Endpoint[seda://websockets?purgeWhenStopping=true&size=100] 2016-01-13 20:41:20,193 [ main] DefaultCamelContext INFO Route: Websocket Rx started and consuming from: Endpoint[skWebsocket://0.0.0.0:3000/signalk/v1/stream] 2016-01-13 20:41:20,194 [ main] DefaultCamelContext INFO Route: Netty OUTPUT_TCP Server started and consuming from: Endpoint[seda://tcp?purgeWhenStopping=true&size=100] 2016-01-13 20:41:20,194 [ main] DefaultCamelContext INFO Route: Netty OUTPUT_NMEA Server started and consuming from: Endpoint[seda://nmeaOutput?purgeWhenStopping=true&size=100] 2016-01-13 20:41:20,195 [ main] DefaultCamelContext INFO Route: COMMON_OUT started and consuming from: Endpoint[seda://commonOut?purgeWhenStopping=true&size=100] 2016-01-13 20:41:20,195 [ main] DefaultCamelContext INFO Route: MQTT out started and consuming from: Endpoint[direct://mqtt] 2016-01-13 20:41:20,195 [ main] DefaultCamelContext INFO Route: STOMP out started and consuming from: Endpoint[direct://stomp] 2016-01-13 20:41:20,195 [ main] DefaultCamelContext INFO Route: Heartbeat started and consuming from: Endpoint[timer://heartbeat?fixedRate=true&period=1000] 2016-01-13 20:41:20,198 [ main] JettyHttpComponent INFO Using default Jetty continuation timeout for: Endpoint[http://0.0.0.0:8080/signalk/v1/auth?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,199 [ main] Server INFO jetty-8.1.16.v20140903 2016-01-13 20:41:20,200 [ main] AbstractConnector INFO Started SelectChannelConnector@0.0.0.0:8080 2016-01-13 20:41:20,203 [ main] DefaultCamelContext INFO Route: REST Authenticate started and consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/auth?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,203 [ main] DefaultCamelContext INFO Route: REST Discovery started and consuming from: Endpoint[http://0.0.0.0:8080/signalk?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,203 [ main] DefaultCamelContext INFO Route: REST Api started and consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/api?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: REST Install started and consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/install?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: REST Upgrade started and consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/upgrade?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: Declination started and consuming from: Endpoint[timer://background?fixedRate=true&period=60000] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: True Wind started and consuming from: Endpoint[timer://wind?fixedRate=true&period=1000] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: AnchorWatch started and consuming from: Endpoint[timer://anchorWatch?fixedRate=true&period=1000] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: Alarms started and consuming from: Endpoint[timer://alarms?fixedRate=true&period=1000] 2016-01-13 20:41:20,204 [ main] DefaultCamelContext INFO Route: NMEA0183 started and consuming from: Endpoint[timer://nmea0183?fixedRate=true&period=1000] 2016-01-13 20:41:20,205 [ main] DefaultCamelContext INFO Route: STOMP In started and consuming from: Endpoint[skStomp://queue:signalk.put] 2016-01-13 20:41:20,205 [ main] MQTTEndpoint INFO Connecting to tcp://0.0.0.0:1883 using 10 seconds timeout 2016-01-13 20:41:20,208 [ ActiveMQ NIO Worker 3] MQTTProtocolConverter DEBUG MQTT Client 0a000143f36a569726f0 requests heart beat of 30000 ms 2016-01-13 20:41:20,208 [ ActiveMQ NIO Worker 3] MQTTProtocolConverter DEBUG MQTT Client 0a000143f36a569726f0 established heart beat of 30000 ms (30000 ms + 15000 ms grace period) 2016-01-13 20:41:20,209 [ ActiveMQ NIO Worker 3] TransportConnection DEBUG Setting up new connection id: ID:Jeremys-iMac.local-62260-1452746409970-5:2, address: tcp://10.0.1.67:62314, info: ConnectionInfo {commandId = 0, responseRequired = true, connectionId = ID:Jeremys-iMac.local-62260-1452746409970-5:2, clientId = 0a000143f36a569726f0, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} 2016-01-13 20:41:20,211 [ ActiveMQ NIO Worker 2] ActiveMqSubscriptionFilter DEBUG Adding subscription:ConsumerInfo {commandId = 3, responseRequired = false, consumerId = ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1, destination = queue://signalk.put, prefetchSize = 1000, maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true, selector = null, clientId = null, subscriptionName = null, noLocal = false, exclusive = false, retroactive = false, priority = 0, brokerPath = null, optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate = null} 2016-01-13 20:41:20,211 [ ActiveMQ NIO Worker 2] AbstractRegion DEBUG localhost adding consumer: ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1 for destination: queue://signalk.put 2016-01-13 20:41:20,211 [ ActiveMQ NIO Worker 3] MQTTProtocolConverter DEBUG MQTT Using subscription strategy: mqtt-default-subscriptions 2016-01-13 20:41:20,211 [ ActiveMQ NIO Worker 2] AbstractRegion DEBUG localhost adding destination: queue://signalk.put 2016-01-13 20:41:20,211 [ ActiveMQ NIO Worker 3] MQTTProtocolConverter DEBUG MQTT Client 0a000143f36a569726f0 connected. (version: 3) 2016-01-13 20:41:20,214 [ hawtdispatch-DEFAULT-5] MQTTEndpoint INFO MQTT Connection connected to tcp://0.0.0.0:1883 2016-01-13 20:41:20,216 [ ActiveMQ NIO Worker 3] ActiveMqSubscriptionFilter DEBUG Adding subscription:ConsumerInfo {commandId = 3, responseRequired = true, consumerId = ID:Jeremys-iMac.local-62260-1452746409970-5:2:-1:1, destination = topic://signalk/put, prefetchSize = 32767, maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true, selector = null, clientId = null, subscriptionName = null, noLocal = false, exclusive = false, retroactive = true, priority = 0, brokerPath = null, optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate = null} 2016-01-13 20:41:20,216 [ ActiveMQ NIO Worker 3] AbstractRegion DEBUG localhost adding consumer: ID:Jeremys-iMac.local-62260-1452746409970-5:2:-1:1 for destination: topic://signalk/put 2016-01-13 20:41:20,216 [ ActiveMQ NIO Worker 3] AbstractRegion DEBUG localhost adding destination: topic://signalk/put 2016-01-13 20:41:20,220 [ ActiveMQ NIO Worker 3] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.Topic 2016-01-13 20:41:20,227 [ ActiveMQ NIO Worker 3] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.Consumer.Topic.signalk/put 2016-01-13 20:41:20,228 [ ActiveMQ NIO Worker 2] Queue DEBUG queue://signalk.put, subscriptions=0, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 2016-01-13 20:41:20,229 [ ActiveMQ NIO Worker 2] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.Queue 2016-01-13 20:41:20,230 [ main] DefaultCamelContext INFO Route: MQTT In started and consuming from: Endpoint[mqtt:signalk?host=tcp://0.0.0.0:1883&subscribeTopicName=signalk.put] 2016-01-13 20:41:20,231 [ main] DefaultCamelContext INFO Total 21 routes, of which 21 is started. 2016-01-13 20:41:20,232 [ main] DefaultCamelContext INFO Apache Camel 2.15.2 (CamelContext: camel-1) started in 0.284 seconds 2016-01-13 20:41:20,237 [ main] RestApiTest DEBUG Routing Rules are: [EventDrivenConsumerRoute[Endpoint[seda://inputData?purgeWhenStopping=true&size=100] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.InputFilterProcessor@3bd7f8dc]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.IncomingSecurityFilter@2f2bf0e2]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.StorageProcessor@1eba372c]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.NMEAProcessor@21ec5d87]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.AISProcessor@25f9407e]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.N2KProcessor@552518c3]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.JsonSubscribeProcessor@1a69561c]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.DeltaImportProcessor@59aa20b3]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.FullImportProcessor@363f6148]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.ValidationProcessor@4b21844c]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.TrackProcessor@1b28f282]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.SignalkModelProcessor@138fe6ec]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.JsonListProcessor@5e77f0f4]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.JsonGetProcessor@19b30c92]]]]], EventDrivenConsumerRoute[Endpoint[seda://websockets?purgeWhenStopping=true&size=100] -> Channel[Filter[if: (header{OUTPUT_TYPE} == OUTPUT_WS) or (header{websocket.connectionKey} == websocket.sendToAll) do: Channel[sendTo(Endpoint[skWebsocket://0.0.0.0:3000/signalk/v1/stream])]]]], EventDrivenConsumerRoute[Endpoint[skWebsocket://0.0.0.0:3000/signalk/v1/stream] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.WsSessionProcessor@455351c4]], Channel[sendTo(Endpoint[seda://inputData?purgeWhenStopping=true&size=100])]]]], EventDrivenConsumerRoute[Endpoint[seda://tcp?purgeWhenStopping=true&size=100] -> Channel[Filter[if: (header{OUTPUT_TYPE} == OUTPUT_TCP) or (header{websocket.connectionKey} == websocket.sendToAll) do: Channel[DelegateSync[nz.co.fortytwo.signalk.server.NettyServer@29876704]]]]], EventDrivenConsumerRoute[Endpoint[seda://nmeaOutput?purgeWhenStopping=true&size=100] -> Channel[Filter[if: (header{OUTPUT_TYPE} == OUTPUT_NMEA) or (header{websocket.connectionKey} == websocket.sendToAll) do: Channel[DelegateSync[nz.co.fortytwo.signalk.server.NettyServer@4816c290]]]]], EventDrivenConsumerRoute[Endpoint[seda://commonOut?purgeWhenStopping=true&size=100] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.MapToJsonProcessor@4940809c]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.FullToDeltaProcessor@16423501]], Channel[Splitter[on: Simple: body to: Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.StorageProcessor@4efcf8a]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.OutputFilterProcessor@7a138fc5]], Channel[Multicast[[Channel[sendTo(Endpoint[seda://tcp?purgeWhenStopping=true&size=100])], Channel[sendTo(Endpoint[seda://websockets?purgeWhenStopping=true&size=100])], Channel[sendTo(Endpoint[direct://mqtt])], Channel[sendTo(Endpoint[direct://stomp])], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.output?level=DEBUG])]]]]]] aggregate: null]]]]], EventDrivenConsumerRoute[Endpoint[direct://mqtt] -> Channel[Filter[if: header{OUTPUT_TYPE} == OUTPUT_MQTT do: Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.MqttProcessor@379ab47b]], Channel[sendTo(Endpoint[mqtt:signalk?host=tcp://0.0.0.0:1883?publishTopicName=signalk.dlq])]]]]]], EventDrivenConsumerRoute[Endpoint[direct://stomp] -> Channel[Filter[if: header{OUTPUT_TYPE} == OUTPUT_STOMP do: Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.StompProcessor@307765b4]], Channel[sendTo(Endpoint[skStomp://queue:signalk?brokerURL=tcp%3A%2F%2F0.0.0.0%3A61613])]]]]]], EventDrivenConsumerRoute[Endpoint[timer://heartbeat?fixedRate=true&period=1000] -> Channel[DelegateSync[nz.co.fortytwo.signalk.processor.HeartbeatProcessor@4a9e6faf]]], EventDrivenConsumerRoute[Endpoint[http://0.0.0.0:8080/signalk/v1/auth?enableJMX=true&sessionSupport=true] -> Pipeline[[Channel[SetExchangePattern[InOut]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.RestAuthProcessor@2c95ac9e]]]]], EventDrivenConsumerRoute[Endpoint[http://0.0.0.0:8080/signalk?enableJMX=true&sessionSupport=true] -> Pipeline[[Channel[SetExchangePattern[InOut]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.RestApiProcessor@4e4efc1b]], Channel[sendTo(Endpoint[seda://inputData?purgeWhenStopping=true&size=100] InOut)]]]], EventDrivenConsumerRoute[Endpoint[http://0.0.0.0:8080/signalk/v1/api?enableJMX=true&sessionSupport=true] -> Pipeline[[Channel[SetExchangePattern[InOut]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.RestApiProcessor@459f7aa3]], Channel[sendTo(Endpoint[seda://inputData?purgeWhenStopping=true&size=100] InOut)]]]], EventDrivenConsumerRoute[Endpoint[http://0.0.0.0:8080/signalk/v1/install?enableJMX=true&sessionSupport=true] -> Pipeline[[Channel[SetExchangePattern[InOut]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.ClientAppProcessor@7cc586a8]]]]], EventDrivenConsumerRoute[Endpoint[http://0.0.0.0:8080/signalk/v1/upgrade?enableJMX=true&sessionSupport=true] -> Pipeline[[Channel[SetExchangePattern[InOut]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.ClientAppProcessor@7db534f2]]]]], EventDrivenConsumerRoute[Endpoint[timer://background?fixedRate=true&period=60000] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.SaveProcessor@260e86a1]], Channel[DelegateSync[nz.co.fortytwo.signalk.processor.DeclinationProcessor@44a2b17b]], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.update?level=DEBUG])]]]], EventDrivenConsumerRoute[Endpoint[timer://wind?fixedRate=true&period=1000] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.WindProcessor@7a56812e]], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.update?level=DEBUG])]]]], EventDrivenConsumerRoute[Endpoint[timer://anchorWatch?fixedRate=true&period=1000] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.AnchorWatchProcessor@2a76b80a]], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.update?level=DEBUG])]]]], EventDrivenConsumerRoute[Endpoint[timer://alarms?fixedRate=true&period=1000] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.AlarmProcessor@7eb01b12]], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.update?level=DEBUG])]]]], EventDrivenConsumerRoute[Endpoint[timer://nmea0183?fixedRate=true&period=1000] -> Pipeline[[Channel[DelegateSync[nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor@2f4854d6]], Channel[sendTo(Endpoint[log://nz.co.fortytwo.signalk.model.update?level=DEBUG])]]]], EventDrivenConsumerRoute[Endpoint[skStomp://queue:signalk.put] -> Pipeline[[Channel[SetHeader(OUTPUT_TYPE, OUTPUT_STOMP)], Channel[sendTo(Endpoint[seda://inputData?purgeWhenStopping=true&size=100])]]]], EventDrivenConsumerRoute[Endpoint[mqtt:signalk?host=tcp://0.0.0.0:1883&subscribeTopicName=signalk.put] -> Pipeline[[Channel[Transform(body)], Channel[SetHeader(OUTPUT_TYPE, OUTPUT_MQTT)], Channel[sendTo(Endpoint[seda://inputData?purgeWhenStopping=true&size=100])]]]]] 2016-01-13 20:41:20,237 [ ActiveMQ NIO Worker 2] Queue DEBUG queue://signalk.put add sub: QueueSubscription: consumer=ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0 2016-01-13 20:41:20,238 [ ActiveMQ NIO Worker 2] AbstractRegion DEBUG localhost adding destination: topic://ActiveMQ.Advisory.Consumer.Queue.signalk.put 2016-01-13 20:41:21,196 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Checking src ip:null 2016-01-13 20:41:21,196 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Exchange[Message: {"context":"vessels.motu.navigation","updates":[{"values":[{"path":"courseOverGroundTrue","value":172.9},{"path":"speedOverGround","value":3.85}],"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"timestamp":"2014-08-15T16:00:00.081+00:00"}]}] 2016-01-13 20:41:21,199 [) thread #0 - seda://inputData] StorageProcessor DEBUG Processed storage :{"context":"vessels.motu.navigation","updates":[{"values":[{"path":"courseOverGroundTrue","value":172.9},{"path":"speedOverGround","value":3.85}],"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"timestamp":"2014-08-15T16:00:00.081+00:00"}]} 2016-01-13 20:41:21,199 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG WsSession is null:{breadcrumbId=ID-Jeremys-iMac-local-62257-1452746409638-0-1, SIGNALK_FORMAT=delta} 2016-01-13 20:41:21,199 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg class: class mjson.Json$ObjectJson 2016-01-13 20:41:21,199 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg: {"context":"vessels.motu.navigation","updates":[{"values":[{"path":"courseOverGroundTrue","value":172.9},{"path":"speedOverGround","value":3.85}],"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"timestamp":"2014-08-15T16:00:00.081+00:00"}]} 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] DeltaImportProcessor DEBUG Converted to:{vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG {vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.courseOverGroundTrue.source.device 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.courseOverGroundTrue.source.pgn 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.courseOverGroundTrue.source.src 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.courseOverGroundTrue.timestamp 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.courseOverGroundTrue.value 2016-01-13 20:41:21,200 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Processing key=vessels.motu.navigation.courseOverGroundTrue.value 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.speedOverGround.source.device 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.speedOverGround.source.pgn 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.speedOverGround.source.src 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.speedOverGround.timestamp 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Checking key=vessels.motu.navigation.speedOverGround.value 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Processing key=vessels.motu.navigation.speedOverGround.value 2016-01-13 20:41:21,201 [) thread #0 - seda://inputData] SignalkModelProcessor DEBUG SignalkModelProcessor updating {vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:21,203 [) thread #0 - seda://inputData] SignalkModelProcessor DEBUG {config.hawtio.authenticationEnabled=false, config.hawtio.context=/hawtio, config.hawtio.port=8000.0, config.hawtio.start=false, config.hawtio.war=./hawtio/hawtio-default-offline-1.4.48.war, config.server.apps.install.allow=true, config.server.apps.upgrade.allow=true, config.server.client.mqtt.connect=[], config.server.client.stomp.connect=[], config.server.client.tcp.connect=[], config.server.clock.source=system, config.server.demo.file=PacCupStartNMEA.txt, config.server.demo.start=false, config.server.files.cfg.dir=./conf/, config.server.files.cfg.file=signalk.cfg, config.server.files.maps.dir=./mapcache, config.server.files.static.dir=./signalk-static, config.server.files.storage.root=./storage/, config.server.files.usb.usbdrive=/media/usb0, config.server.security.config.ip=["10.1.1.64","127.0.0.1"], config.server.security.deny.ip=[], config.server.security.white.ip=["10.1.1.64"], config.server.serial.baud=38400.0, config.server.serial.enable=true, config.server.serial.ports=["/dev/ttyUSB0","/dev/ttyUSB1","/dev/ttyUSB2","/dev/ttyACM0","/dev/ttyACM1","/dev/ttyACM2"], config.server.server.mqtt.port=1883.0, config.server.server.mqtt.start=true, config.server.server.nmea.generate0183=true, config.server.server.rest.port=8080.0, config.server.server.stomp.port=61613.0, config.server.server.stomp.start=true, config.server.server.tcp.nmea.port=55557.0, config.server.server.tcp.port=55555.0, config.server.server.udp.nmea.port=55556.0, config.server.server.udp.port=55554.0, config.server.server.websocket.port=3000.0, config.server.version=0.1, config.server.vessel.uuid=motu, vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:21,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:21,235 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:21,235 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:21,237 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:21,237 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:22,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:22,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:22,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:22,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:22,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:22,349 [ main] NettyAsyncHttpProvider DEBUG Non cached request DefaultHttpRequest(chunked: false) GET /signalk/v1/auth/demo/pass HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 using Channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] 2016-01-13 20:41:22,396 [ qtp1525114112-176] RestAuthProcessor DEBUG Session = 11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,396 [ qtp1525114112-176] RestAuthProcessor DEBUG We are processing the path = /signalk/v1/auth/demo/pass 2016-01-13 20:41:22,396 [ qtp1525114112-176] RestAuthProcessor INFO Adding session = 11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,403 [ New I/O worker #1] NettyAsyncHttpProvider DEBUG Request DefaultHttpRequest(chunked: false) GET /signalk/v1/auth/demo/pass HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 Response DefaultHttpResponse(chunked: false) HTTP/1.1 200 OK Set-Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj;Path=/ Expires: Thu, 01 Jan 1970 00:00:00 GMT Content-Type: text/plain Accept: */* breadcrumbId: ID-Jeremys-iMac-local-62257-1452746409638-0-27 User-Agent: NING/1.0 Content-Length: 0 Server: Jetty(8.1.16.v20140903) 2016-01-13 20:41:22,405 [ New I/O worker #1] NettyConnectionsPool DEBUG Adding uri: http://localhost:8080 for channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] 2016-01-13 20:41:22,408 [ main] NettyAsyncHttpProvider DEBUG Using cached Channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] for uri http://localhost:8080/signalk/v1/api/vessels/motu 2016-01-13 20:41:22,409 [ main] NettyAsyncHttpProvider DEBUG Using cached Channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] for request DefaultHttpRequest(chunked: false) GET /signalk/v1/api/vessels/motu HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,412 [ qtp1525114112-175] RestApiProcessor DEBUG Request = class org.eclipse.jetty.server.Request 2016-01-13 20:41:22,412 [ qtp1525114112-175] RestApiProcessor DEBUG Session = 11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,413 [ qtp1525114112-175] RestApiProcessor DEBUG {Accept=*/*, breadcrumbId=ID-Jeremys-iMac-local-62257-1452746409638-0-29, CamelHttpMethod=GET, CamelHttpPath=/vessels/motu, CamelHttpQuery=null, CamelHttpServletRequest=(GET /signalk/v1/api/vessels/motu)@1179841426 org.eclipse.jetty.server.Request@4652f392, CamelHttpServletResponse=HTTP/1.1 200 , CamelHttpUri=/signalk/v1/api/vessels/motu, CamelHttpUrl=http://localhost:8080/signalk/v1/api/vessels/motu, CamelServletContextPath=/signalk/v1/api, Connection=keep-alive, Content-Type=null, Cookie=JSESSIONID=11t74lavvp6i212q1gvb9e5qrj, Host=localhost:8080, MSG_SRC_IP=127.0.0.1, MSG_SRC_IP_PORT=62315, MSG_TYPE=INTERNAL_IP, REST_REQUEST=true, User-Agent=NING/1.0, websocket.connectionKey=11t74lavvp6i212q1gvb9e5qrj} 2016-01-13 20:41:22,413 [ qtp1525114112-175] RestApiProcessor DEBUG /signalk/v1/api/vessels/motu 2016-01-13 20:41:22,413 [ qtp1525114112-175] RestApiProcessor DEBUG Processing the path = /signalk/v1/api/vessels/motu 2016-01-13 20:41:22,413 [ qtp1525114112-175] RestApiProcessor DEBUG Processing the path extension:vessels.motu 2016-01-13 20:41:22,413 [ qtp1525114112-175] RestApiProcessor DEBUG Processing the context:vessels.motu 2016-01-13 20:41:22,414 [ qtp1525114112-175] RestApiProcessor DEBUG Processing the GET request:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,416 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Checking src ip:127.0.0.1 2016-01-13 20:41:22,416 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Message allowed for src ip (internal):127.0.0.1 2016-01-13 20:41:22,416 [) thread #0 - seda://inputData] StorageProcessor DEBUG Processed storage :{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,416 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg class: class mjson.Json$ObjectJson 2016-01-13 20:41:22,416 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg: {"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] DeltaImportProcessor DEBUG Ignored, not update:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] FullImportProcessor DEBUG Ignored, not update:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Ignored, not update:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] TrackProcessor DEBUG Ignored, not a track:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] SignalkModelProcessor DEBUG Ignored, not update:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,417 [) thread #0 - seda://inputData] JsonListProcessor DEBUG Skipped, not a LIST request:{"get":[{"path":"*"}],"context":"vessels.motu"} 2016-01-13 20:41:22,418 [) thread #0 - seda://inputData] JsonGetProcessor DEBUG Retrieved:{vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:22,419 [) thread #0 - seda://inputData] JsonGetProcessor DEBUG Processed REST GET request:{"vessels":{"motu":{"navigation":{"courseOverGroundTrue":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":172.9,"timestamp":"2014-08-15T16:00:00.081+00:00"},"speedOverGround":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":3.85,"timestamp":"2014-08-15T16:00:00.081+00:00"}}}}} 2016-01-13 20:41:22,425 [ New I/O worker #1] NettyAsyncHttpProvider DEBUG Request DefaultHttpRequest(chunked: false) GET /signalk/v1/api/vessels/motu HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj Response DefaultHttpResponse(chunked: false) HTTP/1.1 200 OK Accept: */* breadcrumbId: ID-Jeremys-iMac-local-62257-1452746409638-0-29 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj MSG_SRC_IP: 127.0.0.1 MSG_SRC_IP_PORT: 62315 MSG_TYPE: INTERNAL_IP REST_REQUEST: true REST_WILDCARD: true SIGNALK_FORMAT: delta User-Agent: NING/1.0 websocket.connectionKey: 11t74lavvp6i212q1gvb9e5qrj Content-Type: application/json;charset=UTF-8 Content-Length: 325 Server: Jetty(8.1.16.v20140903) 2016-01-13 20:41:22,426 [ New I/O worker #1] NettyConnectionsPool DEBUG Adding uri: http://localhost:8080 for channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] 2016-01-13 20:41:22,427 [ main] RestApiTest DEBUG {"vessels":{"motu":{"navigation":{"courseOverGroundTrue":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":172.9,"timestamp":"2014-08-15T16:00:00.081+00:00"},"speedOverGround":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":3.85,"timestamp":"2014-08-15T16:00:00.081+00:00"}}}}} 2016-01-13 20:41:22,430 [ main] NettyAsyncHttpProvider DEBUG Using cached Channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] for uri http://localhost:8080/signalk/v1/api/vessels/motu/navigation 2016-01-13 20:41:22,430 [ main] NettyAsyncHttpProvider DEBUG Using cached Channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] for request DefaultHttpRequest(chunked: false) GET /signalk/v1/api/vessels/motu/navigation HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,432 [ qtp1525114112-177] RestApiProcessor DEBUG Request = class org.eclipse.jetty.server.Request 2016-01-13 20:41:22,432 [ qtp1525114112-177] RestApiProcessor DEBUG Session = 11t74lavvp6i212q1gvb9e5qrj 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG {Accept=*/*, breadcrumbId=ID-Jeremys-iMac-local-62257-1452746409638-0-32, CamelHttpMethod=GET, CamelHttpPath=/vessels/motu/navigation, CamelHttpQuery=null, CamelHttpServletRequest=(GET /signalk/v1/api/vessels/motu/navigation)@1179841426 org.eclipse.jetty.server.Request@4652f392, CamelHttpServletResponse=HTTP/1.1 200 , CamelHttpUri=/signalk/v1/api/vessels/motu/navigation, CamelHttpUrl=http://localhost:8080/signalk/v1/api/vessels/motu/navigation, CamelServletContextPath=/signalk/v1/api, Connection=keep-alive, Content-Type=null, Cookie=JSESSIONID=11t74lavvp6i212q1gvb9e5qrj, Host=localhost:8080, MSG_SRC_IP=127.0.0.1, MSG_SRC_IP_PORT=62315, MSG_TYPE=INTERNAL_IP, REST_REQUEST=true, User-Agent=NING/1.0, websocket.connectionKey=11t74lavvp6i212q1gvb9e5qrj} 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG /signalk/v1/api/vessels/motu/navigation 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG Processing the path = /signalk/v1/api/vessels/motu/navigation 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG Processing the path extension:vessels.motu.navigation 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG Processing the context:vessels.motu 2016-01-13 20:41:22,434 [ qtp1525114112-177] RestApiProcessor DEBUG Processing the GET request:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Checking src ip:127.0.0.1 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] IncomingSecurityFilter DEBUG Message allowed for src ip (internal):127.0.0.1 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] StorageProcessor DEBUG Processed storage :{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg class: class mjson.Json$ObjectJson 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] JsonSubscribeProcessor DEBUG Subscribe msg: {"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,435 [) thread #0 - seda://inputData] DeltaImportProcessor DEBUG Ignored, not update:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,436 [) thread #0 - seda://inputData] FullImportProcessor DEBUG Ignored, not update:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,436 [) thread #0 - seda://inputData] ValidationProcessor DEBUG Ignored, not update:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,436 [) thread #0 - seda://inputData] TrackProcessor DEBUG Ignored, not a track:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,436 [) thread #0 - seda://inputData] SignalkModelProcessor DEBUG Ignored, not update:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,436 [) thread #0 - seda://inputData] JsonListProcessor DEBUG Skipped, not a LIST request:{"get":[{"path":"navigation"}],"context":"vessels.motu"} 2016-01-13 20:41:22,437 [) thread #0 - seda://inputData] JsonGetProcessor DEBUG Retrieved:{vessels.motu.navigation.courseOverGroundTrue.source.device=/dev/actisense, vessels.motu.navigation.courseOverGroundTrue.source.pgn=128267, vessels.motu.navigation.courseOverGroundTrue.source.src=115, vessels.motu.navigation.courseOverGroundTrue.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.courseOverGroundTrue.value=172.9, vessels.motu.navigation.speedOverGround.source.device=/dev/actisense, vessels.motu.navigation.speedOverGround.source.pgn=128267, vessels.motu.navigation.speedOverGround.source.src=115, vessels.motu.navigation.speedOverGround.timestamp=2014-08-15T16:00:00.081+00:00, vessels.motu.navigation.speedOverGround.value=3.85} 2016-01-13 20:41:22,437 [) thread #0 - seda://inputData] JsonGetProcessor DEBUG Processed REST GET request:{"vessels":{"motu":{"navigation":{"courseOverGroundTrue":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":172.9,"timestamp":"2014-08-15T16:00:00.081+00:00"},"speedOverGround":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":3.85,"timestamp":"2014-08-15T16:00:00.081+00:00"}}}}} 2016-01-13 20:41:22,441 [ New I/O worker #1] NettyAsyncHttpProvider DEBUG Request DefaultHttpRequest(chunked: false) GET /signalk/v1/api/vessels/motu/navigation HTTP/1.1 Host: localhost:8080 Connection: keep-alive Accept: */* User-Agent: NING/1.0 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj Response DefaultHttpResponse(chunked: false) HTTP/1.1 200 OK Accept: */* breadcrumbId: ID-Jeremys-iMac-local-62257-1452746409638-0-32 Cookie: JSESSIONID=11t74lavvp6i212q1gvb9e5qrj MSG_SRC_IP: 127.0.0.1 MSG_SRC_IP_PORT: 62315 MSG_TYPE: INTERNAL_IP REST_REQUEST: true REST_WILDCARD: false SIGNALK_FORMAT: delta User-Agent: NING/1.0 websocket.connectionKey: 11t74lavvp6i212q1gvb9e5qrj Content-Type: application/json;charset=UTF-8 Content-Length: 325 Server: Jetty(8.1.16.v20140903) 2016-01-13 20:41:22,441 [ New I/O worker #1] NettyConnectionsPool DEBUG Adding uri: http://localhost:8080 for channel [id: 0x6bea2d89, /127.0.0.1:62315 => localhost/127.0.0.1:8080] 2016-01-13 20:41:22,442 [ main] RestApiTest DEBUG {"vessels":{"motu":{"navigation":{"courseOverGroundTrue":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":172.9,"timestamp":"2014-08-15T16:00:00.081+00:00"},"speedOverGround":{"source":{"src":"115","pgn":"128267","device":"/dev/actisense"},"value":3.85,"timestamp":"2014-08-15T16:00:00.081+00:00"}}}}} 2016-01-13 20:41:22,457 [ main] NettyServer INFO Stopping ptrans... 2016-01-13 20:41:23,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:23,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:23,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:23,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:23,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:24,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:24,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:24,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:24,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:24,234 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:24,676 [ main] NettyServer INFO Stopped 2016-01-13 20:41:24,676 [ main] NettyServer INFO Stopping ptrans... 2016-01-13 20:41:25,236 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:25,236 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:25,236 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:25,236 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:25,236 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:26,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:26,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:26,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Sending: null 2016-01-13 20:41:26,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor ERROR Value out of bounds [0..360] 2016-01-13 20:41:26,233 [ thread #10 - timer://nmea0183] NMEA0183ExportProcessor DEBUG Value out of bounds [0..360] java.lang.IllegalArgumentException: Value out of bounds [0..360] at net.sf.marineapi.nmea.parser.SentenceParser.setDegreesValue(SentenceParser.java:461) at net.sf.marineapi.nmea.parser.VTGParser.setTrueCourse(VTGParser.java:153) at nz.co.fortytwo.signalk.handler.NMEA0183Producer.createVTG(NMEA0183Producer.java:188) at nz.co.fortytwo.signalk.processor.NMEA0183ExportProcessor.process(NMEA0183ExportProcessor.java:51) at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:448) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.processor.Pipeline.process(Pipeline.java:118) at org.apache.camel.processor.Pipeline.process(Pipeline.java:80) at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191) at org.apache.camel.component.timer.TimerConsumer.sendTimerExchange(TimerConsumer.java:165) at org.apache.camel.component.timer.TimerConsumer$1.run(TimerConsumer.java:73) at java.util.TimerThread.mainLoop(Timer.java:555) at java.util.TimerThread.run(Timer.java:505) 2016-01-13 20:41:26,894 [ main] NettyServer INFO Stopped 2016-01-13 20:41:26,895 [ main] BrokerService INFO Apache ActiveMQ 5.11.1 (localhost, ID:Jeremys-iMac.local-62260-1452746409970-0:1) is shutting down 2016-01-13 20:41:26,895 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=tcp_//localhost_61616 2016-01-13 20:41:26,896 [ main] TransportConnector INFO Connector tcp://localhost:61616 stopped 2016-01-13 20:41:26,896 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=ws_//localhost_61614 2016-01-13 20:41:26,918 [ main] ContextHandler INFO stopped o.e.j.s.ServletContextHandler{/,null} 2016-01-13 20:41:26,970 [ main] TransportConnector INFO Connector ws://localhost:61614 stopped 2016-01-13 20:41:26,970 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=stomp+nio_//0.0.0.0_61613&qe;transport.hbGracePeriodMultiplier&1.5 2016-01-13 20:41:26,971 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=stomp+nio_//0.0.0.0_61613&qe;transport.hbGracePeriodMultiplier&1.5,connectionViewType=clientId,connectionName=ID_Jeremys-iMac.local-62260-1452746409970-2_1 2016-01-13 20:41:26,971 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=stomp+nio_//0.0.0.0_61613&qe;transport.hbGracePeriodMultiplier&1.5,connectionViewType=remoteAddress,connectionName=tcp_//127.0.0.1_62311 2016-01-13 20:41:26,971 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopping connection: tcp://127.0.0.1:62311 2016-01-13 20:41:26,971 [rokerService[localhost] Task-1] TcpTransport DEBUG Stopping transport tcp:///127.0.0.1:62311@61613 2016-01-13 20:41:26,972 [rokerService[localhost] Task-1] TaskRunnerFactory DEBUG Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@23dcc691[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:41:26,972 [ ActiveMQ Task-1] TcpTransport DEBUG Closed socket Socket[unconnected] 2016-01-13 20:41:26,972 [rokerService[localhost] Task-1] ThreadPoolUtils DEBUG Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@23dcc691[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1] 2016-01-13 20:41:26,972 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopped transport: null 2016-01-13 20:41:26,973 [rokerService[localhost] Task-1] TransportConnection DEBUG Cleaning up connection resources: null 2016-01-13 20:41:26,973 [rokerService[localhost] Task-1] TransportConnection DEBUG remove connection id: ID:Jeremys-iMac.local-62260-1452746409970-2:1 2016-01-13 20:41:26,973 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,endpoint=dynamicProducer,clientId=ID_Jeremys-iMac.local-62260-1452746409970-2_1,producerId=ID_Jeremys-iMac.local-62260-1452746409970-2_1_-1_1 2016-01-13 20:41:26,974 [rokerService[localhost] Task-1] TransportConnection DEBUG Connection Stopped: null 2016-01-13 20:41:26,974 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=stomp+nio_//0.0.0.0_61613&qe;transport.hbGracePeriodMultiplier&1.5,connectionViewType=clientId,connectionName=ID_Jeremys-iMac.local-62260-1452746409970-2_2 2016-01-13 20:41:26,974 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=stomp+nio_//0.0.0.0_61613&qe;transport.hbGracePeriodMultiplier&1.5,connectionViewType=remoteAddress,connectionName=tcp_//127.0.0.1_62312 2016-01-13 20:41:26,974 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopping connection: tcp://127.0.0.1:62312 2016-01-13 20:41:26,974 [rokerService[localhost] Task-1] TcpTransport DEBUG Stopping transport tcp:///127.0.0.1:62312@61613 2016-01-13 20:41:26,974 [rokerService[localhost] Task-1] TaskRunnerFactory DEBUG Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@39bc71e2[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:41:26,975 [ ActiveMQ Task-1] TcpTransport DEBUG Closed socket Socket[unconnected] 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] ThreadPoolUtils DEBUG Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@39bc71e2[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1] 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopped transport: null 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] TransportConnection DEBUG Cleaning up connection resources: null 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] TransportConnection DEBUG remove connection id: ID:Jeremys-iMac.local-62260-1452746409970-2:2 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] ActiveMqSubscriptionFilter DEBUG Remove consumer:ConsumerInfo {commandId = 3, responseRequired = false, consumerId = ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1, destination = queue://signalk.put, prefetchSize = 1000, maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true, selector = null, clientId = null, subscriptionName = null, noLocal = false, exclusive = false, retroactive = false, priority = 0, brokerPath = null, optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate = null} 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Queue,destinationName=signalk.put,endpoint=Consumer,clientId=ID_Jeremys-iMac.local-62260-1452746409970-2_2,consumerId=ID_Jeremys-iMac.local-62260-1452746409970-2_2_-1_1 2016-01-13 20:41:26,975 [rokerService[localhost] Task-1] AbstractRegion DEBUG localhost removing consumer: ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1 for destination: queue://signalk.put 2016-01-13 20:41:26,976 [rokerService[localhost] Task-1] Queue DEBUG queue://signalk.put remove sub: QueueSubscription: consumer=ID:Jeremys-iMac.local-62260-1452746409970-2:2:-1:1, destinations=1, dispatched=0, delivered=0, pending=0, lastDeliveredSeqId: -1, dequeues: 0, dispatched: 0, inflight: 0, groups: 0 2016-01-13 20:41:26,978 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,endpoint=dynamicProducer,clientId=ID_Jeremys-iMac.local-62260-1452746409970-2_2,producerId=ID_Jeremys-iMac.local-62260-1452746409970-2_2_-1_1 2016-01-13 20:41:26,978 [rokerService[localhost] Task-1] TransportConnection DEBUG Connection Stopped: null 2016-01-13 20:41:26,978 [ main] TransportConnector INFO Connector stomp+nio://0.0.0.0:61613?transport.hbGracePeriodMultiplier=1.5 stopped 2016-01-13 20:41:26,979 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=mqtt+nio_//0.0.0.0_1883 2016-01-13 20:41:26,979 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=mqtt+nio_//0.0.0.0_1883,connectionViewType=clientId,connectionName=0a000143f369569726f0 2016-01-13 20:41:26,979 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=mqtt+nio_//0.0.0.0_1883,connectionViewType=remoteAddress,connectionName=tcp_//10.0.1.67_62313 2016-01-13 20:41:26,979 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopping connection: tcp://10.0.1.67:62313 2016-01-13 20:41:26,979 [rokerService[localhost] Task-1] TcpTransport DEBUG Stopping transport tcp:///10.0.1.67:62313@1883 2016-01-13 20:41:26,979 [rokerService[localhost] Task-1] TaskRunnerFactory DEBUG Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@3fd35979[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:41:26,980 [ ActiveMQ Task-1] TcpTransport DEBUG Closed socket Socket[unconnected] 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] ThreadPoolUtils DEBUG Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@3fd35979[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1] 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopped transport: null 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] TransportConnection DEBUG Cleaning up connection resources: null 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] TransportConnection DEBUG remove connection id: ID:Jeremys-iMac.local-62260-1452746409970-5:1 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,endpoint=dynamicProducer,clientId=0a000143f369569726f0,producerId=ID_Jeremys-iMac.local-62260-1452746409970-5_1_-1_1 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] TransportConnection DEBUG Connection Stopped: null 2016-01-13 20:41:26,980 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=mqtt+nio_//0.0.0.0_1883,connectionViewType=clientId,connectionName=0a000143f36a569726f0 2016-01-13 20:41:26,980 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,connector=clientConnectors,connectorName=mqtt+nio_//0.0.0.0_1883,connectionViewType=remoteAddress,connectionName=tcp_//10.0.1.67_62314 2016-01-13 20:41:26,980 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopping connection: tcp://10.0.1.67:62314 2016-01-13 20:41:26,981 [rokerService[localhost] Task-1] ThreadPoolUtils DEBUG Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@56e1f315[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: true took: 0.000 seconds. 2016-01-13 20:41:26,981 [rokerService[localhost] Task-1] TcpTransport DEBUG Stopping transport tcp:///10.0.1.67:62314@1883 2016-01-13 20:41:26,981 [rokerService[localhost] Task-1] TaskRunnerFactory DEBUG Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@2d488a20[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:41:26,981 [ ActiveMQ Task-1] TcpTransport DEBUG Closed socket Socket[unconnected] 2016-01-13 20:41:26,981 [rokerService[localhost] Task-1] ThreadPoolUtils DEBUG Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@2d488a20[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1] 2016-01-13 20:41:26,981 [rokerService[localhost] Task-1] TransportConnection DEBUG Stopped transport: null 2016-01-13 20:41:26,982 [rokerService[localhost] Task-1] TransportConnection DEBUG Cleaning up connection resources: null 2016-01-13 20:41:26,982 [rokerService[localhost] Task-1] TransportConnection DEBUG remove connection id: ID:Jeremys-iMac.local-62260-1452746409970-5:2 2016-01-13 20:41:26,982 [rokerService[localhost] Task-1] ActiveMqSubscriptionFilter DEBUG Remove consumer:ConsumerInfo {commandId = 3, responseRequired = true, consumerId = ID:Jeremys-iMac.local-62260-1452746409970-5:2:-1:1, destination = topic://signalk/put, prefetchSize = 32767, maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true, selector = null, clientId = null, subscriptionName = null, noLocal = false, exclusive = false, retroactive = true, priority = 0, brokerPath = null, optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate = null} 2016-01-13 20:41:26,982 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=signalk/put,endpoint=Consumer,clientId=0a000143f36a569726f0,consumerId=ID_Jeremys-iMac.local-62260-1452746409970-5_2_-1_1 2016-01-13 20:41:26,982 [rokerService[localhost] Task-1] AbstractRegion DEBUG localhost removing consumer: ID:Jeremys-iMac.local-62260-1452746409970-5:2:-1:1 for destination: topic://signalk/put 2016-01-13 20:41:26,983 [rokerService[localhost] Task-1] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,endpoint=dynamicProducer,clientId=0a000143f36a569726f0,producerId=ID_Jeremys-iMac.local-62260-1452746409970-5_2_-1_1 2016-01-13 20:41:26,983 [rokerService[localhost] Task-1] TransportConnection DEBUG Connection Stopped: null 2016-01-13 20:41:26,984 [ main] TransportConnector INFO Connector mqtt+nio://0.0.0.0:1883 stopped 2016-01-13 20:41:26,986 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.Connection 2016-01-13 20:41:26,986 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.MasterBroker 2016-01-13 20:41:26,986 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=signalk/put 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.Topic 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Queue,destinationName=signalk.put 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.Consumer.Topic.signalk/put 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.Queue 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,destinationType=Topic,destinationName=ActiveMQ.Advisory.Consumer.Queue.signalk.put 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,service=Log4JConfiguration 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Unregistering MBean org.apache.activemq:type=Broker,brokerName=localhost,service=Health 2016-01-13 20:41:26,987 [ main] ManagementContext DEBUG Stopping jmx connector 2016-01-13 20:41:26,989 [ main] ManagementContext DEBUG Unexported JMX RMI Registry 2016-01-13 20:41:26,991 [ main] ThreadPoolUtils DEBUG Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@72cde7cc[Terminated, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 14] is shutdown: true and terminated: false took: 0.000 seconds. 2016-01-13 20:41:26,992 [ main] ThreadPoolUtils DEBUG Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@54336c81[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] 2016-01-13 20:41:26,992 [ main] BrokerService INFO Apache ActiveMQ 5.11.1 (localhost, ID:Jeremys-iMac.local-62260-1452746409970-0:1) uptime 1 minute 2016-01-13 20:41:26,992 [ main] BrokerService INFO Apache ActiveMQ 5.11.1 (localhost, ID:Jeremys-iMac.local-62260-1452746409970-0:1) is shutdown 2016-01-13 20:41:26,992 [ main] DefaultCamelContext INFO Apache Camel 2.15.2 (CamelContext: camel-1) is shutting down 2016-01-13 20:41:26,992 [ main] DefaultShutdownStrategy INFO Starting to graceful shutdown 21 routes (timeout 10 seconds) 2016-01-13 20:41:30,458 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: MQTT In shutdown complete, was consuming from: Endpoint[mqtt:signalk?host=tcp://0.0.0.0:1883&subscribeTopicName=signalk.put] 2016-01-13 20:41:30,458 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: STOMP In shutdown complete, was consuming from: Endpoint[skStomp://queue:signalk.put] 2016-01-13 20:41:30,459 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: NMEA0183 shutdown complete, was consuming from: Endpoint[timer://nmea0183?fixedRate=true&period=1000] 2016-01-13 20:41:30,459 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Alarms shutdown complete, was consuming from: Endpoint[timer://alarms?fixedRate=true&period=1000] 2016-01-13 20:41:30,460 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: AnchorWatch shutdown complete, was consuming from: Endpoint[timer://anchorWatch?fixedRate=true&period=1000] 2016-01-13 20:41:30,460 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: True Wind shutdown complete, was consuming from: Endpoint[timer://wind?fixedRate=true&period=1000] 2016-01-13 20:41:30,460 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Declination shutdown complete, was consuming from: Endpoint[timer://background?fixedRate=true&period=60000] 2016-01-13 20:41:30,461 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: REST Upgrade shutdown complete, was consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/upgrade?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:30,461 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: REST Install shutdown complete, was consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/install?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:30,462 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: REST Api shutdown complete, was consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/api?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:30,462 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: REST Discovery shutdown complete, was consuming from: Endpoint[http://0.0.0.0:8080/signalk?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:30,485 [l-1) thread #11 - ShutdownTask] ContextHandler INFO stopped o.e.j.s.ServletContextHandler{/,null} 2016-01-13 20:41:30,536 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: REST Authenticate shutdown complete, was consuming from: Endpoint[http://0.0.0.0:8080/signalk/v1/auth?enableJMX=true&sessionSupport=true] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Heartbeat shutdown complete, was consuming from: Endpoint[timer://heartbeat?fixedRate=true&period=1000] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: STOMP out shutdown complete, was consuming from: Endpoint[direct://stomp] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: MQTT out shutdown complete, was consuming from: Endpoint[direct://mqtt] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: COMMON_OUT shutdown complete, was consuming from: Endpoint[seda://commonOut?purgeWhenStopping=true&size=100] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Netty OUTPUT_NMEA Server shutdown complete, was consuming from: Endpoint[seda://nmeaOutput?purgeWhenStopping=true&size=100] 2016-01-13 20:41:30,537 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Netty OUTPUT_TCP Server shutdown complete, was consuming from: Endpoint[seda://tcp?purgeWhenStopping=true&size=100] 2016-01-13 20:41:30,538 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Websocket Rx shutdown complete, was consuming from: Endpoint[skWebsocket://0.0.0.0:3000/signalk/v1/stream] 2016-01-13 20:41:30,538 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: Websocket Tx shutdown complete, was consuming from: Endpoint[seda://websockets?purgeWhenStopping=true&size=100] 2016-01-13 20:41:30,538 [l-1) thread #11 - ShutdownTask] DefaultShutdownStrategy INFO Route: INPUT shutdown complete, was consuming from: Endpoint[seda://inputData?purgeWhenStopping=true&size=100] 2016-01-13 20:41:30,538 [ main] DefaultShutdownStrategy INFO Graceful shutdown of 21 routes completed in 3 seconds 2016-01-13 20:41:35,543 [ main] DefaultCamelContext WARN Error occurred while shutting down service: org.apache.camel.impl.RouteService@71652c98. This exception will be ignored. java.util.concurrent.TimeoutException at org.fusesource.mqtt.client.Promise.await(Promise.java:83) at org.apache.camel.component.mqtt.MQTTEndpoint.doStop(MQTTEndpoint.java:161) at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) at org.apache.camel.util.ServiceHelper.stopService(ServiceHelper.java:141) at org.apache.camel.util.ServiceHelper.stopAndShutdownServices(ServiceHelper.java:234) at org.apache.camel.util.ServiceHelper.stopAndShutdownServices(ServiceHelper.java:192) at org.apache.camel.impl.RouteService.doShutdown(RouteService.java:278) at org.apache.camel.support.ChildServiceSupport.shutdown(ChildServiceSupport.java:112) at org.apache.camel.util.ServiceHelper.stopAndShutdownService(ServiceHelper.java:210) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2827) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2852) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2840) at org.apache.camel.impl.DefaultCamelContext.doStop(DefaultCamelContext.java:2675) at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) at nz.co.fortytwo.signalk.server.SignalKCamelTestSupport.shutdownBroker(SignalKCamelTestSupport.java:80) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33) at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:242) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:137) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75) 2016-01-13 20:41:35,572 [ main] ContextHandler INFO stopped o.e.j.s.ServletContextHandler{/,null} 2016-01-13 20:41:40,628 [ main] DefaultCamelContext WARN Error occurred while shutting down service: Endpoint[mqtt:signalk?host=tcp://0.0.0.0:1883?publishTopicName=signalk.dlq]. This exception will be ignored. java.util.concurrent.TimeoutException at org.fusesource.mqtt.client.Promise.await(Promise.java:83) at org.apache.camel.component.mqtt.MQTTEndpoint.doStop(MQTTEndpoint.java:161) at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) at org.apache.camel.util.ServiceHelper.stopService(ServiceHelper.java:141) at org.apache.camel.util.ServiceHelper.stopAndShutdownService(ServiceHelper.java:204) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2827) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2852) at org.apache.camel.impl.DefaultCamelContext.shutdownServices(DefaultCamelContext.java:2840) at org.apache.camel.impl.DefaultCamelContext.doStop(DefaultCamelContext.java:2701) at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) at nz.co.fortytwo.signalk.server.SignalKCamelTestSupport.shutdownBroker(SignalKCamelTestSupport.java:80) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33) at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:242) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:137) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75) 2016-01-13 20:41:40,630 [ main] DefaultCamelContext INFO Apache Camel 2.15.2 (CamelContext: camel-1) uptime 20.683 seconds 2016-01-13 20:41:40,630 [ main] DefaultCamelContext INFO Apache Camel 2.15.2 (CamelContext: camel-1) is shutdown in 13.638 seconds 2016-01-13 20:41:40,630 [ main] RestApiTest INFO ******************************************************************************** 2016-01-13 20:41:40,630 [ main] RestApiTest INFO Testing done: shouldGetJsonResponse(nz.co.fortytwo.signalk.server.RestApiTest) 2016-01-13 20:41:40,630 [ main] RestApiTest INFO Took: 20.393 seconds (20393 millis) 2016-01-13 20:41:40,630 [ main] RestApiTest INFO ******************************************************************************** Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 91.785 sec 2016-01-13 20:41:40,633 [ Thread-33] NettyServer INFO Stopping ptrans... 2016-01-13 20:41:40,633 [ Thread-32] NettyServer INFO Stopping ptrans... 2016-01-13 20:41:40,633 [ Thread-33] NettyServer INFO Stopped 2016-01-13 20:41:40,633 [ Thread-32] NettyServer INFO Stopped Results : Tests run: 1, Failures: 0, Errors: 0, Skipped: 0 [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 01:35 min [INFO] Finished at: 2016-01-13T20:41:41-08:00 [INFO] Final Memory: 31M/368M [INFO] ------------------------------------------------------------------------