企业应用日志开发浅析

 

企业应用中，在什么情况下要记日志？

 

支持型日志

 

一般这个问题意味着“什么情况”是由审计需求驱动的，有人想要知道在某一段时间内谁干了什么事情，结果如何。最好呢，就能有如下的结果：

 

2012-04-01 13:14:20 [admin] login [success]
2012-04-01 13:15:32 [admin] place order [customer=Hippo, product=1231] [success, trackingId=1239]
2012-04-01 13:20:05 [admin] logout [success]

那么在哪里记录日志呢？一般来说，一个用户发起的请求会提交给Controller(Spring framework)或是系统暴露的RemoteFacade，它们收到请求后完成输入解析并转交给对应的ApplicationService完成请求的处理。

我一般在Controller/RemoteFacade中记录日志，因为：

1. 在Controller中，我们可以从Session中获取到用户信息，这解决了是“谁”的问题。

2.Controller/RemoteFacade调用ApplicationService后可以根据返回值得到结果（一般还要捕获ApplicationService抛出的异常），这样我们知道“做了什么”以及“结果如何”。

 

现在我们有了一个基本的方案，那么如何验证呢？因为这样的日志要不不会有人来看，只要有人来看，它就必须清晰无误。最简单的就是通过手工查看日志文件来验证，但是这个方案很笨拙且无法有效的回归测试。通过不同级别的测试配合或许能简化这项工作。一方面，我们可以通过单元测试来检验日志记录的内容和时机是否正确；另一方面，再通过组件测试来检验日志的基础设施配置是否正确。

单元测试方面的重点是利用模拟对象技术（Mock objects），通过预期检验来测试日志内容和时机是否正确。

 

LoginControllerUnitTests.java

private LoginController target;
private LoginService loginService = context.mock(LoginService.class);
private Logger logger = context.mock(Logger.class);

@Before
public void init() {
    target = new LoginController(loginService, logger);
}

注意这里的logger不像平时由controller对象自己实例化，而是通过构造函数传入。

 

LoginControllerUnitTests.java

 

@Test
public void forwardsToWelcomeViewIfLoginSuccess() throws Exception {

    final String username = "admin"; 
    final String password = "123456";
    final String expectViewName = "welcome";
    final String logText = "[" + username + "] login [success]";
    MockHttpServletRequest request = new MockHttpServletRequest();
    MockHttpServletResponse response = new MockHttpServletResponse();
    LoginCommand command = aLoginCommandWith(username, password);

    context.checking(new Expectations() {
        {
	    oneOf(loginService).login(username, password);

	    oneOf(logger).info(logText);
	}
    });

    ModelAndView actual = target.login(request, response, command);

    assertEquals(expectViewName, actual.getViewName());
}

请注意预期定义的代码oneOf(logger).info(logText);，这里通过校验了当controller的login()方法被调用后，一定会调用一次logger的info()方法，且参数为预期的日志内容。

 

 

再来关注组件测试，在这个测试中我们要验证系统中的日志基础结构设置是否正确（比如，log4j.properties是否位置正确等等）。

Log4jSmokeTests.java

 

        @Test
	public void writesTextToSpecifiedFile() throws Exception {
		final String fileName = "D:/log/logging.log";
		clean(fileName);
	
		String expectedText = "It's just ok";
		log(expectedText);
	
		String actualText = load(fileName);
		assertTrue(actualText.contains(expectedText));
	}

 

 

 

诊断型日志

除了上述情况下，我们还会写一些“诊断型”的日志，来帮助我们了解系统的运行情况，例如有时候我们会在程序的某个执行路径中加上System.out.println(“Access here.”)，这样的代码基本上可以理解为将日志信息打印至控制台。一般来说，这些信息的输出级别比较低，一般是debug/trace，在生产环境一般是不输出的，但是在开发环境/测试环境或是在生产环境调查问题时会打开，比如下面代码中的logger.debug()

LoginController.java

 

	public ModelAndView logout2(HttpServletRequest request,
			HttpServletResponse response, LogoutCommand command) {
		String username = command.getUsername();
		logger.debug(username + " wants to logout.");
		loginService.logout(username);
		logger.info(the(username) + " logout [success]");
		return new ModelAndView(VIEW_LOGIN);
	}

 

 

但这使得测试代码变得不那么清晰了，因为诊断型代码一般是由开发者自己定义的，并没有需求来驱动，自然也不需要去测试，但是为了测试logout2()，我们不得不为其多定义一个预期，这可不是我们想要的

LoginControllerUnitTests.java

 

        @Test
	public void forwardsToLoginViewIfLogout2Success() throws Exception {
		
		target.setProductionModel(true);
		
		final String username = "admin";
		final String expectViewName = "login";
		final String logText = "[" + username + "] logout [success]";

		MockHttpServletRequest request = new MockHttpServletRequest();
		MockHttpServletResponse response = new MockHttpServletResponse();
		LogoutCommand command = aLogoutCommandWith(username);

		context.checking(new Expectations() {
			{
				allowing(logger).debug("Access here.");
				
				oneOf(loginService).logout(username);

				oneOf(logger).info(logText);
			}
		});

		ModelAndView actual = target.logout(request, response, command);

		assertEquals(expectViewName, actual.getViewName());
	}

对于这种情况，我们就不必为了测试而将logger传入了，在Controller对象中实例化一个logger即可。

 

 

LoginController.java

 

public class LoginController extends MultiActionController {
	private static final String VIEW_WELCOME = "welcome";
	private static final String VIEW_ERROR = "error";
	private static final String VIEW_LOGIN = "login";
	private LoginService loginService;
	private Logger logger;
	private boolean productionModel = false;
	private final Logger loggerForDiagnoses = LoggerFactory
			.getLogger(this.getClass());

public ModelAndView logout3(HttpServletRequest request,
			HttpServletResponse response, LogoutCommand command) {
		String username = command.getUsername();
		loggerForDiagnoses.debug(username + " wants to logout.");
		loginService.logout(username);
		logger.info(the(username) + " logout [success]");
		return new ModelAndView(VIEW_LOGIN);
	}

由于代码中loggerForDiagnoses并不是模拟对象，因此我们不需要为其定义预期

 

工作在事务中

 

在处理某些业务请求时，我们需要使用到事务技术，来保持数据库的一致性。但是往往我们的框架只能支持对于一个数据源（大多数情况是数据库）的事务。这对使用文件系统的日志实现来说，可能存在一些陷阱。对于支持型日志，有可能出现用户请求的操作由于异常被回滚，但是支持日志却被保留的情况。

 

PlaceOrderService.java

 

@Transactional
	public String placeOrderFor(String customer) {
		// some customer handling codes
		// order has been placed
		String trackingId = A_NEW_TRACKING_ID;
		logger.info(TEXT_WHEN_ORDER_PLACED + trackingId);
		throw new IllegalArgumentException("Yes, we do this on purpose.");
	}

 

 将日志输出级别调整为debug(以便看到Spring framework输出的日志)后，可以看到日志被打印出来后，开始回滚

 

(PlaceOrderService.java:17) - Order has been placed, trackingId=111
2012-10-20 11:51:36,921 DEBUG [main] (AbstractPlatformTransactionManager.java:821) - Initiating transaction rollback
2012-10-20 11:51:36,921 DEBUG [main] (DataSourceTransactionManager.java:273) - Rolling back JDBC transaction on Connection ……
2012-10-20 11:51:36,921 DEBUG [main] (DataSourceTransactionManager.java:314) - Releasing JDBC Connection……

 

如果遇到这种情况，可能要仔细考虑一下，这里我们到底是需要支持型日志还是诊断型日志。一般来说，审计需求驱动的支持型日志不应遇到这样的情况，否则不就“莫须有”了吗？值得一提的是，如果在一个事务中调用了事务传播范围外的API（比如一个Web Service），则没有问题，因为无论本次事务是提交还是回滚，该API都不受影响。

 

抽象级别

 

 

建议使用slf4j作为编码时的API，原因如下：

1.目前，开源的日志实现有多种，比如log4j、logback、commons-logging，slf4j提供了一个统一的API，如果要替换实现，并需要修改应用中的日志输出代码

2.slf4j的API设计，使得开发人员可以减少错误。比如常见的，在输出error日志时：

catch(Exception e) {

    logger.error(e);

}

这样输出的日志缺少信息，比如缺少堆栈，而slf4j的api不支持只传入object，必须是String， Object，这样减少了出错的概率（编译器检查）

 

另外，我们发现直接模拟logger，始终无法消除重复（主要是对记录内容的拼接），这可能在提示我们日志的内容拼接和其他逻辑并不在同一个抽象级别上。在一些技术书籍中不约而同地提到了应该通知记录日志，而不是直接记录日志的概念。

 

 

OrderAdminController.java

 

public void updateCustomer(MockHttpServletRequest request,
			MockHttpServletResponse response) {
		final String trackingId = request.getParameter("trackingId");
		final String customer = request.getParameter("customer");

		modifyOrderService.updateCustomer(trackingId, customer);

		loggingSupport.notifyCustomerUpdated(trackingId, customer);

	}

 在这个方案中，我们使用loggingSupport来通知记录日志，这样至少有以下两个好处：

 

1.拼接日志文本的代码不见了

2.未必一定要使用文件系统来记录日志，在接口背后隐藏的可以是其他方案

使用这个方案我们可以简化OrderAdminController（或任何通知记录的对象）的测试，在这个测试中我们不必再准备预期的日志文本。同时我们可以将loggSupport的测试设计为实际读取日志文件（如果采用文件实现的话）的集成测试

当然，使用这个方案的话，也有一些问题，比如，我们在日志中就看不到通知记录日志的对象的文件名和行号了：

 

2012-10-21 14:00:50,078 INFO [main] (Slf4jOrderAdminLoggingSupport.java:14) - [121]'s customer was changed as [Hippoom]

 

 

噢 对了 附加中的有几个测试用例中，我用File.delete()不能删除文件是啥原因，有人知道不？

 

参考资料：

 

Growing Object-Oriented Software, Guided by Tests 

Steve Freeman, Nat Pryce