如何理解Java的异常以及如何将异常记录到日中
分类: HowTo ◆ 标签: #IoT Hub #java ◆ 发布于: 2025-02-16 18:47:54
最近遇到一个问题：使用Azure IoT Java SDK发送物联网的云到设备(C2D)消息一个应用，上周突然发现整个系统中的C2D消息发送都不正常了，业务部门也反馈没有消费到C2D的消息，要尽快缓解这个问题。
使用Azure Portal查询了相应的指标，发现C2D消息的发送指标在问题发生时，发送消息总数为0。检查应用系统日志没有发现任何的异常日志被记录到。请Azure技术支持加入排查，Azure技术支持排除了Azure平台引发问题的可能性。使用Demo测试代码也发现发送C2D消息成功，证明平台确实没有问题。
为了快速的缓解这个问题，将应用系统重启，重启后发现这个问题立即缓解了。再观察了一段时间，问题又重现了，检查应用系统的日志，发现系统日志仍然是没有记录到异常，不过分析了应用日志，从日志中可以观察到部分日志记录确实和之前不太一样，不明白为什么没有记录到异常，考虑到该应用系统是基于：SpringBoot + Log4j2用于记录日志，猜测是不是由于默认的日志级别过滤掉了异常日志。检查默认的日志级别配置是Error, 为了记录到更多的日志信息，尝试将日志级别更改为'Information', 然后重启应用，缓解了问题，继续观察。
大约观察了几天发现该问题又重现了，但是系统中仍然没有记录任何日志，决定再次将日志级别更改， 更改为'Trace'级别，重启应用，缓解问题。过了几天该问题又再次重现了，这一次日志中记录了详细的异常堆栈，根据这个异常堆栈定位到了应用系统中的代码中有一个方法因为三方的系统服务报了空指针异常，由于该空指针异常没有处理，JVM最终将该异常交给了默认的UncatchExceptionHandler处理，抛出异常并终止了该线程，找到了原因，缓解很快，只需要在该代码中添加异常处理的代码，该问题就没有再次发生。
但是上述这个排查和定位过程带来一些疑问：为什么要将日志级别调整到Trace级别，日志系统中才能记录到这个没有被处理的异常？是用户代码问题，还是采用了Azure IoT Java SDK的问题？
我们梳理了发送C2D消息的源代码，根据异常我们发现该异常是发生在一个callback方法中，该方法用于处理发送C2D消息成功之后的返回结果，关于如何定义这个方法的样例代码可以参考如下代码：
//先定义一个call back函数，该函数用在发送`C2D`消息之后，用于处理返回的结果，这里还有一个原因是因为用了异步的模式，需要callback方法处理
final CountDownLatch messagesSentLatch = new CountDownLatch(numberOfMessagesToSend);
Consumer<SendResult> sendResultCallback = sendResult ->
{
//为了重现问题，我们这里手动丢出一个空指针异常：
throw new NullPointerException();
if (sendResult.wasSentSuccessfully())
{
System.out.println("Successfully sent message with correlation id " + sendResult.getCorrelationId());
numberOfMessagesSentSuccessfully++;
}
else
{
IotHubException messageException = sendResult.getException();
if (messageException instanceof IotHubNotFoundException)
{
System.out.println("Failed to send message with correlation id " + sendResult.getCorrelationId() + " because the device it was sent to does not exist");
}
else if (messageException instanceof IotHubDeviceMaximumQueueDepthExceededException)
{
System.out.println("Failed to send message with correlation id " + sendResult.getCorrelationId() + " because the device it was sent to has a full queue of cloud to device messages already");
}
else if (messageException instanceof IotHubMessageTooLargeException)
{
System.out.println("Failed to send message with correlation id " + sendResult.getCorrelationId() + " because the message was too large");
}
else
{
System.out.println("Encountered an IoT hub level error while sending events " + messageException.getMessage());
}
numberOfMessagesFailedToSend++;
}
messagesSentLatch.countDown();
};
上述是定义的一个callback函数, 并且为了重现问题，主动的抛出了一个空指针异常。
然后继续发送的代码：
while (messageCount < numberOfMessagesToSend)
{
Message messageToSend = new Message(String.valueOf(messageCount));
boolean messageSent = false;
while (!messageSent)
{
try
{
messagingClient.sendAsync(deviceId, messageToSend, sendResultCallback, null);
messageCount++;
messageSent = true;
}
catch (IllegalStateException e)
{
System.out.println("Client was closed when attempting to send a message. Re-opening the client and trying again");
if (!openMessagingClientWithRetry(messagingClient))
{
// exit the sample, but close the connection in the finally block first
return;
}
}
}
}
主要的引入callback函数是这行代码: messagingClient.sendAsync(deviceId, messageToSend, sendResultCallback, null);
为了简便，我们这里省去了很多代码，包括创建MessageClient以及设置选项等参数，完整的代码，您可以参考连接：https://github.com/Azure/azure-iot-service-sdk-java/blob/a2b7342347f3bfb4913dc439dbe73bab76e89d02/service/iot-service-samples/messaging-client-performance-sample/src/main/java/samples/com/microsoft/azure/sdk/iot/MessagingClientPerformanceSample.java
我们使用了上述的异常之后，在控制台应用上测试发现，该Demo代码会直接在控制台上抛出异常，这是由于我们在callback方法：sendResultCallback 中没有添加任何处理异常的代码，那么按照理论上来说，最后这个异常会被抛到JVM默认的UncatchExceptionHandler来处理， 所以这个和Azure IoT Java SDK没有直接联系。
应用系统的异常只有在Trace日志级别才被写入日志文件
问题是应用系统没有抛出异常，而是将异常记录到了日志系统里，并且只有在日志系统的级别设置为Trace级别，才在日志中显示了该异常。考虑到该应用系统是由SpringBoot框架开发的，而且SpringBoot提供设置全局异常的处理的部分，检查了全局异常发现在全局异常里对于没有处理的异常确实是使用了Log.Trace()来处理这部分异常，因此也能解释了为什么要设置Trace级别的才能在日志中显示完整的异常堆栈。
虽然上述的案例可以很完整的解释，但是随之带来问题：到底该如何理解Java的异常？Java的内部到底是如何处理异常的？假如我们仅仅定义一个简单的Java应用，这个Java应用只有一个Main方法，该Main方法里抛出一个异常，那么JVM是如何处理这个异常的呢？
JVM如何处理异常？
仔细研究了一下文档， 可以通过如下的回答来解释：
用户自己写的
Java应用中Main方法不是真正的程序入口
可能大多数的教材上或者文档上都有提及，用户编写Java应用，它的主要入口就是公共类提供的一个public static void Main(Strings[] args) 方法。而实际上，或者说严格意义上来讲，这个Main方法并不是主要的入口，而是当你运行Java应用的时候，使用java执行命令时，它会预先启动一个JVM, jvm启动之后执行必要的初始化，装载必要的类文件，最后才开始寻找您定义的Main方法，然后从这个方法开始执行用户的代码，在java应用运行的生命周期中，始终有一个jvm在监控和控制整个系统的运行。
异常是一个对象
异常一定是一个对象，所谓的抛出异常是指创建一个异常的实例，然后将这个异常交给异常处理器的过程，就叫抛出异常。
异常对象是谁创建的？
对于内置的异常，当错误发生时JVM会创建这些异常实例，如果是用户自定义的异常，那么由用户明确的创建他们，并抛出，例如：
throw new UserDefinedException();
异常是在哪里创建的？
异常实在错误发生的代码那里开始创建的，可以类比Java中也有一个类似于C语言中的goto语句，这个语句由于抛出并寻找异常处理器。
异常是如何被抛给指定的异常处理器的，如果没有找到合适的异常处理器会怎么办？
当执行线程中异常发生了之后，JVM注意到该代码处，并由JVM在这个代码处生成一个异常，暂停该线程的执行，同时搜索能够处理该异常的异常处理器，所谓的异常处理器也就是类似try...catch这样的语句，对比异常实例和处理器中的类型是否匹配，如果匹配，那么异常对象就交由该异常处理器处理，类似于C语言中的goto语句直接goto到这个异常处理器处继续运行。
如果JVM一直没有找到该异常匹配的异常处理器，那么会将该异常发送给runtime的DefaultUncatchExceptionHandler, 该默认异常处理器会做两件事：
向
System.err标准错误打印该异常Stack退出执行线程，终止应用运行。
以上可以明确的看到异常的基本处理过程，需要明白类似于Java以及.Net这类托管语言，基本的设计原理是大致是差不多的理念，因此异常处理这个部分也是类似的。
如何使用日志记录异常
我们前面看到一个异常如果不被处理，最终会由默认的DefaultUnCatchExceptionHandler直接向System.err 标准错误打印该内容，并终止应用，而实际的应用中，我们不希望由默认的异常处理器来处理异常，我们希望能够将异常记录到日志中去。
关于这个部分，Java SE提供通用的日志处理框架，自从java 8之后，可以默认使用logger.log(LOG.Level, ExcepitonObject), 直接记录异常，或者使用相应的日志框架，例如log4j2, 这个工具可以完整的记录异常的所有信息到日志中。
参考文档：
https://stackoverflow.com/questions/68333290/how-does-exception-handling-work-internally-in-java
https://softwareengineering.stackexchange.com/questions/257174/how-does-the-jvm-handle-an-exception-thrown-by-the-main-method