摘要：當web工程比較大，歷史代碼較多時， 應當使用log4j2框架的能力來修改日志注入問題，而不是按照有些博文里寫的逐個進化參數的方式。
案例故事
某個新系統上線了，小A在其中開發了個簡單的登錄模塊，會在日志里記錄所有登錄成功或者失敗的用戶。
小A對用戶名都做了白名單校驗，不正確的名字，也會用WARN的形式，打印出來做記錄。
像下面這樣：
[2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][WARN][main] [Login:308] username is wrong,userName=tony.dssdff
日志對接了風險審計系統，會定期從日志中審計出那些每天有可疑登錄行為的人，例如那些半夜登錄或者頻繁登錄（不要在意細節，不用審計也能做，只是舉個例子而已）
某天，日志審計系統提示tony登錄過於頻繁且高危操作， 於是把tony的號給封了。
隨后一天又封了N多個無辜的用戶，引發用戶大量不滿。運營部找來問罪，小A拿出下面的日志文件做證據:
[2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][WARN][main] [Login:308] username is wrong,userName=tony.dssdff [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony
然而tony反應說他那天在外面旅游，電腦也放在家中，是有證據的。
這時候小A的老大翻出了請求接口日志，發現那時候有1個請求發來， 接口里的username參數竟然是：
username=tony.dssdff [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony
好家伙，竟然是username里帶了換行，雖然我做了白名單校驗，但是日志里為了記錄這個帶換行的錯誤名，坑了一堆用戶。（因為對方可能是使用rest-api去惡意發送的，所以也繞過了前台頁面的校驗）
小A的公司因此遭遇了巨大損失，小A最終也失業了。
簡單整改方法
小A費勁九牛二虎之力找到一家新公司，接手了一堆舊代碼。他決定提前預防， 給外部輸入的日志參數加上換行處理.
他寫了一個方法如下：
/** * 獲取凈化后的消息，過濾掉換行，避免日志注入 * @param message * @return */ public static String getCleanedMsg(String message) { if (message == null) { return ""; } message = message.replace('\n', '_').replace('\r', '_'); return message; }
並且給自己打日志的地方，補充了這個方法
LOGGER.warn("username is wrong,userName={}", getCleanedMsg(userName));
但是想起來這個系統比較舊，還有好多類似的參數，於是搜索了一下，發現竟然有一千多處帶參數的日志，好多是前輩留給他的坑。
於是他懷着責任心一個一個修改和檢查， 花了一個多月終於把所有外部輸入的參數排查出來並加上getCLeanMsg方法。年末最終因為輸出不夠，背了個最低績效，郁郁寡歡，頭發又掉光了。
log4j2配置統一修改message
小A被換了個項目組，這次決定不再重蹈覆轍，使用別的方式簡化一下。他的項目里日志都是用log4j2打印的，如果能利用框架能力，把日志的換行全部去掉就好了，嚴格保證日志輸出的只有1行。
於是開始認真學習log4j2的官方文檔。他在里面找到了和日志輸出格式有關的位置，如下：https://logging.apache.org/log4j/2.x/manual/layouts.html
他搜索\n或者換行的關鍵字，找到了如下的內容：
文檔里寫得很清楚， 使用%enc{%m}{CRLF}， 即可對這部分進行換行的過濾處理。於是在log4j2.xml的<PatternLayout>改成了如下：
<Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}][%-5p] [%t] [%c{10}#%M:%L] %enc{%m}{CRLF} %n "/> </Console>
測試，最終所有的日志都會只有一行。以前會引發問題的日志也變成了
username=tony.dssdff\r\n[2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony
因此不會被日志系統錯誤解析，同時也省去了一個個排查的風險。
log4j2 修改異常里的mesage
過了一個月，突然日志審計又告警了， 最終排查下來又是誤報。去看了日志，發現長這樣：
[2021-04-17 16:50:35][INFO][main] [Login:308] unknown error happend java.lang.RuntimeException: name,name=%s [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony [2021-04-17 16:50:35][INFO][main] [Login:308] login success,userName=tony at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?] at java.net.SocketInputStream.socketRead(SocketInputStream.java:115) ~[?:?] at java.net.SocketInputStream.read(SocketInputStream.java:168) ~[?:?] at java.net.SocketInputStream.read(SocketInputStream.java:140) ~[?:?] at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:448) ~[?:?]
好家伙，原來是有些地方打印日志時， 順便把未處理過的異常堆棧也打印出來了。異常堆棧的第一行往往是異常名+message， 這里也能被惡意攻擊。
小A翻遍了log4j2文檔，沒有找到能在異常中處理換行的符號，只找到了1個ThrowablePatternConverter， 文檔里告訴他，你可以自定義這個ThrowablePatternConverter，來打印自己想要的異常。
於是他自己編寫了一個UndefineThrowablePatternConvert，在里面重寫了日志堆棧打印的邏輯，
/** * 會對異常做特定編碼處理的格式轉換類 * 使用時，在layout中添加 %eEx即可 * * @since 2021/4/16 */ @Plugin(name = "UndefineThrowablePatternConverter", category = PatternConverter.CATEGORY) // 自己定義的layout鍵值 @ConverterKeys({"uEx"}) public class UndefineThrowablePatternConverter extends ThrowablePatternConverter { /** * 進行過特定編碼處理的ThrowableProxy */ static class EncodeThrowableProxy extends ThrowableProxy { public EncodeThrowableProxy(Throwable throwable) { super(throwable); } // 將\r和\n進行編碼，避免日志注入 @Override public String getMessage() { String encodeMessage = super.getMessage().replaceAll("\r", "\\\\r").replaceAll("\n", "\\\\n"); return encodeMessage; } } protected UndefineThrowablePatternConverter(Configuration config, String[] options) { super("UndefineThrowable", "throwable", options, config); } // log4j2中使用反射調用newInstance靜態方法進行構造，因此必須要實現這個方法。 public static UndefineThrowablePatternConverter newInstance(final Configuration config, final String[] options) { return new UndefineThrowablePatternConverter(config, options); } @Override public void format(final LogEvent event, final StringBuilder toAppendTo) { Throwable throwable = event.getThrown(); if (throwable == null) { return; } // 使用自定義的EncodeThrowableProxy，里面重寫了ThrowableProxy的getMessage方法 EncodeThrowableProxy proxy = new EncodeThrowableProxy(throwable); // 添加到toAppendTo proxy.formatExtendedStackTraceTo(toAppendTo, options.getIgnorePackages(), options.getTextRenderer(), getSuffix(event), options.getSeparator()); } }
並且在PatternLayout中添加%uEx， 就會使用這里的format去生成堆棧字符串。
總結
- 白名單無法避免日志注入問題，因為有時候我們可能會記錄那些有錯誤的輸入參數。
- 當web工程比較大，歷史代碼較多時， 應當使用log4j2框架的能力來修改日志注入問題，而不是按照有些博文里寫的逐個進化參數的方式
- 異常堆棧里的message同樣有日志注入風險，如果工程里支持打印堆棧，則最好也統一處理一下。
本文分享自華為雲社區《Java雲服務開發安全問題解析——日志注入，並沒那么簡單》，原文作者：breakDraw。