CODEWITHSUNDEEP
javaspring-bootamazon-elastic-beanstalk
Ben
Ben

Reputation: 86

Spring Boot App Fails to Start on Elastic Beanstalk

I am trying to run my Spring Boot + MySQL app on Elastic Beanstalk. No matter what I try I get the 502 Bad Gateway. I have tried changing my Spring Boot port to 5000, but it does not seem to help at all.

I have tried adding server.port=5000 in application.properties. I have also tried adding server.port=${PORT}.

Every time I eb deploy the logs show this:

03:08:21.096 [main] INFO  t.t.TrackMyWaterChangeApplication - Starting TrackMyWaterChangeApplication v0.0.1-SNAPSHOT on ip-172-31-41-134 with PID 6105 (/var/app/current/application.jar started by webapp in /var/app/current)
03:08:21.098 [main] INFO  t.t.TrackMyWaterChangeApplication - No active profile set, falling back to default profiles: default
03:08:54.024 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Bootstrapping Spring Data repositories in DEFAULT mode.
03:08:56.577 [main] INFO  o.s.d.r.c.RepositoryConfigurationDelegate - Finished Spring Data repository scanning in 2305ms. Found 4 repository interfaces.
03:09:20.544 [main] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$c95c6ba6] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
03:09:35.665 [main] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat initialized with port(s): 5000 (http)
03:09:36.122 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-5000"]
03:09:36.533 [main] INFO  o.a.catalina.core.StandardService - Starting service [Tomcat]
03:09:36.533 [main] INFO  o.a.catalina.core.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.21]
03:09:39.127 [main] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext
03:09:39.128 [main] INFO  o.s.web.context.ContextLoader - Root WebApplicationContext: initialization completed in 75522 ms
03:09:59.224 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
03:10:08.318 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
03:10:08.880 [main] INFO  org.hibernate.Version - HHH000412: Hibernate Core {5.3.10.Final}
03:10:08.889 [main] INFO  org.hibernate.cfg.Environment - HHH000205: Loaded properties from resource hibernate.properties: {hibernate.dialect=org.hibernate.dialect.MySQLDialect, hibernate.bytecode.use_reflection_optimizer=false}
03:10:09.268 [main] INFO  o.h.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.0.4.Final}
03:10:10.046 [main] INFO  org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
03:10:12.003 [main] INFO  o.s.o.j.LocalContainerEntityManagerFactoryBean - Initialized JPA EntityManagerFactory for persistence unit 'default'
03:10:13.291 [main] INFO  o.h.h.i.QueryTranslatorFactoryInitiator - HHH000397: Using ASTQueryTranslatorFactory
03:10:14.039 [main] INFO  o.s.o.j.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'default'
03:10:14.041 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
03:10:14.049 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
03:10:14.063 [main] INFO  o.a.catalina.core.StandardService - Stopping service [Tomcat]

My assumption is that the app never starts because of the last line (o.a.catalina.core.StandardService - Stopping service [Tomcat]). It works when I run locally when I set the port to 5000. To deploy the app I use mvn clean package and then eb deploy. If I run the packaged JAR from the command line on my Windows PC, it runs no problem. This is the <build> portion of my pom.xml file:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.1.6.RELEASE</version>
        <relativePath /> <!-- lookup parent from repository -->
    </parent>
    <groupId>themayoras</groupId>
    <artifactId>trackmywaterchange</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <name>trackmywaterchange</name>
    <description>Web Project for tracking water change schedules</description>

    <properties>
        <java.version>1.8</java.version>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-data-jpa</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-devtools</artifactId>
            <scope>runtime</scope>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework</groupId>
                    <artifactId>spring-core</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

        <!-- Hibernate Validator -->
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-validator</artifactId>
            <version>6.0.17.Final</version>
        </dependency>

        <!-- thymeleaf -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-thymeleaf</artifactId>
        </dependency>

        <!-- AOP -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>

        <!-- Spring Security -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-security</artifactId>
        </dependency>


        <!-- SL4FJ Logging -->

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.5</version>
        </dependency>


        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.3</version>
        </dependency>


    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <configuration>
                    <mainClass>${start-class}</mainClass>
                    <layout>JAR</layout>
                </configuration>

                <executions>
                    <execution>
                        <goals>
                            <goal>repackage</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

</project>

edit: I am getting a new log message under /var/log/nginx/error.log that reads 

Professional SP1 x64|'|'|No|'|'|0.7d|'|'|..|'|'|AA==|'|'|112.inf|'|'|SGFjS2VkDQoxOTIuMTY4LjkyLjIyMjo1NTUyDQpEZXNrdG9wDQpjbGllbnRhLmV4ZQ0KRmFsc2UNCkZhbHNlDQpUcnVlDQpGYWxzZQ==12.act|'|'|AA=="
2019/08/11 16:48:57 [error] 1293#0: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 35.21.86.49, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:5000/", host: "trackmywaterchange.us-east-2.elasticbeanstalk.com"
2019/08/11 16:48:57 [error] 1293#0: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 35.21.86.49, server: , request: "GET /favicon.ico HTTP/1.1", upstream: "http://127.0.0.1:5000/favicon.ico", host: "trackmywaterchange.us-east-2.elasticbeanstalk.com", referrer: "http://trackmywaterchange.us-east-2.elasticbeanstalk.com/"

logs under /var/logs/nginx/error.log

2019/08/11 03:16:33 [error] 6663#0: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 35.21.86.49, server: , request: "GET /favicon.ico HTTP/1.1", upstream: "http://127.0.0.1:5000/favicon.ico", host: "trackmywaterchange.us-east-2.elasticbeanstalk.com", referrer: "http://trackmywaterchange.us-east-2.elasticbeanstalk.com/"
2019/08/11 05:40:09 [warn] 6663#0: *4 using uninitialized "year" variable while logging request, client: 194.32.117.3, server: , request: "GET / HTTP/1.1"
2019/08/11 05:40:09 [warn] 6663#0: *4 using uninitialized "month" variable while logging request, client: 194.32.117.3, server: , request: "GET / HTTP/1.1"
2019/08/11 05:40:09 [warn] 6663#0: *4 using uninitialized "day" variable while logging request, client: 194.32.117.3, server: , request: "GET / HTTP/1.1"
2019/08/11 05:40:09 [warn] 6663#0: *4 using uninitialized "hour" variable while logging request, client: 194.32.117.3, server: , request: "GET / HTTP/1.1"
2019/08/11 13:26:14 [warn] 6663#0: *26 using uninitialized "year" variable while logging request, client: 164.132.153.130, server: , request: "CONNECT i.instagram.com:443 HTTP/1.1"
2019/08/11 13:26:14 [warn] 6663#0: *26 using uninitialized "month" variable while logging request, client: 164.132.153.130, server: , request: "CONNECT i.instagram.com:443 HTTP/1.1"
2019/08/11 13:26:14 [warn] 6663#0: *26 using uninitialized "day" variable while logging request, client: 164.132.153.130, server: , request: "CONNECT i.instagram.com:443 HTTP/1.1"
2019/08/11 13:26:14 [warn] 6663#0: *26 using uninitialized "hour" variable while logging request, client: 164.132.153.130, server: , request: "CONNECT i.instagram.com:443 HTTP/1.1"
2019/08/11 14:30:49 [warn] 6663#0: *33 using uninitialized "year" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:49 [warn] 6663#0: *33 using uninitialized "month" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:49 [warn] 6663#0: *33 using uninitialized "day" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:49 [warn] 6663#0: *33 using uninitialized "hour" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:50 [warn] 6663#0: *32 using uninitialized "year" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:50 [warn] 6663#0: *32 using uninitialized "month" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:50 [warn] 6663#0: *32 using uninitialized "day" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:50 [warn] 6663#0: *32 using uninitialized "hour" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:58 [warn] 6663#0: *34 using uninitialized "year" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:58 [warn] 6663#0: *34 using uninitialized "month" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:58 [warn] 6663#0: *34 using uninitialized "day" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:30:58 [warn] 6663#0: *34 using uninitialized "hour" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:31:06 [warn] 6663#0: *35 using uninitialized "year" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:31:06 [warn] 6663#0: *35 using uninitialized "month" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:31:06 [warn] 6663#0: *35 using uninitialized "day" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:31:06 [warn] 6663#0: *35 using uninitialized "hour" variable while logging request, client: 110.249.212.46, server: , request: "GET http://110.249.212.46/testget?q=23333&port=80 HTTP/1.1"
2019/08/11 14:33:45 [warn] 6663#0: *36 using uninitialized "year" variable while logging request, client: 66.240.205.34, server: , request: "145.ll|'|'|SGFjS2VkX0Q0OTkwNjI3|'|'|WIN-JNAPIER0859|'|'|JNapier|'|'|19-02-01|'|'||'|'|Win 7 Professional SP1 x64|'|'|No|'|'|0.7d|'|'|..|'|'|AA==|'|'|112.inf|'|'|SGFjS2VkDQoxOTIuMTY4LjkyLjIyMjo1NTUyDQpEZXNrdG9wDQpjbGllbnRhLmV4ZQ0KRmFsc2UNCkZhbHNlDQpUcnVlDQpGYWxzZQ==12.act|'|'|AA=="
2019/08/11 14:33:45 [warn] 6663#0: *36 using uninitialized "month" variable while logging request, client: 66.240.205.34, server: , request: "145.ll|'|'|SGFjS2VkX0Q0OTkwNjI3|'|'|WIN-JNAPIER0859|'|'|JNapier|'|'|19-02-01|'|'||'|'|Win 7 Professional SP1 x64|'|'|No|'|'|0.7d|'|'|..|'|'|AA==|'|'|112.inf|'|'|SGFjS2VkDQoxOTIuMTY4LjkyLjIyMjo1NTUyDQpEZXNrdG9wDQpjbGllbnRhLmV4ZQ0KRmFsc2UNCkZhbHNlDQpUcnVlDQpGYWxzZQ==12.act|'|'|AA=="
2019/08/11 14:33:45 [warn] 6663#0: *36 using uninitialized "day" variable while logging request, client: 66.240.205.34, server: , request: "145.ll|'|'|SGFjS2VkX0Q0OTkwNjI3|'|'|WIN-JNAPIER0859|'|'|JNapier|'|'|19-02-01|'|'||'|'|Win 7 Professional SP1 x64|'|'|No|'|'|0.7d|'|'|..|'|'|AA==|'|'|112.inf|'|'|SGFjS2VkDQoxOTIuMTY4LjkyLjIyMjo1NTUyDQpEZXNrdG9wDQpjbGllbnRhLmV4ZQ0KRmFsc2UNCkZhbHNlDQpUcnVlDQpGYWxzZQ==12.act|'|'|AA=="
2019/08/11 14:33:45 [warn] 6663#0: *36 using uninitialized "hour" variable while logging request, client: 66.240.205.34, server: , request: "145.ll|'|'|SGFjS2VkX0Q0OTkwNjI3|'|'|WIN-JNAPIER0859|'|'|JNapier|'|'|19-02-01|'|'||'|'|Win 7 Professional SP1 x64|'|'|No|'|'|0.7d|'|'|..|'|'|AA==|'|'|112.inf|'|'|SGFjS2VkDQoxOTIuMTY4LjkyLjIyMjo1NTUyDQpEZXNrdG9wDQpjbGllbnRhLmV4ZQ0KRmFsc2UNCkZhbHNlDQpUcnVlDQpGYWxzZQ==12.act|'|'|AA=="
2019/08/11 16:48:57 [error] 1293#0: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 35.21.86.49, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:5000/", host: "trackmywaterchange.us-east-2.elasticbeanstalk.com"
2019/08/11 16:48:57 [error] 1293#0: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 35.21.86.49, server: , request: "GET /favicon.ico HTTP/1.1", upstream: "http://127.0.0.1:5000/favicon.ico", host: "trackmywaterchange.us-east-2.elasticbeanstalk.com", referrer: "http://trackmywaterchange.us-east-2.elasticbeanstalk.com/"

/etc/nginx/nginx.conf:

user                    nginx;
error_log               /var/log/nginx/error.log warn;
pid                     /var/run/nginx.pid;
worker_processes        auto;
worker_rlimit_nofile    32793;

events {
    worker_connections  1024;
}

http {
    include       /etc/nginx/mime.types;
    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

    include       conf.d/*.conf;

    map $http_upgrade $connection_upgrade {
        default     "upgrade";
    }

    server {
        listen        80 default_server;
        access_log    /var/log/nginx/access.log main;

        client_header_timeout 60;
        client_body_timeout   60;
        keepalive_timeout     60;
        gzip                  off;
        gzip_comp_level       4;
        gzip_types text/plain text/css application/json application/javascript application/x-javascript text/xml application/xml application/xml+rss text/javascript;

        # Include the Elastic Beanstalk generated locations
        include conf.d/elasticbeanstalk/*.conf;
    }
}

Upvotes: 1

Views: 2125

Answers (2)

Ben
Ben

Reputation: 86

This ended up failing on a database connection.

If you notice in the log, there is this line:

03:10:13.291 [main] INFO  o.h.h.i.QueryTranslatorFactoryInitiator - HHH000397: Using ASTQueryTranslatorFactory

As it turns out, the startup fails after this step. Unfortunately there isn't a good error message describing what is wrong, but after a lot of testing, I found that it was due to a failure to connect to the database.

Here are the basic troubleshooting steps that I took.

  1. Verify locally:

    This should go without saying, but shut down your local database and try to start your app. If it fails, then you've got your issue, otherwise this is not your root cause.

  2. Verify all spelling:

    Again, this should go without saying, but after figuring out the issue, check your spelling. For example, I was using this as my datasource url in my application.properties jdbc:mysql://${MSYQL_HOST:test_host}:${MYSQL_PORT:3306}/${MYSQL_DB:test_db}. If you look carefully, you will notice that my MYSQL_HOST environment variable is spelled wrong.

  3. SSH and Check you Connection

    Try to connect to your database after ssh'ing into your environment. After doing yum install MySQL, use this command: MySQL -h 'rds-endpoint-url' -P 'rds-DB-port' -u 'db-username' -p. After entering the connection password, you should enter a MySQL prompt. If not, check that your RDS instance is in the same VPC as your ec2 or elb instance and allows the security group that your ec2 or elb instance has.

After all is said and done, these general steps will hopefully resolve your issue.

Upvotes: 1

vaquar khan
vaquar khan

Reputation: 11479

seems like following dependancy is missing in your pom ,could you plz update full pom in question ?

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>

Upvotes: 1

Related Questions