steve-community / steve

SteVe - OCPP server implementation in Java
GNU General Public License v3.0
795 stars 388 forks source link

Start error for 3.4.0 and 3.3.2 #236

Closed scribas closed 4 years ago

scribas commented 4 years ago

Checklist

Specifications

SteVe Version     : 3.4.0 and 3.3.2
Operating system  : Ubuntu on AWS
JDK               : openjdk 11.0.4 2019-07-16
Database          :  mysql Ver 14.14 Distrib 5.7.27, for Linux (x86_64)

Expected Behavior

When running java -jar target/steve.jar, web server should start.

Actual Behavior

For SteVe.3.4.0: Maven ran successfully and produced target/steve.jar. When running java -jar target/steve.jar, I get the following error message:

Exception in thread "main" java.lang.ExceptionInInitializerError
        at de.rwth.idsg.steve.Application.<init>(Application.java:40)
        at de.rwth.idsg.steve.Application.main(Application.java:63)
Caused by: java.lang.NullPointerException
        at de.rwth.idsg.steve.utils.PropertiesFileLoader.trim(PropertiesFileLoader.java:173)
        at de.rwth.idsg.steve.utils.PropertiesFileLoader.getOptionalString(PropertiesFileLoader.java:100)
        at de.rwth.idsg.steve.SteveConfiguration.<init>(SteveConfiguration.java:66)
        at de.rwth.idsg.steve.SteveConfiguration.<clinit>(SteveConfiguration.java:35)
        ... 2 more

For Steve.3.3.2:

Log file: /home/ubuntu/logs/steve.log
Starting.......WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.jooq.tools.reflect.Reflect (file:/home/ubuntu/steve-steve-3.3.2/target/libs/jooq-3.11.11.jar) to constructor java.lang.invoke.MethodHandles$Lookup(java.lang.Class)
WARNING: Please consider reporting this to the maintainers of org.jooq.tools.reflect.Reflect
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
.............. FAILED!
Please refer to the log file for details

Log file contains:

[INFO ] 2019-11-11 08:27:09,208 de.rwth.idsg.steve.utils.PropertiesFileLoader - Hint: The Java system property 'main.properties' can be set to point to an external properties file, which will be prioritized over the bundled one
[INFO ] 2019-11-11 08:34:31,875 de.rwth.idsg.steve.utils.PropertiesFileLoader - Hint: The Java system property 'main.properties' can be set to point to an external properties file, which will be prioritized over the bundled one
[INFO ] 2019-11-11 08:38:23,230 de.rwth.idsg.steve.utils.PropertiesFileLoader - Hint: The Java system property 'main.properties' can be set to point to an external properties file, which will be prioritized over the bundled one
[INFO ] 2019-11-11 08:38:23,405 de.rwth.idsg.steve.Application - Loaded the properties. Starting with the 'PROD' profile
[INFO ] 2019-11-11 08:38:23,453 de.rwth.idsg.steve.Application - Date/time zone of the application is set to UTC. Current date/time: 2019-11-11T08:38:23.426Z
[INFO ] 2019-11-11 08:38:23,537 org.eclipse.jetty.util.log - Logging initialized @2232ms to org.eclipse.jetty.util.log.Slf4jLog
[INFO ] 2019-11-11 08:38:24,047 org.eclipse.jetty.server.Server - jetty-9.4.19.v20190610; built: 2019-06-10T16:30:51.723Z; git: afcf563148970e98786327af5e07c261fda175d3; jvm 11.0.4+11-post-Ubuntu-1ubuntu218.04.3
[INFO ] 2019-11-11 08:38:24,306 org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0
[INFO ] 2019-11-11 08:38:24,308 org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
[INFO ] 2019-11-11 08:38:24,309 org.eclipse.jetty.server.session - node0 Scavenging every 600000ms
[INFO ] 2019-11-11 08:38:24,329 org.eclipse.jetty.server.handler.ContextHandler.steve - Initializing Spring root WebApplicationContext
[INFO ] 2019-11-11 08:38:24,330 org.springframework.web.context.ContextLoader - Root WebApplicationContext: initialization started
[INFO ] 2019-11-11 08:38:26,414 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
[INFO ] 2019-11-11 08:38:26,762 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
[INFO ] 2019-11-11 08:38:31,150 org.apache.cxf.wsdl.service.factory.ReflectionServiceFactoryBean - Creating Service {urn://Ocpp/Cs/2010/08/}CentralSystemService from class ocpp.cs._2010._08.CentralSystemService
[INFO ] 2019-11-11 08:38:32,192 org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /CentralSystemServiceOCPP12
[INFO ] 2019-11-11 08:38:32,224 org.apache.cxf.wsdl.service.factory.ReflectionServiceFactoryBean - Creating Service {urn://Ocpp/Cs/2012/06/}CentralSystemService from class ocpp.cs._2012._06.CentralSystemService
[INFO ] 2019-11-11 08:38:32,407 org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /CentralSystemServiceOCPP15
[INFO ] 2019-11-11 08:38:32,411 org.apache.cxf.wsdl.service.factory.ReflectionServiceFactoryBean - Creating Service {urn://Ocpp/Cs/2015/10/}CentralSystemService from class ocpp.cs._2015._10.CentralSystemService
[INFO ] 2019-11-11 08:38:32,531 org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /CentralSystemServiceOCPP16
[INFO ] 2019-11-11 08:38:32,541 org.apache.cxf.wsdl.service.factory.ReflectionServiceFactoryBean - Creating Service {urn://Ocpp/Cs/2010/08/}CentralSystemService from class ocpp.cs._2010._08.CentralSystemService
[INFO ] 2019-11-11 08:38:32,558 org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /CentralSystemService
[INFO ] 2019-11-11 08:38:34,535 org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 6.0.16.Final
[INFO ] 2019-11-11 08:38:35,202 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/static/**'], []
[INFO ] 2019-11-11 08:38:35,207 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/views/**'], []
[INFO ] 2019-11-11 08:38:35,281 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@19c578bf, org.springframework.security.web.context.SecurityContextPersistenceFilter@2d4aadc, org.springframework.security.web.header.HeaderWriterFilter@43069adf, org.springframework.security.web.csrf.CsrfFilter@628b1538, org.springframework.security.web.authentication.logout.LogoutFilter@2d0ce8a1, org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter@4c897417, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@14ecd835, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@20e8286a, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@216c6825, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@1eeb9e5c, org.springframework.security.web.session.SessionManagementFilter@4823f4d0, org.springframework.security.web.access.ExceptionTranslationFilter@76e4df53, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@6c04310f]
[INFO ] 2019-11-11 08:38:35,728 org.springframework.web.context.ContextLoader - Root WebApplicationContext initialized in 11398 ms
[INFO ] 2019-11-11 08:38:35,863 org.eclipse.jetty.server.handler.ContextHandler.steve - Initializing Spring DispatcherServlet 'spring-dispatcher'
[INFO ] 2019-11-11 08:38:35,867 org.springframework.web.servlet.DispatcherServlet - Initializing Servlet 'spring-dispatcher'
[INFO ] 2019-11-11 08:38:35,887 org.springframework.web.servlet.DispatcherServlet - Completed initialization in 20 ms
[INFO ] 2019-11-11 08:38:35,916 org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@6adc90e9{/steve,jar:file:/home/ubuntu/steve-steve-3.3.2/target/steve.jar!/webapp,AVAILABLE}
[ERROR] 2019-11-11 08:38:35,926 de.rwth.idsg.steve.SteveProdStarter - Exception happened
java.io.IOException: Failed to bind to /63.34.91.23:8080
        at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:346) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:308) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.server.Server.doStart(Server.java:396) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
        at de.rwth.idsg.steve.JettyServer.start(JettyServer.java:162) ~[steve.jar:?]
        at de.rwth.idsg.steve.SteveProdStarter.start(SteveProdStarter.java:55) ~[steve.jar:?]
        at de.rwth.idsg.steve.Application.start(Application.java:75) ~[steve.jar:?]
        at de.rwth.idsg.steve.Application.main(Application.java:64) ~[steve.jar:?]
Caused by: java.net.BindException: Cannot assign requested address
        at sun.nio.ch.Net.bind0(Native Method) ~[?:?]
        at sun.nio.ch.Net.bind(Net.java:461) ~[?:?]
        at sun.nio.ch.Net.bind(Net.java:453) ~[?:?]
        at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227) ~[?:?]
        at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:80) ~[?:?]
        at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:342) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
        ... 10 more
[INFO ] 2019-11-11 08:38:35,940 org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@38f2342b{HTTP/1.1,[http/1.1]}{63.34.91.23:8080}
[INFO ] 2019-11-11 08:38:35,940 org.eclipse.jetty.server.session - node0 Stopped scavenging
[INFO ] 2019-11-11 08:38:35,945 org.eclipse.jetty.server.handler.ContextHandler.steve - Destroying Spring FrameworkServlet 'spring-dispatcher'
[INFO ] 2019-11-11 08:38:35,957 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
[INFO ] 2019-11-11 08:38:35,975 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
[INFO ] 2019-11-11 08:38:35,977 org.eclipse.jetty.server.handler.ContextHandler.steve - Closing Spring root WebApplicationContext
[INFO ] 2019-11-11 08:38:35,979 org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.w.WebAppContext@6adc90e9{/steve,jar:file:/home/ubuntu/steve-steve-3.3.2/target/steve.jar!/webapp,UNAVAILABLE}

Steps to Reproduce the Problem

  1. See above

Additional context

I first tried SteVe.3.4.0, but got above error. I then tried to go back to SteVe.3.3.2. Both compiled successfully with maven, but refused to start running. I would appreciate if I can get either version running. Please assist.

goekay commented 4 years ago

the exception from Steve.3.3.2 is an indicator for main.properties file not being configured correctly.

i think, that the exception from Steve.3.4.0 is a different manifestation of the same underlying cause. i will add additional guards to prevent this exception, but they will not resolve your problem.

please make sure that values for fields in main.properties are correct, e.g. you are using the correct ip and port.

scribas commented 4 years ago

awesome, will have a look. does the port have to be 8080 for unencrypted and 8442 for encrypted?

goekay commented 4 years ago

no, not at all. these values depend on your specific system and network configuration.

scribas commented 4 years ago

Below is the main.properties file. I just changed the 2 usernames and passwords and the server_host to my_aws_elastic_ip for security reasons. Can you spot anything else wrong?

# Just to be backwards compatible with previous versions, this is set to "steve",
# since there might be already configured chargepoints expecting the older path.
# Otherwise, might as well be changed to something else or be left empty.
#
context.path = steve

# Database configuration
#
db.ip = localhost
db.port = 3306
db.schema = stevedb
db.user = db_user
db.password = db_password

# Credentials for Web interface access
#
auth.user = steve_user
auth.password = steve_password

# Jetty configuration
#
server.host = my_aws_elastic_ip
server.gzip.enabled = false

# Jetty HTTP configuration
#
http.enabled = true
http.port = 8080

# Jetty HTTPS configuration
#
https.enabled = false
https.port = 8443
keystore.path =
keystore.password =

# When the WebSocket/Json charge point opens more than one WebSocket connection,
# we need a mechanism/strategy to select one of them for outgoing requests.
# For allowed values see de.rwth.idsg.steve.ocpp.ws.custom.WsSessionSelectStrategyEnum.
#
ws.session.select.strategy = ALWAYS_LAST

# if BootNotification messages arrive (SOAP) or WebSocket connection attempts are made (JSON) from unknown charging
# stations, we reject these charging stations, because stations with these chargeBoxIds were NOT inserted into database
# beforehand. by setting this property to true, this behaviour can be modified to automatically insert unknown
# stations into database and accept their requests.
#
# CAUTION: setting this property to true is very dangerous, because we will accept EVERY BootNotification or WebSocket
# connection attempt from ANY sender as long as the sender knows the URL and sends a valid message.
#
auto.register.unknown.stations = false

### DO NOT MODIFY ###
steve.version = ${project.version}
git.describe = ${git.commit.id.describe}
db.sql.logging = false
profile = prod
goekay commented 4 years ago

Can you spot anything else wrong?

no, but i also have no experience running java servers on aws. my instinct is that the ip you are setting is not the ip you should be using.

kalldert commented 4 years ago

Hi, I dont know if this helps or not but I just tried to install 3.4.0 on a fresh instance of Ubuntu 18.04 VM and got the exact same error on 3.4.0 as mentioned here. Rolled back my VM and used the same main.properties that I used on 3.4.0 on 3.3.2 and that works perfectly.

/Jonas

goekay commented 4 years ago

@kalldert thanks for your input. can you please test the repository with my latest commit ddd6fc0cef0209cfe10639811ff4a605ca067623 and give feedback, whether the issue is resolved. the problem seems to be caused by 72cad0be272587ea22af677eb091455f4d5617ff, which was introduced earlier.

still, since @scribas is having issues with 3.3.2 as well, the exception stacktrace indicates a wrongly used ip setting.

scribas commented 4 years ago

I tried using the public DNS of AWS, which I use to connect with SSH and SCP. Now SteVe actually launches on 3.3.2. The problem is that I then cannot access the web interface with the public DNS address it provides, nor with the elastic IP. As @goekay mentioned, this is most probably an issue with AWS specifically. 3.4.0 still throws the same problem mentioned before.

kalldert commented 4 years ago

@goekay Thanks. I installed the latest update and 3.4.0 now works.

goekay commented 4 years ago

3.4.0 still throws the same problem mentioned before.

@scribas 3.4.0 should not throw the NullPointerException anymore. something like java.net.BindException: Cannot assign requested address is still possible, since --as i said it-- is related to your ip setting and aws setup. i cannot help there.

@kalldert this is great to hear.

scribas commented 4 years ago

@goekay i have now launched a google cloud instance, to see whether this works better. Again, if I use the public IP address that Google provided, the app cannot bind to the IP address and fails. It runs successfully, if I point Steve to the internal IP address, however, then it does not seem to be reachable (or at least, I don't know how to reach it).

Btw, I did open up the outgoing 8080 port on both the operating system and the Google cloud management interface. Same on AWS. Not sure what to try next?

goekay commented 4 years ago

@scribas it is perfectly reasonable that external/public IP is only there for clients to access it. local apps probably should bind to localhost or 127.0.0.1. now, the request routing from external ip/port to internal ip/port should be part of a configuration, how this configuration step should be done is specific to your cloud/vm provider.

csamsel commented 4 years ago

@scribas what ip configuration are you using for your cloud service? for google cloud a reserved fixed ip adress is not actually assigned to your instance (so steve can not bind to it) but via a 1:1 NAT to the ethereal instance ip. What you have to do in this case is have steve bind to 0.0.0.0

Also you have to allow traffic INCOMING (ingress) on port 8080 (or what ever you use)

scribas commented 4 years ago

@csamsel apologies - I opened the incoming ports. The outgoing ports are all open.

I tried binding steve to 0.0.0.0, but that did not help either. Do I maybe need to do something with iptables, to route the external IP to localhost?

csamsel commented 4 years ago

No, thats done by Google. You could check if the VMs firewall (if activated) is blocking anything. Should be showing up in dmesg. If it's ubuntu you could do e.g. ufw allow 8080

scribas commented 4 years ago

@csamsel I am indeed running ubuntu on both Google Cloud and AWS. I tried running centos on AWS at the beginning, but found that software versions were a bit more outdated, as they are more conservative.

I ran dmesg and read up a bit more about it. I could not see anything in particular, although, may simply not know what to look for. But at least I now know more about dmesg. Too much to learn about this linux world.

I did not know about ufw either. I rather followed some tutorials, installed firewalld and used firewall_ctrl to open up the ports.

Initially, on AWS, I did upload php and apache, and saw the default php welcome page on port 80. When I started the SteVe installation, port 80 went dead. I hope that this does not mean that I broke something towards the outside world, but suspect that this was rather jetty replacing itself with apache as the default web server? I must admit that I still don't understand the web server world well enough, to go look for the place in etc where the default web server resides, never mind how one would make both run in parallel.

goekay commented 4 years ago

guys.... so many people are running java servers on cloud providers (aws, google cloud, etc.). i cannot imagine this configuration being so hard and it requiring such intricate tinkering.

i just googled a bit and came across the following pages:

the table from "get started" page contains multiple sample projects. the sample project "java-se-jetty-gradle-v3.zip" has one java class, where only the port is set. and the port is read as system environment variable. if i remember correctly, jetty binds to 0.0.0.0 if no hostname is set. therefore, the following should work.

server.host = 0.0.0.0
http.port = $PORT

now the question is: where does the port come from? some management/configuration web ui must have this setting.

another project from the table (https://github.com/aws-samples/eb-java-scorekeep) uses localhost as server.host and 5000 as port.

csamsel commented 4 years ago

@goekay There are multiple ways of deploying things to e.g. AWS.

You absolutely can use a infrastructure as a service solution where you directly deploy the Steve application to AWS using Elastic Beanstalk and configure it to use a Amazon RDS MySQL instance as database. That would probably be the preferred way as you dont have to deal with OS updates and HA and backups come with it at no additional configuration - but it would also cost more.

@scribas just spun up a standard Ubuntu VM in AWS (probably using EC2) as you would you do in VMware vCenter and tried configuring it. Thats a bit cheaper and you are a bit more flexible w.r.t. to e.g. JDK and MySQL versions. Also costs less then using RDS.

For me personally, both variants are quiet straight forward to configure, but without AWS and Linux knowledge it isn't. But then i would recommend running any service available on the internet anyways.

@goekay The AWS Java SDK you linked is for orchestration (similar as the vCenter API) - you can configure AWS with - e.g. the Deployment units, API Gateway, Lamba configuration and such. Not really relevant here.

csamsel commented 4 years ago

I created a SteVe instance using AWS lightsail and it worked fine.

csamsel commented 4 years ago

@scribas @goekay I wrote a howto for AWS Lightsail: https://github.com/RWTH-i5-IDSG/steve/wiki/Create-SteVe-Instance-in-AWS-Lightsail

scribas commented 4 years ago

@csamsel i wanted to try out your tutorial today, but ended up running out of time. Hopefully, I will get a gap tomorrow. Thank you so much for your effort! This looks very detailed.

scribas commented 4 years ago

@csamsel, I finally managed to get it running. Very well written tutorial!

Initially, I locked myself out of ssh, because I allowed ubuntu to replace the config file with the default operating system config. May be worth adding into your wiki page, that when prompted during the apt upgrade whether config files should be replaced by default operating system files, NOT to do that. Sort of obvious in hindsight, but while following a tutorial, one does not always think things through.

Then, to really finish off the tutorial, please add right at the end, that the internal IP address must obviously be replaced by the public IP in the URL to access the management environment.

Finally, please create a link on the main page of the project to this tutorial. This is super useful for people wanting to deploy steve on AWS.

Just out of interest, do you have any idea how many professional charging companies are actually running steve to manage their infrastructure? It would be interesting to get some sort of idea, whether there are major companies using this open source project?

csamsel commented 4 years ago

Thanks for your feedback, i'll add a few remarks. But please keep in mind that these are very basic issues, that everyone working on Linux/Servers/Cloud must understand. If not, please ask someone who does.

We know a few cases of companies having SteVe running in AWS (EC2 though, not Lightsail). Most SteVe instances are probably deployed in a residential environment - as VM or an Raspberry Pi.

goekay commented 4 years ago

Just out of interest, do you have any idea how many professional charging companies are actually running steve to manage their infrastructure?

@scribas i am being contacted with questions etc. from multiple companies from all over the world all the time. however, i cannot say how big these companies are and how many stations/users they are managing.