问题描述
App Service for Linux 资源创建完成后，通过FTP方式把 .jar包（logdemo.jar）包上传到 /site/wwwroot/ 文件夹后，在App Service的Configration 配置页面配置启动命令为：
java -jar /site/wwwroot/logdemo.jar
但是，在访问App Service时，却是 Application Error 错误 （503 Service Temporarily Unavailable）
image
问题解决
第一步：查看日志
进入App Service的Kudu站点(https://<your app service name>.scm.chinacloudsites.cn/DebugConsole)，查看Log Stream，检查错误日志
image
第二步：分析错误信息
2022-02-19T08:55:59.035870757Z Add private certificates to keystore if exists...
2022-02-19T08:55:59.035875157Z Configuring max heap = 1346 MB
2022-02-19T08:55:59.076047416Z STARTUP_FILE=
2022-02-19T08:55:59.076713522Z STARTUP_COMMAND=java -jar /site/wwwroot/logdemo.jar
2022-02-19T08:55:59.076729422Z No STARTUP_FILE available.
2022-02-19T08:55:59.085391200Z Running STARTUP_COMMAND: java -jar /site/wwwroot/logdemo.jar
2022-02-19T08:55:59.087846422Z Error: Unable to access jarfile /site/wwwroot/logdemo.jar
2022-02-19T08:55:59.095872294Z Finished running startup file 'java -jar /site/wwwroot/logdemo.jar'. Exit code: '1'.
2022-02-19T08:55:59.115095866Z Custom startup complete. Now, exiting with exit code '1'
/home/LogFiles/2022_02_19_lw0sdlwk00005J_docker.log (https://xxxxx.scm.chinacloudsites.cn/api/vfs/LogFiles/2022_02_19_lw0sdlwk00005J_docker.log)
2022-02-19T08:55:49.578Z INFO - Pull Image successful, Time taken: 0 Minutes and 0 Seconds
2022-02-19T08:55:49.659Z INFO - Starting container for site
2022-02-19T08:55:49.660Z INFO - docker run -d -p 8080:8080 --name lbjavainlinux_0_2fbcc321 -e PORT=8080 -e WEBSITE_SITE_NAME=lbjavainlinux -e WEBSITE_AUTH_ENABLED=False -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_HOSTNAME=lbjavainlinux.chinacloudsites.cn -e WEBSITE_INSTANCE_ID=f902a04a85d38b0fa81789a73bd7f0fd35ab4400956424760d2a2f982ef05b43 mcr.microsoft.com/azure-app-service/java:8-jre8_210526002747 java -jar /site/wwwroot/logdemo.jar
2022-02-19T08:55:49.660Z INFO - Logging is not enabled for this container.
Please use https://aka.ms/linux-diagnostics to enable logging to see container logs here.
2022-02-19T08:55:58.101Z INFO - Initiating warmup request to container lbjavainlinux_0_2fbcc321 for site lbjavainlinux
2022-02-19T08:55:59.460Z ERROR - Container lbjavainlinux_0_2fbcc321 for site lbjavainlinux has exited, failing site start
2022-02-19T08:55:59.467Z ERROR - Container lbjavainlinux_0_2fbcc321 didn't respond to HTTP pings on port: 8080, failing site start. See container logs for debugging.
2022-02-19T08:55:59.497Z INFO - Stopping site lbjavainlinux because it failed during startup.
日志显示，不能访问jar文件 /site/wwwroot/logdemo.jar, 所以站点无法启动。 但是通过Kudu Bash查看App Service的文件，发现logdemo.jar文件时存在的：
image
所以问题根源就是 App Service的Java应用启动命令中，jar包路径配置错误。正确的启动命令为：
java -jar /home/site/wwwroot/logdemo.jar</pre>
PS: 因为通过FTP工具显示的文件根路径就是/，并没有/home/显示，所以在Linux环境中，极易忽略home而导致以上错误。
第三步：问题解决，查看日志启动成功
/home/LogFiles/2022_02_19_lw0sdlwk00005J_docker.log (https://lbjavainlinux.scm.chinacloudsites.cn/api/vfs/LogFiles/2022_02_19_lw0sdlwk00005J_docker.log)
2022-02-19T09:11:02.556Z INFO - 8-jre8_210526002747 Pulling from azure-app-service/java
2022-02-19T09:11:02.557Z INFO - Digest: sha256:b26811cc1b99fc7cfa7485d2313da3abbf0f96f742961908ee7da07ef489ddc6
2022-02-19T09:11:02.557Z INFO - Status: Image is up to date for mcr.microsoft.com/azure-app-service/java:8-jre8_210526002747
2022-02-19T09:11:02.565Z INFO - Pull Image successful, Time taken: 0 Minutes and 0 Seconds
2022-02-19T09:11:02.617Z INFO - Starting container for site
2022-02-19T09:11:02.617Z INFO - docker run -d -p 8080:8080 --name lbjavainlinux_0_ffad47c9 -e PORT=8080 -e WEBSITE_SITE_NAME=lbjavainlinux -e WEBSITE_AUTH_ENABLED=False -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_HOSTNAME=lbjavainlinux.chinacloudsites.cn -e WEBSITE_INSTANCE_ID=f902a04a85d38b0fa81789a73bd7f0fd35ab4400956424760d2a2f982ef05b43 mcr.microsoft.com/azure-app-service/java:8-jre8_210526002747 java -jar /home/site/wwwroot/logdemo.jar
2022-02-19T09:11:02.637Z INFO - Logging is not enabled for this container.
Please use https://aka.ms/linux-diagnostics to enable logging to see container logs here.
2022-02-19T09:11:08.645Z INFO - Initiating warmup request to container lbjavainlinux_0_ffad47c9 for site lbjavainlinux
/home/LogFiles/webssh/.log (https://lbjavainlinux.scm.chinacloudsites.cn/api/vfs/LogFiles/webssh/.log)
Ending Log Tail of existing logs ---
Starting Live Log Stream ---
2022-02-19T09:11:08.645Z INFO - Initiating warmup request to container lbjavainlinux_0_ffad47c9 for site lbjavainlinux
2022-02-19 09:11:22.559 INFO 125 --- [main] com.example.App : Starting App v1.0-SNAPSHOT on f60af282340b with PID 125 (/home/site/wwwroot/logdemo.jar started by root in /)
2022-02-19 09:11:23.022 INFO 125 --- [main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@447d90dd: startup date [Sat Feb 19 09:11:23 GMT 2022]; root of context hierarchy
2022-02-19 09:11:29.200 INFO 125 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Overriding bean definition for bean 'beanNameViewResolver': replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration; factoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter; factoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter.class]]
2022-02-19 09:11:32.370 INFO 125 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [class org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$EnhancerBySpringCGLIB$b749a166] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-02-19 09:11:32.721 INFO 125 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'transactionAttributeSource' of type [class org.springframework.transaction.annotation.AnnotationTransactionAttributeSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-02-19 09:11:32.842 INFO 125 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'transactionInterceptor' of type [class org.springframework.transaction.interceptor.TransactionInterceptor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-02-19 09:11:32.903 INFO 125 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.config.internalTransactionAdvisor' of type [class org.springframework.transaction.interceptor.BeanFactoryTransactionAttributeSourceAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-02-19 09:11:37.004 INFO 125 --- [main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 8080 (http)
2022-02-19T09:11:40.611Z INFO - Waiting for response to warmup request for container lbjavainlinux_0_ffad47c9\. Elapsed time = 31.9663615 sec
2022-02-19 09:11:40.594 INFO 125 --- [main] o.apache.catalina.core.StandardService : Starting service Tomcat
2022-02-19 09:11:40.633 INFO 125 --- [main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.0.28
2022-02-19 09:11:41.800 INFO 125 --- [localhost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-02-19 09:11:41.819 INFO 125 --- [localhost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 18816 ms
2022-02-19 09:11:48.263 INFO 125 --- [localhost-startStop-1] o.s.b.c.e.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
2022-02-19 09:11:48.295 INFO 125 --- [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
2022-02-19 09:11:48.304 INFO 125 --- [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2022-02-19 09:11:51.478 INFO 125 --- [main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@447d90dd: startup date [Sat Feb 19 09:11:23 GMT 2022]; root of context hierarchy
2022-02-19 09:11:52.406 INFO 125 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/]}" onto java.lang.String com.example.HelloController.hello()
2022-02-19 09:11:52.412 INFO 125 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/newhello]}" onto java.lang.String com.example.HelloController.hello2()
2022-02-19 09:11:52.422 INFO 125 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest)
2022-02-19 09:11:52.435 INFO 125 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2022-02-19 09:11:52.666 INFO 125 --- [main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2022-02-19 09:11:52.684 INFO 125 --- [main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2022-02-19 09:11:53.066 INFO 125 --- [main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2022-02-19T09:11:55.939Z INFO - Waiting for response to warmup request for container lbjavainlinux_0_ffad47c9\. Elapsed time = 47.2941072 sec
2022-02-19 09:11:55.146 INFO 125 --- [main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2022-02-19 09:11:55.950 INFO 125 --- [main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
2022-02-19 09:11:56.000 INFO 125 --- [main] com.example.App : Started App in 35.854 seconds (JVM running for 40.855)
2022-02-19 09:11:56.002 INFO 125 --- [main] com.example.App : test java logs : info
2022-02-19 09:11:56.010 ERROR 125 --- [main] com.example.App : test java logs : error
2022-02-19 09:11:56.012 WARN 125 --- [main] com.example.App : test java logs : warn
2022-02-19 09:11:56.409 INFO 125 --- [http-nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2022-02-19 09:11:56.413 INFO 125 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2022-02-19 09:11:56.545 INFO 125 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 131 ms
2022-02-19T09:11:57.181Z INFO - Container lbjavainlinux_0_ffad47c9 for site lbjavainlinux initialized successfully and is ready to serve requests.
Java应用启动完成！
image
参考资料
为 Azure 应用服务配置 Java 应用： https://docs.azure.cn/zh-cn/app-service/configure-language-java?pivots=platform-linux#java-se
当在复杂的环境中面临问题，格物之道需：浊而静之徐清，安以动之徐生。 云中，恰是如此!
分类: 【Azure 应用服务】
标签: App Service, Azure Developer, JaveSE 启动Jar包路径问题, 503 Service Temporarily Unavailable, Application Error 错误
