記錄一次 Spring boot 應用排錯過程

  • 2019 年 12 月 6 日
  • 筆記

問題背景

一個spring boot開發的項目，spring boot版本是1.5.7，攜帶的spring版本是4.1.3。開發反饋，突然在本地啟動不起來了，表象特徵就是在本地IDEA上運行時，進程卡住也不退出，應用啟動時加載相關組件的日誌也不輸出。癥狀如下圖：

問題分析

因為沒有有用的日誌信息，所以不能從日誌這個層面上排查問題。但是像這種沒有輸出日誌的話，一般情況下，肯定是程序內部啟動流程卡在什麼地方了，只能通過打印下當前線程堆棧信息了解下。一般情況下，在服務器環境，我們會使用java工具包中的jstack 工具來查看：如jstack pid（應用java進程）。

但是，在IDEA本地開發的話，IDEA內置了一個工具，可以直接查看當前應用的線程上線文信息，如：

注意下面那個箭頭指向的像照相機一樣的圖標，故圖思意，就是打印當前線程快照的的意思。點擊後，就出現了右邊那些線程上下文信息了，可以看到有很多的線程，我們主要關注下main線程，線程狀態確實是waiting的，接着點擊箭頭所指向的main線程，可以看到如下內容：

"main@1" prio=5 tid=0x1 nid=NA waitingjava.lang.Thread.State: WAITINGat sun.misc.Unsafe.park(Unsafe.java:-1)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)at org.springframework.boot.autoconfigure.BackgroundPreinitializer.onApplicationEvent(BackgroundPreinitializer.java:63)at org.springframework.boot.autoconfigure.BackgroundPreinitializer.onApplicationEvent(BackgroundPreinitializer.java:45)at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:158)at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)at org.springframework.boot.context.event.EventPublishingRunListener.finished(EventPublishingRunListener.java:115)at org.springframework.boot.SpringApplicationRunListeners.callFinishedListener(SpringApplicationRunListeners.java:79)at org.springframework.boot.SpringApplicationRunListeners.finished(SpringApplicationRunListeners.java:72)at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:745)at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:134)- locked <0xea6> (a java.util.concurrent.atomic.AtomicBoolean)at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:175)at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:98)at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:64)at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:74)at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:325)at org.springframework.boot.SpringApplication.run(SpringApplication.java:296)at cn.keking.project.customerManagement.KekingCustomerManagement.main(KekingCustomerManagement.java:36)

可以看到是通過CountDownLatch.await()阻塞了線程，接着看下面那行，所在代碼塊如下：

private static final CountDownLatch preinitializationComplete = new CountDownLatch(1);  @Overridepublic void onApplicationEvent(SpringApplicationEvent event) {   if (event instanceof ApplicationEnvironmentPreparedEvent) {      if (preinitializationStarted.compareAndSet(false, true)) {         performPreinitialization();      }   }   if (event instanceof ApplicationReadyEvent || event instanceof ApplicationFailedEvent) {      try {         preinitializationComplete.await();      }      catch (InterruptedException ex) {         Thread.currentThread().interrupt();      }   }}

這是spring boot中的一個安全初始化資源的一個類，代碼所示為監聽SpringApplicationEvent事件，可以肯定的是，它的邏輯執行到了 preinitializationComplete.await();這裡，導致了線程阻塞了。正常情況下，spring會觸發ApplicationEnvironmentPreparedEvent事件完成資源的初始化，這裡先不深究Spring為什麼這麼做，主要通過程序邏輯看下為什麼卡這裡了，在preinitializationComplete.await();所在行打個斷點，看下event對象里的信息，如下：

原來event是一個Spring上下文初始化失敗的異常事件對象，對象里包含了具體的異常信息，如箭頭所指，關鍵異常信息如：

NoSuchMethodError："org.springframework.util.ObjectUtils.unwrapOptional(Ljava/lang/Object;)Ljava/lang/Object;"

假設問題

通過上面的分析，基本定位到Spring boot應用啟動卡住這個表象背後的真實原因了，而且也定位到了異常信息。

出現NoSuchMethodError異常，是因為調用方法的時候，找不到方法了。一般出現在兩個有關聯的jar包，但是版本對不上了，也就是常說的jar版本依賴衝突。查看了下，ObjectUtils是spring-core包里的一個類，當前的4.1.3版本確實沒有這個unwrapOptional方法，spring-core-5.x的版本才新增了這個方法。因為之前的依賴是沒有問題，為什麼現在spring上下文會調用5.x的版本的方法呢？

所以先假設近期有開發在pom.xml里添加了新的的依賴，導致了這個問題。

小心求證

有了找問題的方向就好辦了，因為代碼都是git管理維護的，所以查看下pom.xml文件近期的提交記錄即可，查看後，確實發現了近期對pom.xml有改動，添加了一個依賴：

<dependency>    <groupId>org.springframework</groupId>    <artifactId>spring-context</artifactId>    <version>5.1.6.RELEASE</version></dependency>

這裡還涉及到一點Maven依賴優先級的問題，在pom.xml里直接這樣添加的依賴優先於其他jar中pom.xml依賴的，也就是說，即使spring boot1.5.7自帶了Spring-context.4.1.3，但是這樣指定後，應用最後依賴的還是5.1.6的版本。結合之前的分析，八九不離十了就是因為加了這個依賴導致的問題，spring-context.5.1.6配合spring-core.4.1.3肯定得出問題啊。直接移除這個依賴，然後啟動系統一切正常，日誌打印了Spring加載上線文的信息。

問題總結

定位這個問題的關鍵在於要了解java中線程堆棧的知識，在沒有足夠異常日誌情況下通過線程快照排查問題。在定位到問題後，如NoSuchMethodError這樣的異常，需要平時的經驗積累來假設問題的真實原因，然後在追本溯源驗明問題所在根本原因。找問題本質一定要這種循序漸進的思路。舉例，出現這種問題，如果你直接去搜索引擎搜：「Spring boot應用啟動卡住了」，是搜不出來什麼東西的，但是當你發現了是由於jar衝突。去搜索引擎搜索：

「NoSuchMethodError："org.springframework.util.ObjectUtils.unwrapOptional(Ljava/lang/Object;)Ljava/lang/Object;"」。就會有很多的內容，很容易解決問題。

來源：http://suo.im/55CotD

VirMach 便宜 VPS

QNews

QNews