I have created a simple Spring Boot Application and compiled it with Spring Native gradle bootBuildImage. I uploaded the docker container to an private registry and deployed it to Microsoft Azure Function. Accessing the function will correctly start the Spring Boot Application inside the docker container. But it crashes with following exception:
2021-11-09T15:46:55.996267267Z 2021-11-09 15:46:55.996 INFO 1 --- [ main] o.s.nativex.NativeListener : This application is bootstrapped with code generated with Spring AOT
2021-11-09T15:46:55.997230973Z
2021-11-09T15:46:55.997396574Z . ____ _ __ _ _
2021-11-09T15:46:55.997539875Z /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
2021-11-09T15:46:55.997679976Z ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
2021-11-09T15:46:55.997816777Z \\/ ___)| |_)| | | | | || (_| | ) ) ) )
2021-11-09T15:46:55.997979078Z ' |____| .__|_| |_|_| |_\__, | / / / /
2021-11-09T15:46:55.998114779Z =========|_|==============|___/=/_/_/_/
2021-11-09T15:46:55.999546489Z :: Spring Boot :: (v2.5.6)
2021-11-09T15:46:55.999559889Z
2021-11-09T15:46:56.065075944Z 2021-11-09 15:46:56.054 INFO 1 --- [ main] o.s.boot.SpringApplication : Starting application using Java 11.0.13 on 421026966d15 with PID 1 (started by cnb in /workspace)
2021-11-09T15:46:56.065102544Z 2021-11-09 15:46:56.056 INFO 1 --- [ main] o.s.boot.SpringApplication : No active profile set, falling back to default profiles: default
2021-11-09T15:46:56.095177553Z 2021-11-09 15:46:56.094 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2021-11-09T15:46:56.097067866Z 2021-11-09 15:46:56.096 INFO 1 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 1 ms. Found 1 JPA repository interfaces.
2021-11-09T15:46:56.147529016Z 2021-11-09 15:46:56.147 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 80 (http)
2021-11-09T15:46:56.148811625Z 2021-11-09 15:46:56.148 INFO 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-11-09T15:46:56.149445829Z 2021-11-09 15:46:56.148 INFO 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.54]
2021-11-09T15:46:56.154613565Z 2021-11-09 15:46:56.154 INFO 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-11-09T15:46:56.155352670Z 2021-11-09 15:46:56.154 INFO 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 95 ms
2021-11-09T15:46:56.177839326Z 2021-11-09 15:46:56.177 INFO 1 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-11-09T15:46:56.179695539Z 2021-11-09 15:46:56.179 INFO 1 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.32.Final
2021-11-09T15:46:56.181115849Z 2021-11-09 15:46:56.180 INFO 1 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-11-09T15:46:56.183164263Z 2021-11-09 15:46:56.182 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-11-09T15:46:56.533544294Z 2021-11-09 15:46:56.533 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2021-11-09T15:46:56.534665902Z 2021-11-09 15:46:56.533 INFO 1 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
2021-11-09T15:46:56.675326478Z 2021-11-09 15:46:56.675 INFO 1 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-11-09T15:46:56.676515986Z 2021-11-09 15:46:56.676 INFO 1 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-11-09T15:46:56.722262803Z 2021-11-09 15:46:56.722 WARN 1 --- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2021-11-09T15:46:56.746931074Z 2021-11-09 15:46:56.746 WARN 1 --- [ main] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.context.ApplicationContextException: Failed to start bean 'webServerStartStop'; nested exception is org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat server
2021-11-09T15:46:56.749313091Z 2021-11-09 15:46:56.749 INFO 1 --- [ main] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2021-11-09T15:46:56.750124797Z 2021-11-09 15:46:56.749 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated...
2021-11-09T15:46:56.877499580Z 2021-11-09 15:46:56.877 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown completed.
2021-11-09T15:46:56.878593388Z 2021-11-09 15:46:56.877 INFO 1 --- [ main] o.apache.catalina.core.StandardService : Stopping service [Tomcat]
2021-11-09T15:46:56.888123954Z 2021-11-09 15:46:56.880 INFO 1 --- [ main] ConditionEvaluationReportLoggingListener :
2021-11-09T15:46:56.888151454Z
2021-11-09T15:46:56.888156354Z Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2021-11-09T15:46:56.888160554Z 2021-11-09 15:46:56.880 ERROR 1 --- [ main] o.s.boot.SpringApplication : Application run failed
2021-11-09T15:46:56.888164954Z
2021-11-09T15:46:56.888168654Z org.springframework.context.ApplicationContextException: Failed to start bean 'webServerStartStop'; nested exception is org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat server
2021-11-09T15:46:56.888172954Z at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:181) ~[de.aditu.buchschrank.BuchschrankApplicationKt:5.3.12]
2021-11-09T15:46:56.888177354Z at org.springframework.context.support.DefaultLifecycleProcessor.access$200(DefaultLifecycleProcessor.java:54) ~[de.aditu.buchschrank.BuchschrankApplicationKt:5.3.12]
2021-11-09T15:46:56.888181254Z at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.start(DefaultLifecycleProcessor.java:356) ~[na:na]
2021-11-09T15:46:56.888196454Z at java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
2021-11-09T15:46:56.888200454Z at org.springframework.context.support.DefaultLifecycleProcessor.startBeans(DefaultLifecycleProcessor.java:155) ~[de.aditu.buchschrank.BuchschrankApplicationKt:5.3.12]
2021-11-09T15:46:56.888204354Z at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:123) ~[de.aditu.buchschrank.BuchschrankApplicationKt:5.3.12]
2021-11-09T15:46:56.888208354Z at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:935) ~[na:na]
2021-11-09T15:46:56.888212155Z at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:586) ~[na:na]
2021-11-09T15:46:56.888216155Z at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[na:na]
2021-11-09T15:46:56.888220055Z at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754) ~[de.aditu.buchschrank.BuchschrankApplicationKt:2.5.6]
2021-11-09T15:46:56.888224455Z at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434) ~[de.aditu.buchschrank.BuchschrankApplicationKt:2.5.6]
2021-11-09T15:46:56.888228555Z at org.springframework.boot.SpringApplication.run(SpringApplication.java:338) ~[de.aditu.buchschrank.BuchschrankApplicationKt:2.5.6]
2021-11-09T15:46:56.888232355Z at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[de.aditu.buchschrank.BuchschrankApplicationKt:2.5.6]
2021-11-09T15:46:56.888236255Z at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[de.aditu.buchschrank.BuchschrankApplicationKt:2.5.6]
2021-11-09T15:46:56.888240055Z at de.aditu.buchschrank.BuchschrankApplicationKt.main(BuchschrankApplication.kt:17) ~[na:na]
2021-11-09T15:46:56.888243955Z Caused by: org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat server
2021-11-09T15:46:56.888247755Z at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.start(TomcatWebServer.java:229) ~[na:na]
2021-11-09T15:46:56.888251555Z at org.springframework.boot.web.servlet.context.WebServerStartStopLifecycle.start(WebServerStartStopLifecycle.java:43) ~[na:na]
2021-11-09T15:46:56.888255455Z at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:178) ~[de.aditu.buchschrank.BuchschrankApplicationKt:5.3.12]
2021-11-09T15:46:56.888259455Z ... 14 common frames omitted
2021-11-09T15:46:56.888263155Z Caused by: java.lang.IllegalArgumentException: standardService.connector.startFailed
2021-11-09T15:46:56.888266855Z at org.apache.catalina.core.StandardService.addConnector(StandardService.java:238) ~[na:na]
2021-11-09T15:46:56.888270755Z at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.addPreviouslyRemovedConnectors(TomcatWebServer.java:282) ~[na:na]
2021-11-09T15:46:56.888275055Z at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.start(TomcatWebServer.java:213) ~[na:na]
2021-11-09T15:46:56.888281755Z ... 16 common frames omitted
2021-11-09T15:46:56.888285555Z Caused by: org.apache.catalina.LifecycleException: Protocol handler start failed
2021-11-09T15:46:56.888289355Z at org.apache.catalina.connector.Connector.startInternal(Connector.java:1075) ~[na:na]
2021-11-09T15:46:56.888293055Z at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[na:na]
2021-11-09T15:46:56.888296855Z at org.apache.catalina.core.StandardService.addConnector(StandardService.java:234) ~[na:na]
2021-11-09T15:46:56.888300655Z ... 18 common frames omitted
2021-11-09T15:46:56.888304255Z Caused by: java.net.SocketException: Permission denied
2021-11-09T15:46:56.888308255Z at com.oracle.svm.jni.JNIJavaCallWrappers.jniInvoke_VA_LIST_SocketException_constructor_df417f52c09624a386e25e5af85993f853394076(JNIJavaCallWrappers.java:0) ~[na:na]
2021-11-09T15:46:56.888312255Z at sun.nio.ch.Net.bind0(Net.java) ~[na:na]
2021-11-09T15:46:56.888315955Z at sun.nio.ch.Net.bind(Net.java:455) ~[na:na]
2021-11-09T15:46:56.888319655Z at sun.nio.ch.Net.bind(Net.java:447) ~[na:na]
2021-11-09T15:46:56.888323255Z at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227) ~[na:na]
2021-11-09T15:46:56.888327055Z at org.apache.tomcat.util.net.NioEndpoint.initServerSocket(NioEndpoint.java:271) ~[de.aditu.buchschrank.BuchschrankApplicationKt:9.0.54]
2021-11-09T15:46:56.888330955Z at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:226) ~[de.aditu.buchschrank.BuchschrankApplicationKt:9.0.54]
2021-11-09T15:46:56.888334755Z at org.apache.tomcat.util.net.AbstractEndpoint.bindWithCleanup(AbstractEndpoint.java:1208) ~[de.aditu.buchschrank.BuchschrankApplicationKt:9.0.54]
2021-11-09T15:46:56.888338655Z at org.apache.tomcat.util.net.AbstractEndpoint.start(AbstractEndpoint.java:1294) ~[de.aditu.buchschrank.BuchschrankApplicationKt:9.0.54]
2021-11-09T15:46:56.888342555Z at org.apache.coyote.AbstractProtocol.start(AbstractProtocol.java:614) ~[de.aditu.buchschrank.BuchschrankApplicationKt:9.0.54]
2021-11-09T15:46:56.888346355Z at org.apache.catalina.connector.Connector.startInternal(Connector.java:1072) ~[na:na]
2021-11-09T15:46:56.888350255Z ... 20 common frames omitted
2021-11-09T15:46:56.888353856Z
Regarding the logs, Azure starts docker with
docker run -d -p 7502:80...
The first port seems to be random.
The full source code can be found here: https://github.com/lesestunden/buchschrank-backend
Does anybody have an idea whats going wrong?
Thanks a lot!
Your application should listen on a non-privileged port (> 1024).
The created container is unable to use a privileged port. The bootBuildImage task creates and runs images utilizing buildpacks (for runtime paketobuildpacks/run:tiny-cnb), the application in the container doesn't run as root. Therefore you can not listen on a port below 1024.
Spring boot uses paketo-buildpacks, which have some security-hardenings in them
The stack images are run as a dedicated non-root user when building and running applications.