Replace log4j2 with our own far more efficient logging implementation t…

…urms-im#875

README.md

@@ -99,7 +99,6 @@ Note: The main disadvantage of the current Turms project is that it does not pro
       * During business logic processing, there is no synchronization or lock, only CAS
   * Memory
       * The Turms server allocates heap or direct memory smartly according to its usage to reduce the memory footprint 
-      * If you add `-XX:+AlwaysPreTouch` to the JVM configuration, the Turms server can ensure that it commits all the required heap memory when the server starts, so that no page faults will occur when the Turms server is running to improve efficiency
       * The Turms server refactors parts of MongoDB/Redis client dependencies to ensure that there is no redundant memory allocation in the Turms server, which greatly improves the effective use of memory
   * Cache: The Turms server makes full use of the local memory cache
 ## Subprojects

README_zh.md

@@ -104,7 +104,6 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
      - 业务逻辑处理过程中，无同步加锁操作，只有CAS操作
    - 内存
      - 在划分内存空间时，合理且充分地循环利用堆内存与直接内存
-     - 如果您在JVM配置中添加了`-XX:+AlwaysPreTouch`，即可保证Turms在服务端启动时向系统commit所有需要的堆内存，保证Turms服务端在运作时不会发生缺页异常，以提升运行效率
      - Turms通过重写MongoDB/Redis客户端依赖的部分实现，保证了Turms服务端中无冗余的内存分配，极大地提高了内存的有效使用率
    - 缓存：Turms服务端各功能模块充分利用本地内存缓存
 
@@ -119,7 +118,7 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
 | <span style="white-space:nowrap;">turms-client-kotlin</span> | 同上                                                         |
 | <span style="white-space:nowrap;">turms-client-swift</span>  | 同上                                                         |
 | <span style="white-space:nowrap;">turms-plugin</span>        | 当指定事件（如用户上下线、消息接收与转发等）被触发时，turms-gateway和turms-service会调用对应的自定义插件以方便开发者实现各种各样定制化功能 |
-| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
+| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现的反垃圾机制（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
 | <span style="white-space:nowrap;">turms-plugin-minio</span>  | 基于turms-plugin实现的存储服务插件。用于与MinIO服务端进行交互 |
 | <span style="white-space:nowrap;">turms-data（TODO）</span>  | 尚未发布。基于Flink生态的独立数据分析系统，负责业务数据统计与分析，为turms的管理员统计API与turms-admin运营报表提供底层数据支持 |
 

pom.xml

@@ -122,12 +122,6 @@
             <artifactId>lettuce-core</artifactId>
         </dependency>
 
-        <!-- Logging -->
-        <dependency>
-            <groupId>org.springframework.boot</groupId>
-            <artifactId>spring-boot-starter-log4j2</artifactId>
-        </dependency>
-
         <!-- Miscellaneous -->
         <dependency>
             <groupId>com.github.ben-manes.caffeine</groupId>

turms-docs/src/README.md

@@ -104,7 +104,6 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
      - 业务逻辑处理过程中，无同步加锁操作，只有CAS操作
    - 内存
      - 在划分内存空间时，合理且充分地循环利用堆内存与直接内存
-     - 如果您在JVM配置中添加了`-XX:+AlwaysPreTouch`，即可保证Turms在服务端启动时向系统commit所有需要的堆内存，保证Turms服务端在运作时不会发生缺页异常，以提升运行效率
      - Turms通过重写MongoDB/Redis客户端依赖的部分实现，保证了Turms服务端中无冗余的内存分配，极大地提高了内存的有效使用率
    - 缓存：Turms服务端各功能模块充分利用本地内存缓存
 
@@ -119,7 +118,7 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
 | <span style="white-space:nowrap;">turms-client-kotlin</span> | 同上                                                         |
 | <span style="white-space:nowrap;">turms-client-swift</span>  | 同上                                                         |
 | <span style="white-space:nowrap;">turms-plugin</span>        | 当指定事件（如用户上下线、消息接收与转发等）被触发时，turms-gateway和turms-service会调用对应的自定义插件以方便开发者实现各种各样定制化功能 |
-| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
+| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现的反垃圾机制（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
 | <span style="white-space:nowrap;">turms-plugin-minio</span>  | 基于turms-plugin实现的存储服务插件。用于与MinIO服务端进行交互 |
 | <span style="white-space:nowrap;">turms-data（TODO）</span>  | 尚未发布。基于Flink生态的独立数据分析系统，负责业务数据统计与分析，为turms的管理员统计API与turms-admin运营报表提供底层数据支持 |
 

turms-docs/src/for-developers/observability.md

@@ -135,7 +135,20 @@ Turms与其他常规服务端一样，将可观测性的具体实现分为三类
 
 每条日志都对应着Turms服务端运行时发生的事件，用于追踪系统的运行状态与生成高纬度的统计数据。Turms中的日志分类两大类，即`应用日志`与`业务日志`。应用运行日志本身数量不多，占用空间不大，遵循精与准原则。但为业务分析而设计的客户端API访问日志则不同，它是大部分统计数据的基础数据，是企业的重要资产，因此Turms默认对其进行100%采样，存储消耗巨大。
 
-注意：Turms的所有日志、度量与链路追踪的数据格式设计，都是兼顾“简单快捷，方便快速查询”与“精准采样，方便日志服务分析”设计的，但Turms本身不提供任何日志分析功能。
+注意
+
+* Turms的所有日志、度量与链路追踪的数据格式设计，都是兼顾“简单快捷，方便快速查询”与“精准采样，方便日志服务分析”设计的，但Turms本身不提供任何日志分析功能
+* Turms的日志时间戳与日志切割都是根据UTC时间，而非系统默认时间
+
+### 定制实现原因
+
+1. 第三方Logging实现过于冗余，性能低下且内存占用高
+2. 避免第三方Logging的开发人员由于缺乏安全常识，写出类似[Remote code injection in Log4j](https://github.com/advisories/GHSA-jfh8-c2jp-5v3q)的Critical bug
+3. Turms的日志实现通过“几乎什么功能都没实现”，并且实现了的功能也照着几乎最高性能标准实现（之后我们会避免使用Java低效的`String`与`StringBuilder`，达到更高的性能），因此该实现的吞吐量能比log4j2 async logger高数倍，同时内存开销小数倍
+4. Turms打印日志的过程也非常精简，大概只实现了标准日志库的百分之几的功能，具体包括：
+   * 调用`log`接口
+   * `log`接口内部通过`PooledByteBufAllocator.DEFAULT`分配一块堆外内存，并遍历一遍message，将非占位符直接写入该内存，跳过占位符并写入具体参数，最后将这块内存放到日志处理的MPSC队列中（基于jctools的`MpscUnboundedArrayQueue`）
+   * 日志处理线程检测到有新的日志（即`ByteBuffer`对象）时，会将该堆外内存写入NIO包的`FileChannel`（可以是控制台、也可以是文件）中，该对象在Linux系统下，会最终调用`pwrite`直接将堆外内存写入文件描述符中
 
 ### 不使用JSON格式的原因
 
@@ -197,7 +210,7 @@ turms-service的服务端JVM GC配置为：`-Xlog:gc*,gc+age=trace,safepoint:fil
 示例：
 
 ```spreadsheet
-2021-09-02 07:19:27.219  INFO S wzocsebz 3501287524626242885 Thread-28 : turms|0:0:0:0:0:0:0:1|db612e82-199|2021-09-02T07:30:30.414Z|updateUser|1|{ids=[1], updateUserDTO=UpdateUserDTO[password=******, name=null, intro=null, profileAccess=null, permissionGroupId=null, registrationDate=null, isActive=null]}|TRUE|
+2021-09-02 07:19:27.219  INFO S wzocsebz 3501287524626242885 Thread-28 : turms|0:0:0:0:0:0:0:1|db612e82-199|2021-09-02 07:30:30.414|updateUser|1|{ids=[1], updateUserDTO=UpdateUserDTO[password=******, name=null, intro=null, profileAccess=null, permissionGroupId=null, registrationDate=null, isActive=null]}|TRUE|
 ```
 
 #### 客户端API访问日志
@@ -217,9 +230,9 @@ turms-service的服务端JVM GC配置为：`-Xlog:gc*,gc+age=trace,safepoint:fil
 示例：
 
 ```spreadsheet
-2021-08-17 13:21:10.082  INFO G ocnpinxk 4073578036035627538 gateway-tcp-worker-18-2 : 1669286372|100|DESKTOP|1|0:0:0:0:0:0:0:1|6275734689527119988|CREATE_GROUP_MEMBER_REQUEST|32|2021-08-17T13:21:10.079Z|1201||21|3
-2021-08-17 13:21:10.086  INFO G ocnpinxk 8485909300068121199 gateway-tcp-worker-18-1 : 315622910|101|DESKTOP|1|0:0:0:0:0:0:0:1|8981788720014999664|QUERY_GROUP_JOIN_REQUESTS_REQUEST|17|2021-08-17T13:21:10.082Z|1201||21|4
-2021-08-17 13:21:10.087  INFO G ocnpinxk 195568170846055794  gateway-tcp-worker-18-2 : 1669286372|100|DESKTOP|1|0:0:0:0:0:0:0:1|7875023820838742819|CREATE_GROUP_JOIN_QUESTION_REQUEST|181|2021-08-17T13:21:10.083Z|1201||21|4
+2021-08-17 13:21:10.082  INFO G ocnpinxk 4073578036035627538 gateway-tcp-worker-18-2 : 1669286372|100|DESKTOP|1|0:0:0:0:0:0:0:1|6275734689527119988|CREATE_GROUP_MEMBER_REQUEST|32|2021-08-17 13:21:10.079|1201||21|3
+2021-08-17 13:21:10.086  INFO G ocnpinxk 8485909300068121199 gateway-tcp-worker-18-1 : 315622910|101|DESKTOP|1|0:0:0:0:0:0:0:1|8981788720014999664|QUERY_GROUP_JOIN_REQUESTS_REQUEST|17|2021-08-17 13:21:10.082|1201||21|4
+2021-08-17 13:21:10.087  INFO G ocnpinxk 195568170846055794  gateway-tcp-worker-18-2 : 1669286372|100|DESKTOP|1|0:0:0:0:0:0:0:1|7875023820838742819|CREATE_GROUP_JOIN_QUESTION_REQUEST|181|2021-08-17 13:21:10.083|1201||21|4
 ```
 
 ##### turms-service服务端
@@ -235,9 +248,9 @@ turms-service的服务端JVM GC配置为：`-Xlog:gc*,gc+age=trace,safepoint:fil
 示例：
 
 ```spreadsheet
-2021-08-17 13:25:11.809  INFO S lkumxlpd 1650561895646191481 Thread-13 : 101|DESKTOP|::1|6798130843268792999|QUERY_MESSAGES_REQUEST|28|2021-08-17T13:25:11.807Z|1001||2
-2021-08-17 13:25:11.809  INFO S lkumxlpd 2979813149711907727 Thread-9 : 100|DESKTOP|::1|5095384146247218867|QUERY_GROUP_JOIN_QUESTIONS_REQUEST|17|2021-08-17T13:25:11.807Z|1002||2
-2021-08-17 13:25:11.809  INFO S lkumxlpd 7231219143674352809 ver-worker-14-1 : 101|DESKTOP|::1|358075665001342897|QUERY_SIGNED_GET_URL_REQUEST|40|2021-08-17T13:25:11.809Z|6000||0
+2021-08-17 13:25:11.809  INFO S lkumxlpd 1650561895646191481 Thread-13 : 101|DESKTOP|::1|6798130843268792999|QUERY_MESSAGES_REQUEST|28|2021-08-17 13:25:11.807|1001||2
+2021-08-17 13:25:11.809  INFO S lkumxlpd 2979813149711907727 Thread-9 : 100|DESKTOP|::1|5095384146247218867|QUERY_GROUP_JOIN_QUESTIONS_REQUEST|17|2021-08-17 13:25:11.807|1002||2
+2021-08-17 13:25:11.809  INFO S lkumxlpd 7231219143674352809 ver-worker-14-1 : 101|DESKTOP|::1|358075665001342897|QUERY_SIGNED_GET_URL_REQUEST|40|2021-08-17 13:25:11.809|6000||0
 ```
 
 补充：

turms-docs/src/intro/README.md

@@ -104,7 +104,6 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
      - 业务逻辑处理过程中，无同步加锁操作，只有CAS操作
    - 内存
      - 在划分内存空间时，合理且充分地循环利用堆内存与直接内存
-     - 如果您在JVM配置中添加了`-XX:+AlwaysPreTouch`，即可保证Turms在服务端启动时向系统commit所有需要的堆内存，保证Turms服务端在运作时不会发生缺页异常，以提升运行效率
      - Turms通过重写MongoDB/Redis客户端依赖的部分实现，保证了Turms服务端中无冗余的内存分配，极大地提高了内存的有效使用率
    - 缓存：Turms服务端各功能模块充分利用本地内存缓存
 
@@ -119,7 +118,7 @@ Turms基于读扩散消息模型进行架构设计，对业务数据变化感知
 | <span style="white-space:nowrap;">turms-client-kotlin</span> | 同上                                                         |
 | <span style="white-space:nowrap;">turms-client-swift</span>  | 同上                                                         |
 | <span style="white-space:nowrap;">turms-plugin</span>        | 当指定事件（如用户上下线、消息接收与转发等）被触发时，turms-gateway和turms-service会调用对应的自定义插件以方便开发者实现各种各样定制化功能 |
-| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
+| <span style="white-space:nowrap;">turms-plugin-antispam</span> | 基于双数组Trie的AC自动机算法实现的反垃圾机制（检测的时间复杂度为O(n)，n为目标字符串code points的长度） |
 | <span style="white-space:nowrap;">turms-plugin-minio</span>  | 基于turms-plugin实现的存储服务插件。用于与MinIO服务端进行交互 |
 | <span style="white-space:nowrap;">turms-data（TODO）</span>  | 尚未发布。基于Flink生态的独立数据分析系统，负责业务数据统计与分析，为turms的管理员统计API与turms-admin运营报表提供底层数据支持 |
 

turms-docs/src/intro/redevelopment.md

@@ -95,6 +95,8 @@ git submodule foreach git pull origin master
 
 * 部分依赖库在一些地方会自行Suppress异常，上层应用代码无法感知。由于出问题的时候，底层库代码与上层应用代码在大部分情况下，是跑在不同的栈上的。除非底层依赖库支持全局的异常回调，否则上层应用甚至无法感知异常的发生。对于一些Trivial级别的错误，上层应用感知不到也没关系。但如果是一些上层应用非常关注的异常（如RPC的TCP连接的异常断开），这将是引发整个系统异常与失序的导火索了。
 
+* 部分知名依赖库的开发人员甚至缺乏最基本的安全常识。比如`Log4j`的开发人员竟然添加代码来自动检测预备打印的字符串中是否存在`${jndi}`模式，如果存在则调用对应的JNDI服务，并默认开启该功能。作为专门编写日志依赖库的开发人员竟然如此缺乏安全常识，且还通过了PR review。
+
 另一方面，自研能规避掉上述所有问题，在提高代码可控性的同时，也极大地降低了研发难度与问题排查难度，并提升代码性能与资源利用率。
 
 综上，Turms项目在引用一个类库时，通常不引入抽象封装库（如Spring），而仅引入实现库。对依赖库中需要性能优化或逻辑优化的点，会直接在Turms项目内部进行重构。结合考虑到自研的难易程度与代码可控性，我们在大部分情况下会尽可能选择自研。

turms-gateway/src/main/java/im/turms/gateway/access/common/UserSessionDispatcher.java

@@ -29,13 +29,13 @@
 import im.turms.gateway.service.mediator.ServiceMediator;
 import im.turms.server.common.constant.TurmsStatusCode;
 import im.turms.server.common.dto.CloseReason;
-import im.turms.server.common.logging.RequestLoggingContext;
+import im.turms.server.common.logging.core.logger.LoggerFactory;
 import im.turms.server.common.tracing.TracingCloseableContext;
 import im.turms.server.common.tracing.TracingContext;
+import im.turms.server.common.logging.core.logger.Logger;
 import im.turms.server.common.util.ExceptionUtil;
 import io.netty.buffer.ByteBuf;
 import io.netty.handler.codec.http.websocketx.BinaryWebSocketFrame;
-import lombok.extern.log4j.Log4j2;
 import reactor.core.publisher.Flux;
 import reactor.core.publisher.Mono;
 import reactor.netty.Connection;
@@ -49,9 +49,10 @@
 /**
  * @author James Chen
  */
-@Log4j2
 public abstract class UserSessionDispatcher {
 
+    private static final Logger LOGGER = LoggerFactory.getLogger(UserSessionDispatcher.class);
+
     private final ApiLoggingContext apiLoggingContext;
     protected final ServiceMediator serviceMediator;
     protected final UserRequestDispatcher userRequestDispatcher;
@@ -104,10 +105,10 @@ private Mono<Void> respondWithRequests(Connection connection,
                     requestData.retain();
 
                     // Note that handleRequest() should never return MonoError
-                    RequestLoggingContext loggingContext = new RequestLoggingContext();
+                    TracingContext ctx = new TracingContext();
                     userRequestDispatcher.handleRequest(sessionWrapper, requestData)
                             .onErrorResume(throwable -> {
-                                loggingContext.updateMdc();
+                                ctx.updateThreadContext();
                                 handleNotificationError(throwable, sessionWrapper.getUserSession());
                                 return Mono.empty();
                             })
@@ -118,9 +119,9 @@ private Mono<Void> respondWithRequests(Connection connection,
                                 return Mono.from(outbound);
                             })
                             .onErrorResume(throwable -> handleConnectionError(throwable, sessionWrapper.getConnection(),
-                                    sessionWrapper.getUserSession(), loggingContext.getTracingContext()))
-                            .contextWrite(context -> context.put(RequestLoggingContext.CTX_KEY_NAME, loggingContext))
-                            .doFinally(signal -> loggingContext.clearMdc())
+                                    sessionWrapper.getUserSession(), ctx))
+                            .contextWrite(context -> context.put(TracingContext.CTX_KEY_NAME, ctx))
+                            .doFinally(signal -> ctx.clearThreadContext())
                             .subscribe();
                 })
                 .then()
@@ -175,7 +176,7 @@ private Mono<Void> handleConnectionError(Throwable throwable,
                                              TracingContext tracingContext) {
         if (!ExceptionUtil.isDisconnectedClientError(throwable)) {
             try (TracingCloseableContext ignored = tracingContext.asCloseable()) {
-                log.error("Caught an exception from a connection bound with the session: {}",
+                LOGGER.error("Caught an exception from a connection bound with the session: {}",
                         userSession,
                         throwable);
             }
@@ -191,7 +192,7 @@ private Mono<Void> handleConnectionError(Throwable throwable,
                 .onErrorResume(t -> {
                     // Log because this should be the last error handler here
                     try (TracingCloseableContext ignored = tracingContext.asCloseable()) {
-                        log.error("Caught an exception when setting the local session [{}:{}] offline due to connection error",
+                        LOGGER.error("Caught an exception when setting the local session [{}:{}] offline due to connection error",
                                 userId, deviceType, t);
                     }
                     return Mono.empty();
@@ -205,7 +206,7 @@ private void handleNotificationError(Throwable throwable, @Nullable UserSession
         }
         CloseReason closeReason = CloseReason.get(throwable);
         if (closeReason.isServerError()) {
-            log.error("Failed to send outbound notification to the session: " + userSession, throwable);
+            LOGGER.error("Failed to send outbound notification to the session: " + userSession, throwable);
         }
         Long userId = userSession.getUserId();
         DeviceType deviceType = userSession.getDeviceType();