search

OSGP / Documentation

This repository contains documentation for the Open Smart Grid Platform project. This repository is built as a GitBook, therefore all content has to be written using markdown syntax. See the latest GitBook:
https://documentation.gxf.lfenergy.org/
Apache License 2.0
24 stars 15 forks source link

Problem registering device in testing stage #203

Closed sarah225 closed 5 years ago

sarah225 commented 5 years ago

Hi, I installed and set up the OSGP and everything seems perfectly fine. But, when I try to test the platform, in both procedures, I have problem registering the device, and get an error message indicating that it failed to connect. I tested both examples, and the result was the same.

I would appreciate it if you could help me figuring out what the problem is.

kevinsmeets commented 5 years ago

Hi @sarah225

When you created the device using the device simulator application are you using these values: 

Device Identification: SSLD_000-00-01
IP Address: 127.0.0.1
Device Type: SSLD
Protocol: OSLP_ELSTER

or are you using something different?

What logging or error is printed to the Eclipse console when attempting to register the device? And, what is the exact error shown by the device simulator application? Can you provide the text or a screenshot?

You mention you tried both procedures. I assume you mean these segments of the chapter 'Tests the Platform':

Does the Demo App at URL 'https://localhost/web-demo-app' work for you? If so, when adding the device to OSGP, what is the logging printed to the Eclipse console? Also, is there a record in the table oslp_device of the osgp_adapter_protocol_oslp database for the device you added to OSGP?

I'm thinking there might not be a record in the protocol adapter for OSLP database for the device you added. This could explain why registering the device using the device simulator fails.

sarah225 commented 5 years ago

I used exactly the same values as you said. The error message is: ERROR: Device with identification SSLD_000-00-01 communication failed (Unable to connect). And here is the screenshot of the error message: screenshot at 2019-01-15 10-17-32

Here is the logging which is printed to the Eclipse console: Jan 15, 2019 10:04:06 AM org.springframework.oxm.jaxb.Jaxb2Marshaller createJaxbContextFromContextPath INFO: Creating JAXBContext with context path [org.opensmartgridplatform.adapter.ws.schema.admin.devicemanagement] 2019-01-15 10:04:07.303] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.a.w.a.e.DeviceManagementEndpoint@updateKey:401 - Update key for organisation: test-org and device: SSLD_000-00-01. 2019-01-15 10:04:07.724] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.d.core.services.SecurityService@checkAuthorization:77 - Organisation test-org is allowed function UPDATE_KEY 2019-01-15 10:04:07.803] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.a.w.a.i.j.AdminRequestMessageSender@sendMessage:77 - Sending request message to admin requests queue 2019-01-15 10:04:08.005] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 10:04:08.228] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.a.w.e.WebServiceMonitorInterceptor@printSoapMessage:314 - soap message: test-orgdemo-appdev</SOAP-ENV:Header>SSLD_000-00-01</ns2:DeviceIdentification>MFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEFhUImXFJdqmputquVAc2CPdnn9Ju00M3m/Ice7wABNN+oAYKQbw/OceqvZmFF1+r4nO/vCm/f1JO5nEorE2jNQ==</ns2:PublicKey>4</ns2:ProtocolInfoId></ns2:UpdateKeyRequest></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-01-15 10:04:08.271] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.a.w.e.WebServiceMonitorInterceptor@printSoapMessage:314 - soap message: </SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-01-15 10:04:08.276] [dev-box] [ajp-nio-8009-exec-10] INFO o.o.a.w.i.jms.LoggingMessageSender@sendMessage:53 - Sending logger message to queue 2019-01-15 10:04:08.282] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 10:04:08.390] [dev-box] [loggingMessageListenerContainer-1] INFO o.o.l.i.jms.LoggingMessageListener@onMessage:45 - Received logging message 2019-01-15 10:04:16.575] [dev-box] [ajp-nio-8009-exec-15] INFO o.o.w.service.RegisterDevice@sendRequest:309 - Trying to send request: registerDeviceRequest { deviceIdentification: "SSLD_000-00-01" ipAddress: "\000\000\001" deviceType: SSLD hasSchedule: false randomDevice: 65447 }

2019-01-15 10:04:16.591] [dev-box] [ajp-nio-8009-exec-15] INFO o.o.w.service.OslpChannelHandler@send:396 - Sending OSLP request: registerDeviceRequest { deviceIdentification: "SSLD_000-00-01" ipAddress: "\000\000\001" deviceType: SSLD hasSchedule: false randomDevice: 65447 }

2019-01-15 10:04:16.593] [dev-box] [ajp-nio-8009-exec-15] INFO o.o.w.a.config.ApplicationContext@lambda$0:269 - Created new client pipeline 2019-01-15 10:04:16.603] [dev-box] [ajp-nio-8009-exec-15] INFO o.o.w.service.OslpChannelHandler@channelOpen:356 - Channel -1429052622 opened 2019-01-15 10:04:16.609] [dev-box] [ajp-nio-8009-exec-15] INFO o.o.w.service.OslpChannelHandler@send:410 - The connnection to OSGP from device SSLD_000-00-01 is not successful 2019-01-15 10:04:16.609] [dev-box] [ajp-nio-8009-exec-15] WARN o.o.w.service.OslpChannelHandler@send:411 - Unable to connect to: localhost/127.0.0.1:12122 2019-01-15 10:04:16.613] [dev-box] [New I/O worker #1] INFO o.o.w.service.OslpChannelHandler@channelClosed:368 - Channel -1429052622 closed 2019-01-15 10:04:16.619] [dev-box] [ajp-nio-8009-exec-15] ERROR o.o.w.service.RegisterDevice@sendRegisterDeviceCommand:164 - register device exception java.io.IOException: Unable to connect at org.opensmartgridplatform.webdevicesimulator.service.OslpChannelHandler.send(OslpChannelHandler.java:412) ~[classes/:na] at org.opensmartgridplatform.webdevicesimulator.service.RegisterDevice.sendRequest(RegisterDevice.java:310) ~[classes/:na] at org.opensmartgridplatform.webdevicesimulator.service.RegisterDevice.sendRegisterDeviceCommand(RegisterDevice.java:134) ~[classes/:na] at org.opensmartgridplatform.webdevicesimulator.web.controller.DeviceManagementController.sendRegisterDeviceCommand(DeviceManagementController.java:324) [classes/:na] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_191] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_191] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_191] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_191] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) [spring-web-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133) [spring-web-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) [servlet-api.jar:na] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) [spring-webmvc-4.3.18.RELEASE.jar:4.3.18.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [servlet-api.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [catalina.jar:8.5.20] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.20] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-websocket.jar:8.5.20] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.20] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.20] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [catalina.jar:8.5.20] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:8.5.20] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) [catalina.jar:8.5.20] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [catalina.jar:8.5.20] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80) [catalina.jar:8.5.20] at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) [catalina.jar:8.5.20] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [catalina.jar:8.5.20] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [catalina.jar:8.5.20] at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:486) [tomcat-coyote.jar:8.5.20] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-coyote.jar:8.5.20] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-coyote.jar:8.5.20] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1457) [tomcat-coyote.jar:8.5.20] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:8.5.20] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.5.20] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191] 2019-01-15 10:04:16.619] [dev-box] [New I/O boss #5] WARN o.o.w.service.OslpChannelHandler@exceptionCaught:383 - Unexpected exception from downstream. java.net.ConnectException: Connection refused: localhost/127.0.0.1:12122 at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[na:1.8.0_191] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[na:1.8.0_191] at org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152) [netty-3.9.4.Final.jar:na] at org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105) [netty-3.9.4.Final.jar:na] at org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79) [netty-3.9.4.Final.jar:na] at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) [netty-3.9.4.Final.jar:na] at org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42) [netty-3.9.4.Final.jar:na] at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.9.4.Final.jar:na] at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.9.4.Final.jar:na] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191] 2019-01-15 10:05:00.001] [dev-box] [osgp-core-scheduling-1] INFO o.o.c.a.tasks.ScheduledTaskScheduler@run:50 - Processing scheduled tasks 2019-01-15 10:05:00.009] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:05:00.016] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:05:00.017] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:05:00.017] [dev-box] [ResponseUrlDataCleanupJob_Worker-1] INFO o.o.a.w.s.a.s.ResponseUrlDataCleanupJob@execute:29 - Quartz triggered cleanup of response url data. 2019-01-15 10:05:00.018] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:05:00.021] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:05:00.024] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:06:00.001] [dev-box] [microgrids-communication-monitoring-1] INFO o.o.a.d.m.a.t.CommunicationMonitoringTask@run:60 - Running communication monitoring task. 2019-01-15 10:06:00.014] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:06:00.014] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:06:00.016] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:06:00.017] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:06:00.022] [dev-box] [ResponseUrlDataCleanupJob_Worker-1] INFO o.o.a.w.s.a.s.ResponseUrlDataCleanupJob@execute:29 - Quartz triggered cleanup of response url data. 2019-01-15 10:06:00.022] [dev-box] [ResendNotificationJob_Worker-1] INFO o.o.a.w.s.s.ResendNotificationJob@execute:29 - Quartz triggered resend notification. 2019-01-15 10:06:00.014] [dev-box] [ResponseDataCleanupJob_Worker-1] INFO o.o.a.w.s.s.ResponseDataCleanupJob@execute:29 - Quartz triggered cleanup of response data. 2019-01-15 10:06:00.049] [dev-box] [microgrids-communication-monitoring-1] INFO o.o.a.d.m.a.t.CommunicationMonitoringTask@run:71 - Found 0 device(s) for which communication should be restored.

Yes, the URL 'https://localhost/web-demo-app' works for me. The logging printed to the Eclipse console after adding the device: Jan 15, 2019 10:12:31 AM org.springframework.oxm.jaxb.Jaxb2Marshaller createJaxbContextFromContextPath INFO: Creating JAXBContext with context path [org.opensmartgridplatform.adapter.ws.schema.admin.devicemanagement] 2019-01-15 10:12:31.948] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.a.w.a.e.DeviceManagementEndpoint@updateKey:401 - Update key for organisation: test-org and device: SSLD_000-00-01. 2019-01-15 10:12:31.969] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.d.core.services.SecurityService@checkAuthorization:77 - Organisation test-org is allowed function UPDATE_KEY 2019-01-15 10:12:31.977] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.a.w.a.i.j.AdminRequestMessageSender@sendMessage:77 - Sending request message to admin requests queue 2019-01-15 10:12:31.992] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 10:12:32.028] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.a.w.e.WebServiceMonitorInterceptor@printSoapMessage:314 - soap message: test-orgdemo-appdev</SOAP-ENV:Header>SSLD_000-00-01</ns2:DeviceIdentification>MFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEFhUImXFJdqmputquVAc2CPdnn9Ju00M3m/Ice7wABNN+oAYKQbw/OceqvZmFF1+r4nO/vCm/f1JO5nEorE2jNQ==</ns2:PublicKey>4</ns2:ProtocolInfoId></ns2:UpdateKeyRequest></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-01-15 10:12:32.040] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.a.w.e.WebServiceMonitorInterceptor@printSoapMessage:314 - soap message: </SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-01-15 10:12:32.064] [dev-box] [ajp-nio-8009-exec-17] INFO o.o.a.w.i.jms.LoggingMessageSender@sendMessage:53 - Sending logger message to queue 2019-01-15 10:12:32.079] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 10:12:32.097] [dev-box] [loggingMessageListenerContainer-1] INFO o.o.l.i.jms.LoggingMessageListener@onMessage:45 - Received logging message

You are right, there is not any record in the table oslp_device. So, what should I do?

kevinsmeets commented 5 years ago

@sarah225 I'm thinking that one component (or perhaps several components) of OSGP have not started successfully.

Your screenshot and the logging line: 2019-01-15 10:04:16.609] [dev-box] [ajp-nio-8009-exec-15] WARN o.o.w.service.OslpChannelHandler@send:411 - Unable to connect to: localhost/127.0.0.1:12122 indicate that the component 'osgp-protocol-adapter-oslp-elster' is not running.

You can test this using something like netstat -apn | grep 12122. In case the component is running, you would see output like below:

dev@dev-box:/home/dev$ netstat -apn | grep 12122
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp6       0      0 :::12122                :::*                    LISTEN      12590/java

In case the component is not running, there would be no output:

dev@dev-box:/home/dev$ netstat -apn | grep 12122
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)

If the component 'osgp-protocol-adapter-oslp-elster' is not running, this also explains why there's no record in the oslp_device table of the osgp_adapter_protocol_oslp database. When you added the device to OSGP (either using SoapUI or the Demo App) the message to create a record and store the device's public key has not been processed.

Can you remove all applications deployed to Tomcat and only deploy 'osgp-protocol-adapter-oslp-elster'? When you start Tomcat, what logging or errors do you see?

Perhaps a little off-topic but hopefully useful. I would like to suggest using a tool to assist us in troubleshooting your issues. Can you look into installing probe? It can show you which applications (components of OSGP) you have deployed to Tomcat and show you if the application is running or not: https://github.com/psi-probe/psi-probe/releases

sarah225 commented 5 years ago

Well, by running netstat -apn | grep 12122, there was no output and I just received

(Not all processes could be identified, non-owned process info will not be shown, you would have to be root to see it all.).

After removing all deployed application and deploying only 'osgp-protocol-adapter-elster', I saw the followings in Eclipse console:

Jan 15, 2019 7:27:58 PM org.apache.tomcat.util.digester.SetPropertiesRule begin WARNING: [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.jee.server:osgp-protocol-adapter-oslp-elster' did not find a matching property. Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Server version: Apache Tomcat/8.5.20 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Server built: Aug 2 2017 21:35:49 UTC Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Server number: 8.5.20.0 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: OS Name: Linux Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: OS Version: 4.4.0-34-generic Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Architecture: amd64 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Java Home: /usr/lib/jvm/java-8-openjdk-amd64/jre Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: JVM Version: 1.8.0_191-8u191-b12-0ubuntu0.16.04.1-b12 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: JVM Vendor: Oracle Corporation Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: CATALINA_BASE: /home/dev/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: CATALINA_HOME: /home/dev/Tools/apache-tomcat-8.5.20 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Dcatalina.base=/home/dev/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0 Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Dcatalina.home=/home/dev/Tools/tomcat Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Dwtp.deploy=/home/dev/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Djava.endorsed.dirs=/home/dev/Tools/tomcat/endorsed Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Xms512m Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Xmx2048m Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Xss512k Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -XX:MaxMetaspaceSize=1024m Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -XX:+CMSClassUnloadingEnabled Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -XX:+UseConcMarkSweepGC Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Dcom.sun.management.jmxremote=true Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Dfile.encoding=UTF-8 Jan 15, 2019 7:27:58 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib] Jan 15, 2019 7:27:58 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["http-nio-8080"] Jan 15, 2019 7:27:58 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector INFO: Using a shared selector for servlet write/read Jan 15, 2019 7:27:58 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["ajp-nio-8009"] Jan 15, 2019 7:27:58 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector INFO: Using a shared selector for servlet write/read Jan 15, 2019 7:27:58 PM org.apache.catalina.startup.Catalina load INFO: Initialization processed in 671 ms Jan 15, 2019 7:27:58 PM org.apache.catalina.core.StandardService startInternal INFO: Starting service [Catalina] Jan 15, 2019 7:27:58 PM org.apache.catalina.core.StandardEngine startInternal INFO: Starting Servlet Engine: Apache Tomcat/8.5.20 Jan 15, 2019 7:28:00 PM org.apache.jasper.servlet.TldScanner scanJars INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Jan 15, 2019 7:28:04 PM org.apache.jasper.servlet.TldScanner scanJars INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Jan 15, 2019 7:28:05 PM org.apache.catalina.core.ApplicationContext log INFO: 1 Spring WebApplicationInitializers detected on classpath Jan 15, 2019 7:28:05 PM org.apache.catalina.core.ApplicationContext log INFO: Initializing Spring root WebApplicationContext 2019-01-15 19:28:05.154] [dev-box] [localhost-startStop-1] INFO o.s.web.context.ContextLoader@initWebApplicationContext:304 - Root WebApplicationContext: initialization started 2019-01-15 19:28:05.179] [dev-box] [localhost-startStop-1] INFO o.s.w.c.s.AnnotationConfigWebApplicationContext@prepareRefresh:583 - Refreshing Root WebApplicationContext: startup date [Tue Jan 15 19:28:05 UTC 2019]; root of context hierarchy 2019-01-15 19:28:05.253] [dev-box] [localhost-startStop-1] INFO o.s.w.c.s.AnnotationConfigWebApplicationContext@loadBeanDefinitions:208 - Registering annotated classes: [class org.opensmartgridplatform.adapter.protocol.oslp.elster.application.config.ApplicationContext] 2019-01-15 19:28:05.386] [dev-box] [localhost-startStop-1] INFO o.s.c.a.ConfigurationClassParser@processPropertySource:463 - Properties location [file:${osgp/AdapterProtocolOslpElster/config}] not resolvable: /etc/osp/osgp-adapter-protocol-oslp-elster.properties (No such file or directory) 2019-01-15 19:28:05.562] [dev-box] [localhost-startStop-1] INFO o.s.c.a.ConfigurationClassParser@processPropertySource:463 - Properties location [file:${osgp/AdapterProtocolOslpElster/config}] not resolvable: /etc/osp/osgp-adapter-protocol-oslp-elster.properties (No such file or directory) 2019-01-15 19:28:05.589] [dev-box] [localhost-startStop-1] INFO o.s.c.a.ConfigurationClassParser@processPropertySource:463 - Properties location [file:{osgp/AdapterProtocolOslpElster/config}] not resolvable: {osgp/AdapterProtocolOslpElster/config} (No such file or directory) 2019-01-15 19:28:05.593] [dev-box] [localhost-startStop-1] INFO o.s.c.a.ConfigurationClassParser@processPropertySource:463 - Properties location [file:${osgp/AdapterProtocolOslpElster/config}] not resolvable: /etc/osp/osgp-adapter-protocol-oslp-elster.properties (No such file or directory) 2019-01-15 19:28:05.622] [dev-box] [localhost-startStop-1] INFO o.s.c.a.ConfigurationClassParser@processPropertySource:451 - Properties location [file:${osgp/CoreDbApi/config}] not resolvable: Could not resolve placeholder 'osgp/CoreDbApi/config' in value "file:${osgp/CoreDbApi/config}" 2019-01-15 19:28:06.450] [dev-box] [localhost-startStop-1] INFO com.zaxxer.hikari.HikariDataSource@:72 - Hikari pool HikariPool-0 is starting. 2019-01-15 19:28:06.562] [dev-box] [localhost-startStop-1] INFO o.f.c.internal.util.VersionPrinter@info:44 - Flyway 4.1.2 by Boxfuse 2019-01-15 19:28:06.575] [dev-box] [localhost-startStop-1] INFO o.f.c.i.dbsupport.DbSupportFactory@info:44 - Database: jdbc:postgresql://localhost:5432/osgp_adapter_protocol_oslp (PostgreSQL 10.6) 2019-01-15 19:28:06.711] [dev-box] [localhost-startStop-1] INFO o.f.core.internal.command.DbValidate@info:44 - Successfully validated 2 migrations (execution time 00:00.069s) 2019-01-15 19:28:06.727] [dev-box] [localhost-startStop-1] INFO o.f.core.internal.command.DbMigrate@info:44 - Current version of schema "public": 20180724130600666 2019-01-15 19:28:06.727] [dev-box] [localhost-startStop-1] WARN o.f.core.internal.command.DbMigrate@warn:48 - outOfOrder mode is active. Migration of schema "public" may not be reproducible. 2019-01-15 19:28:06.728] [dev-box] [localhost-startStop-1] INFO o.f.core.internal.command.DbMigrate@info:44 - Schema "public" is up to date. No migration necessary. 2019-01-15 19:28:06.786] [dev-box] [localhost-startStop-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean@createNativeEntityManagerFactory:356 - Building JPA container EntityManagerFactory for persistence unit 'OSGP_PROTOCOL_ADAPTER_OSLP_SETTINGS' 2019-01-15 19:28:06.936] [dev-box] [localhost-startStop-1] INFO o.h.annotations.common.Version@:37 - HCANN000001: Hibernate Commons Annotations {4.0.2.Final} 2019-01-15 19:28:06.942] [dev-box] [localhost-startStop-1] INFO org.hibernate.Version@logVersion:41 - HHH000412: Hibernate Core {4.2.16.Final} 2019-01-15 19:28:06.945] [dev-box] [localhost-startStop-1] INFO org.hibernate.cfg.Environment@:238 - HHH000206: hibernate.properties not found 2019-01-15 19:28:06.946] [dev-box] [localhost-startStop-1] INFO org.hibernate.cfg.Environment@buildBytecodeProvider:345 - HHH000021: Bytecode provider name : javassist 2019-01-15 19:28:06.969] [dev-box] [localhost-startStop-1] INFO org.hibernate.ejb.Ejb3Configuration@configure:530 - HHH000204: Processing PersistenceUnitInfo [ name: OSGP_PROTOCOL_ADAPTER_OSLP_SETTINGS ...] 2019-01-15 19:28:07.143] [dev-box] [localhost-startStop-1] INFO o.h.s.j.c.i.ConnectionProviderInitiator@instantiateExplicitConnectionProvider:188 - HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider 2019-01-15 19:28:07.273] [dev-box] [localhost-startStop-1] INFO org.hibernate.dialect.Dialect@:130 - HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect 2019-01-15 19:28:07.285] [dev-box] [localhost-startStop-1] INFO o.h.e.j.internal.LobCreatorBuilder@useContextualLobCreation:120 - HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException 2019-01-15 19:28:07.422] [dev-box] [localhost-startStop-1] INFO o.h.e.t.i.TransactionFactoryInitiator@initiateService:73 - HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory 2019-01-15 19:28:07.429] [dev-box] [localhost-startStop-1] INFO o.h.h.i.a.ASTQueryTranslatorFactory@:48 - HHH000397: Using ASTQueryTranslatorFactory 2019-01-15 19:28:07.477] [dev-box] [localhost-startStop-1] INFO o.h.validator.internal.util.Version@:27 - HV000001: Hibernate Validator 4.3.1.Final 2019-01-15 19:28:07.777] [dev-box] [localhost-startStop-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean@buildNativeEntityManagerFactory:414 - Initialized JPA EntityManagerFactory for persistence unit 'OSGP_PROTOCOL_ADAPTER_OSLP_SETTINGS' 2019-01-15 19:28:07.806] [dev-box] [localhost-startStop-1] INFO com.zaxxer.hikari.HikariDataSource@:72 - Hikari pool HikariPool-1 is starting. 2019-01-15 19:28:07.815] [dev-box] [localhost-startStop-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean@createNativeEntityManagerFactory:356 - Building JPA container EntityManagerFactory for persistence unit 'OSGP_CORE_DB_API' 2019-01-15 19:28:07.816] [dev-box] [localhost-startStop-1] INFO org.hibernate.ejb.Ejb3Configuration@configure:530 - HHH000204: Processing PersistenceUnitInfo [ name: OSGP_CORE_DB_API ...] 2019-01-15 19:28:07.819] [dev-box] [localhost-startStop-1] INFO o.h.s.j.c.i.ConnectionProviderInitiator@instantiateExplicitConnectionProvider:188 - HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider 2019-01-15 19:28:07.919] [dev-box] [localhost-startStop-1] INFO org.hibernate.dialect.Dialect@:130 - HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect 2019-01-15 19:28:07.920] [dev-box] [localhost-startStop-1] INFO o.h.e.j.internal.LobCreatorBuilder@useContextualLobCreation:120 - HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException 2019-01-15 19:28:07.925] [dev-box] [localhost-startStop-1] INFO o.h.e.t.i.TransactionFactoryInitiator@initiateService:73 - HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory 2019-01-15 19:28:07.928] [dev-box] [localhost-startStop-1] INFO o.h.h.i.a.ASTQueryTranslatorFactory@:48 - HHH000397: Using ASTQueryTranslatorFactory 2019-01-15 19:28:07.958] [dev-box] [localhost-startStop-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean@buildNativeEntityManagerFactory:414 - Initialized JPA EntityManagerFactory for persistence unit 'OSGP_CORE_DB_API' 2019-01-15 19:28:08.166] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.queue 2019-01-15 19:28:08.170] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.explicit.qos.enabled 2019-01-15 19:28:08.198] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.time.to.live 2019-01-15 19:28:08.199] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.delivery.persistent 2019-01-15 19:28:08.200] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.initial.redelivery.delay 2019-01-15 19:28:08.201] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.maximum.redeliveries 2019-01-15 19:28:08.201] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.maximum.redelivery.delay 2019-01-15 19:28:08.202] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.redelivery.delay 2019-01-15 19:28:08.203] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.back.off.multiplier 2019-01-15 19:28:08.205] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.requests.use.exponential.back.off 2019-01-15 19:28:08.246] [dev-box] [localhost-startStop-1] INFO o.o.a.p.o.e.a.config.MessagingConfig@replyToQueue:222 - ------> replyToQueue: signing-server.1_0.responses-dev-box 2019-01-15 19:28:08.272] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.queue 2019-01-15 19:28:08.273] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.explicit.qos.enabled 2019-01-15 19:28:08.273] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.time.to.live 2019-01-15 19:28:08.274] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.delivery.persistent 2019-01-15 19:28:08.275] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.initial.redelivery.delay 2019-01-15 19:28:08.275] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.maximum.redeliveries 2019-01-15 19:28:08.276] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.maximum.redelivery.delay 2019-01-15 19:28:08.276] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.redelivery.delay 2019-01-15 19:28:08.277] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.back.off.multiplier 2019-01-15 19:28:08.277] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.responses.use.exponential.back.off 2019-01-15 19:28:08.904] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.queue 2019-01-15 19:28:08.906] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.explicit.qos.enabled 2019-01-15 19:28:08.908] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.time.to.live 2019-01-15 19:28:08.909] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.delivery.persistent 2019-01-15 19:28:08.910] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.initial.redelivery.delay 2019-01-15 19:28:08.911] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.maximum.redeliveries 2019-01-15 19:28:08.913] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.maximum.redelivery.delay 2019-01-15 19:28:08.913] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.redelivery.delay 2019-01-15 19:28:08.917] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.back.off.multiplier 2019-01-15 19:28:08.918] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.requests.use.exponential.back.off 2019-01-15 19:28:09.054] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.queue 2019-01-15 19:28:09.055] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.explicit.qos.enabled 2019-01-15 19:28:09.056] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.time.to.live 2019-01-15 19:28:09.057] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.delivery.persistent 2019-01-15 19:28:09.058] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.initial.redelivery.delay 2019-01-15 19:28:09.058] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.maximum.redeliveries 2019-01-15 19:28:09.059] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.maximum.redelivery.delay 2019-01-15 19:28:09.060] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.redelivery.delay 2019-01-15 19:28:09.060] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.back.off.multiplier 2019-01-15 19:28:09.060] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.log.item.requests.use.exponential.back.off 2019-01-15 19:28:09.164] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: REVOKE_KEY 2019-01-15 19:28:09.172] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: UPDATE_KEY 2019-01-15 19:28:09.177] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_CONFIGURATION 2019-01-15 19:28:09.188] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_FIRMWARE_VERSION 2019-01-15 19:28:09.193] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_STATUS 2019-01-15 19:28:09.205] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_REBOOT 2019-01-15 19:28:09.222] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_CONFIGURATION 2019-01-15 19:28:09.231] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_DEVICE_VERIFICATION_KEY 2019-01-15 19:28:09.235] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_EVENT_NOTIFICATIONS 2019-01-15 19:28:09.239] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: START_SELF_TEST 2019-01-15 19:28:09.244] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: STOP_SELF_TEST 2019-01-15 19:28:09.247] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SWITCH_CONFIGURATION_BANK 2019-01-15 19:28:09.253] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SWITCH_FIRMWARE 2019-01-15 19:28:09.291] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: UPDATE_DEVICE_SSL_CERTIFICATION 2019-01-15 19:28:09.368] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: UPDATE_FIRMWARE 2019-01-15 19:28:09.387] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_POWER_USAGE_HISTORY 2019-01-15 19:28:09.391] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_LIGHT_STATUS 2019-01-15 19:28:09.395] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: RESUME_SCHEDULE 2019-01-15 19:28:09.405] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_LIGHT 2019-01-15 19:28:09.409] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_LIGHT_SCHEDULE 2019-01-15 19:28:09.413] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_TRANSITION 2019-01-15 19:28:09.419] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: GET_TARIFF_STATUS 2019-01-15 19:28:09.427] [dev-box] [localhost-startStop-1] INFO o.o.s.i.jms.BaseMessageProcessorMap@addMessageProcessor:44 - Putting MessageProcessor in DeviceRequestMessageProcessorMap for MessageType: SET_TARIFF_SCHEDULE 2019-01-15 19:28:09.432] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.queue 2019-01-15 19:28:09.433] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.initial.redelivery.delay 2019-01-15 19:28:09.434] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.maximum.redeliveries 2019-01-15 19:28:09.434] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.maximum.redelivery.delay 2019-01-15 19:28:09.440] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.redelivery.delay 2019-01-15 19:28:09.440] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.back.off.multiplier 2019-01-15 19:28:09.441] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.use.exponential.back.off 2019-01-15 19:28:09.441] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.concurrent.consumers 2019-01-15 19:28:09.442] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.oslp.elster.requests.max.concurrent.consumers 2019-01-15 19:28:09.477] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.queue 2019-01-15 19:28:09.480] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.initial.redelivery.delay 2019-01-15 19:28:09.481] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.maximum.redeliveries 2019-01-15 19:28:09.481] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.maximum.redelivery.delay 2019-01-15 19:28:09.481] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.redelivery.delay 2019-01-15 19:28:09.482] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.back.off.multiplier 2019-01-15 19:28:09.482] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.use.exponential.back.off 2019-01-15 19:28:09.483] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.concurrent.consumers 2019-01-15 19:28:09.483] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.osgp.responses.max.concurrent.consumers 2019-01-15 19:28:09.485] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.initial.redelivery.delay 2019-01-15 19:28:09.486] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.maximum.redeliveries 2019-01-15 19:28:09.486] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.maximum.redelivery.delay 2019-01-15 19:28:09.487] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.redelivery.delay 2019-01-15 19:28:09.492] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.back.off.multiplier 2019-01-15 19:28:09.492] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.use.exponential.back.off 2019-01-15 19:28:09.493] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.concurrent.consumers 2019-01-15 19:28:09.493] [dev-box] [localhost-startStop-1] INFO o.o.s.a.c.j.JmsConfigurationFactory@property:201 - Trying to find property jms.signing.server.responses.max.concurrent.consumers 2019-01-15 19:28:09.899] [dev-box] [localhost-startStop-1] INFO o.s.c.s.DefaultLifecycleProcessor@start:341 - Starting beans in phase 2147483647 2019-01-15 19:28:10.107] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 19:28:10.325] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 19:28:10.400] [dev-box] [ActiveMQ Task-1] INFO o.a.a.t.failover.FailoverTransport@doReconnect:1052 - Successfully connected to tcp://localhost:61616 2019-01-15 19:28:10.456] [dev-box] [localhost-startStop-1] INFO o.s.web.context.ContextLoader@initWebApplicationContext:344 - Root WebApplicationContext: initialization completed in 5300 ms Jan 15, 2019 7:28:10 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["http-nio-8080"] Jan 15, 2019 7:28:10 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["ajp-nio-8009"] Jan 15, 2019 7:28:10 PM org.apache.catalina.startup.Catalina start INFO: Server startup in 11942 ms

kevinsmeets commented 5 years ago

Well, that logging looks OK. I think the component has started successfully. I assume if you run netstat -apn | grep 12122 in this case, you would see output indicating the component is listening at port 12122.

You could be having trouble with an issue I witnessed a couple of times, although being quite rare and difficult to reproduce. When all OSGP component are being deployed to 1 Tomcat application server, a library called BouncyCastle is on the classpath. And in the chapter 'Platform Setup' 'Deploying all Open Smart Grid Platform components to Apache Tomcat Server', you were told to deploy all OSGP components. Depending on some set of unknown conditions at this point, some components fail to start when the BouncyCastle is on the classpath. The BouncyCastle library is used by the smart metering components of OSGP.

To test if this is the case, you could try to deploy the public lighting set of components of OSGP, as the public lighting components are used in the documentation in the chapter 'Test the Platform'. Deploy these OSGP components to your Tomcat application server:

osgp-adapter-domain-admin
osgp-adapter-domain-core
osgp-adapter-domain-publiclighting
osgp-adapter-domain-tariffswitching
osgp-adapter-ws-admin
osgp-adapter-ws-core
osgp-adapter-ws-publiclighting
osgp-adapter-ws-tariffswitching
osgp-core
osgp-logging
osgp-protocol-adapter-oslp-elster
signing-server
web-demo-app 
web-device-simulator

Try netstat -apn | grep 12122 when running this reduced set of components in your Tomcat application server. If that shows that some Java process is listening at port 12122, try to add a device to OSGP using the web-demo-app and registering it using the web-device-simulator.

In case something still fails, I'm going to need all Tomcat logging. Tip: set your Eclipse console limit to a high number of characters, or simply switch the limit off. Right-click somewhere in the text area of the console and choose 'Preferences' to configure it: image

sarah225 commented 5 years ago

I deployed the reduced set of components to Tomcat application server and everything works perfectly for both SoapUI and PublicLighting Demo App. So,I guess I'm facing the rare case and cannot deploy all components at the same time. Ok, I'm trying to simulate Advanced Metering Infrastructure. In this case, I need several smart meters which use DLMS/COSEM protocol and a headend. Can you please tell me which components I must deploy to Tomcat application server?

kevinsmeets commented 5 years ago

Nice to hear it works for you 👍

If you want to use the smart metering components of OSGP, here's a list:

osgp-adapter-domain-admin
osgp-adapter-domain-core
osgp-adapter-domain-smartmetering
osgp-adapter-ws-admin
osgp-adapter-ws-core
osgp-adapter-ws-smartmetering
osgp-core
osgp-logging
osgp-protocol-adapter-dlms

We don't have an open source headend component available, so I guess you should use SoapUI as 'headend'. Also, we don't have an open source DLMS simulator, so I guess you should use a real smart meter. You should have a look at this issue: https://github.com/OSGP/Documentation/issues/180. Perhaps it can help you get started.

sarah225 commented 5 years ago

Thank you a million times for all the useful tips, you were a great help.

kevinsmeets commented 5 years ago

You are welcome, I'm glad I could help.

kolawoletech commented 3 years ago

my https endpoint does not work https://localhost/web-demo-app but this one works ,http://localhost:8080/web-demo-app/. How do I fix this issue, I get connection refused error at 443 when I try calling any of the SoapUI Request. Please can you direct me?

kevinsmeets commented 3 years ago

Perhaps Apache HTTPD is not running? Connection refused means nothing is listening at the port. Could also explain why an HTTPS URL is not working.