文地址: https://www.twilio.com/blog/guide-node-js-logging
原文作者: DOMINIK KUNDEL
翻译作者: icepy
译文出处: https://github.com/lightningminers/article/issues/39
当你开始使用 JavaScript 做开发时,你可能学习到的第一件事情就是如何使用 console.log 将内容打印到控制台。如果你搜索如何调试 JavaScript,你会发现数百个博客文章和 StackOverflow 的文章都指向简单的 console.log 。因为这是一种常见的做法,我们甚至可以使用 no-console 这样的规则来确保生产环境不会留下日志。但是,如果我们真的想要记录这些信息呢?
在这篇博文中,我们将介绍你想要记录信息的各种情况,Node.js 中的 console.log 和 console.error 之间的区别是什么,以及如何在不使用户控制台混乱的情况下在库中发送日志记录。
console.log(`Let's go!`);
虽然你可以在浏览器和 Node.js 环境中使用 console.log 和 console.error,但在 Node.js 中使用时一定要记住一件重要的事情。
将如下代码写入到 index.js 文件中,并在 Node.js 环境里执行:
console.log('Hello there'); console.error('Bye bye');
如图:
虽然这两个输出看起来可能一样,但系统实际上对它的处理方式有不同。如果你检查一下 console section of the Node.js documentation 你会发现 console.log 使用 stdout 打印而 console.error 则使用 stderr。
每一个进程都有三个可以使用的默认 streams,它们是 stdin ,stdout 和 stderr。 stdin 可以处理进程的输入,例如按下按钮或重定向输出。stdout 可以用于处理进程的输出。最后 stderr 则用于错误消息。如果你想了解 stderr 为什么存在以及何时使用它,可以访问:When to use STDERR instead of STDOUT。
简而言之,这允许我们使用重定向 > 和管道 | 运算符来处理与应用程序的实际结果分开的错误和诊断信息。而 > 允许我们将命令的输出重定向到文件,2> 允许我们将 stderr 的输出重定向到文件。我们来看一个例子,它会将 Hello there 重定向输出到 hello.log ,Bye bye 重定向输出到 error.log。:
$ node index.js > hello.log 2> error.log
如图:
现在我们已经了解了日志记录的基础技术,那么让我们来谈谈你可能想要记录某些内容的不同例子,通常这些例子都属于以下类别之一:
我们将跳过本博文中的前两篇文章,并将重点介绍基于Node.js的三篇文章。
Your Server Application Logs
你希望在服务器上记录内容的原因可能有多种,例如:记录传入的请求,统计信息,有多少404用户正在访问,另外你也想知道什么时候出错以及为什么。
初始化项目:
$ npm init -y $ npm install express
让我们设置一个带有中间件的服务器,只需要 console.log 为你的请求提供打印:
const express=require("express"); const PORT=process.env.PORT || 3000; const app=express(); app.use((req,res,next)=> { console.log('%o', req); next(); }); app.get('/', (req,res)=> { res.send('hello world'); }); app.listen(PORT, ()=> { console.log('Server running on port %d', PORT); });
这里我们使用 console.log('%o', req); 来记录整个对象。
当你运行 node index.js 并访问 http://localhost:3000 你会注意到打印的很多信息并不是我们需要的。
如果将起更改为 console.log('%s',req) 我们也不会获取太多的信息。
我们可以编写自己的日志功能,只打印我们关心的信息。但让我们先退一步,谈谈我们通常关心的事情。虽然这些信息经常成为我们关注的焦点,但实际上我们可能需要其他信息,例如:
另外,既然我们知道打印最后都会落到 stdout 和 stderr 上,那么我们可能想要不同日志级别的记录以及过滤它的能力。
我们可以通过访问流程的各个部分并编写一堆 JavaScript 代码来获取上述的信息,但 npm 生态已经给我们提供了各种各样的库来使用,例如:
我个人喜欢 pino,因为它速度快,生态全。那么,让我们来看一看 pino 是如何帮助我们记录日志的。
$ npm install pino express-pino-logger const express=require("express"); const pino=require("pino"); const expressPino=require("express-pino-logger"); const logger=pino({ level: process.env.LOG_LEVEL || 'info'}); const expressLogger=expressPino({ logger }); const PORT=process.env.PORT || 3000; const app=express(); app.use(expressLogger); app.get('/', (req,res)=> { logger.debug('Calling res.send') res.send('hello world'); }); app.listen(PORT, ()=> { logger.info('Server running on port %d', PORT); });
运行 node index.js 并访问 http://localhost:3000 你可以看到一行一行的 JSON 输出:
如果你检查此 JSON ,你会看到前面提到的时间戳。你可能还注意到了我们 logger.debug 语句并未打印,那是因为我们必须更改默认日志级别才能使其可见,试试 LOG_LEVEL=debug node index.js 来调整日志级别。
在此之前我们还需要解决一下日志信息的可读性,pino 遵循了一个理念,就是为了性能,你应该通过管道将输出的处理移动到单独的进程中,你可以去查看一下文档,了解其中 pino 的错误为什么不会写入 stderr。
让我们使用 pino-pretty 工具来查看更易读的日志:
$ npm install --save-dev pino-pretty $ LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty
运行 LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty 并访问 http://localhost:3000。
如图:
另外还有各种各样的库可以来美化你的日志,甚至你可以使用 pino-colada 用 emojis 来显示它们。这些对于你的本地开发非常有用,在运行到生产服务器之后,你可能希望将日志的管道转移到另外一个管道,使用 > 将它们写入硬盘以便稍后处理它们。
比如:
$ LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty | > success.log 2> s_error.log
既然我们研究了如何有效的为服务器应用程序编写日志,那么为什么不能将它用在我们的某些库中呢?问题是,你的库可能希望记录用于调试的内容,但实际上不应该让使用者的应用程序变得混乱。相反,如果需要调试某些东西,使用者应该能够启动日志。你的库默认情况下不会处理这些,并将输入输出的操作留给使用者。
express 就是一个很好的例子。
在 express 框架下有很多事情要做,在调试应用程序时,你可能希望了解一下框架的内容。如果我们查询文档,你会注意到你可以在命令行的前面加上 DEBUG=express:* 来启动。
$ DEBUG=express:* node index.js
如图:
如果你没有启动调试日志,则不会看到任何这样的日志输出。这是通过一个叫 debug 的包来完成的。
$ npm install debug
让我们创建一个新的文件 random-id.js 来使用它:
const debug=require("debug"); const log=debug("mylib:randomid"); log("Library loaded"); function getRandomId() { log('Computing random ID'); const outcome=Math.random() .toString(36) .substr(2); log('Random ID is "%s"', outcome); return outcome; } module.exports={ getRandomId };
这里会创建一个带有命名空间为 mylib:randomid 的 debug 记录器,然后会将这两种消息记录上去。
我们可以在 index.js 文件中引用它:
const express=require("express"); const pino=require("pino"); const expressPino=require("express-pino-logger"); const randomId=require("./random-id"); const logger=pino({ level: process.env.LOG_LEVEL || 'info'}); const expressLogger=expressPino({ logger }); const PORT=process.env.PORT || 3000; const app=express(); app.use(expressLogger); app.get('/', (req,res)=> { logger.debug('Calling res.send') const id=randomId.getRandomId(); res.send(`hello world [${id}]`); }); app.listen(PORT, ()=> { logger.info('Server running on port %d', PORT); });
然后使用 DEBUG=mylib:randomid node index.js 来重新运行你的 index.js 文件,如图:
有意思的是,如果你的库使用者想把这些调试信息集成到自己的 pino 日志中去,那么他们可以使用一个叫 pino-debug 的库来正确的格式化这些日志。
$ npm install pino-debug
pino-debug 在我们第一次使用之前需要初始化一次 debug,最简单的方法就是在启动之前使用 Node.js 的 -r 或 --require 命令来初始化。
$ DEBUG=mylib:randomid node -r pino-debug index.js | ./node_modules/.bin/pino-colada
如图:
我将在这篇博文中介绍最后一个案例,针对 CLI 的日志记录。我的理念是将逻辑日志和你的 CLI 输出分开。对于任何逻辑日志来说,你应该使用类似 debug 这样的包。这样你或其他人就可以重写逻辑,而不受 CLI 的约束。
一种情况是你的 CLI 在持续集成的系统中被使用,因此你可能希望删除各种花里胡哨的输出。有些 CI 系统设置了一个被称为 CI 的环境标志。如果你想更安全的检查自己是否在 CI 系统中,你可以使用 is-ci 这个库。
有些库例如 chalk 已经为你检查了 CI 并帮你删除了颜色。
$ npm install chalk const chalk=require("chalk"); console.log('%s Hi there', chalk.cyan('INFO'));
运行 node cli.js,如图:
当你运行 CI=true node cli.js,如图:
你要记住的是另外一个场景 stdout 能否在终端模式中运行。如果是这种情况,我们可以使用类似 boxen的东西来显示所有漂流的输出。但如果不是,则可能会将输出重定向到文件或输出到其他地方。
你可以使用 isTTY 来检查 stdout,stdin,stderr 是否在终端模式。
如:
process.stdout.isTTY
根据 Node.js 的启动方式,这个三个的值可能不同。你可以在文档中找到更多关于它的信息。
让我们看看 process.stdout.isTTY 在不同情况下的变化:
const chalk=require("chalk"); console.log(process.stdout.isTTY); console.log('%s Hi there', chalk.cyan('INFO'));
然后运行 node index.js ,如图:
之后运行相同的内容,但将其输出重定向到一个文件中,这次你会看见它会打印一个 undefined 后面跟着一个简单的无色消息。
这是因为 stdout 关闭了终端模式下 stdout 的重定向。
chalk 使用了 supports-color ,它会在引擎里检查各个流的 isTTY。
像 chalk 这样的库已经帮你处理了这些行为,但在开发 CLI 的过程中还是要注意,在 CI 模式下运行或输出被重定向的问题。
例如,你可以在终端以一种漂亮的方式来排列数据,如果 isTTY 为 undefined 时,则切换到更容易解析的方式上。
在 JavaScript 中使用 console.log 是非常快的,但当你将代码部署到生产环境时,你应该要考虑更多关于记录的内容。
本文仅仅是介绍了各种方法和可用的日志记录解决方案,它不包含你需要知道的一切。
因此我建议你多看一看你喜欢的开源项目,看看它们是如何解决日志记录问题以及它们所使用的工具。
一节我们完成了基本的设置,应该说,至少目前对我来说,现在的功能已经基本够用了。
于是我计划从这篇文章开始,我就不再使用Word进行编辑了,用我这个私人日记软件来编辑,实际验证下是否实用。
如下图,这是我之前教程的编写模式:
之前也交待过,在word文档中编辑,只要是包含了图片的,复制后再粘贴到头条都没办法成功,还需要把图片一个个另外粘贴过去才行。如果是遇到gif动图,从word复制只能复制静态的截图,还得再次复制原文件才能粘贴到头条的编辑器中,操作起来比较麻烦。
于是我就在我的程序中尝试复制粘贴,发现跟word是一样的效果。这对我来说是不实用的,需要对它进行改造。
要解决这个问题,首先要分析下为什么会造成这种情况。我们使用的文本编辑控件是RichTextBox,这个默认是rtf格式的,跟word是一样的。我们把带图文的内容粘贴到word文档中,图片就是可以正常显示的。这就说明我们Ctrl+C的内容是rtf格式的,而不是通过浏览器粘贴能够识别出来的格式。那么浏览器能够识别的格式是不是每个浏览器特有的呢?于是我尝试在FireFox中复制图片和文字,粘贴到用Chrome打开的头条编辑器,发现图片是可以显示的,上述的猜测可以排除了。那么这个格式究竟是怎样的呢?我需要在程序中截获一下粘贴的内容。在ContentManagerForm.cs文件中,添加键盘截获事件,截获Ctrl+V时的内容:
我们发现,如果从浏览器上按Ctrl+C,到我们的软件中按Ctrl+V,用DataFormats.Html做参数可以取到值,值的内容大概是这样:
前面红线部分相当于信息头,定义了一些参数,后面从<div>开始就是我们刚刚复制的内容了。我原封不动地将这些内容再写回到剪贴板中,然后在浏览器中按Ctrl+V,浏览器也能够正常显示了。
这样我们基本上就明白了,想要跟浏览器正常通讯,需要两步:第一步是要将rtf格式转换为html格式,第二步是要将html再转换成浏览器能够识别的格式到剪贴板。
一般这种格式转换需要的工作量都比较大,自己从头开发不大现实,需要网上找找看是否有现成的类库。对比了几家,找到了一个rftpipe的,而且是mit授权的。于是从Nuget获取安装,使用起来很容易:
Encoding.RegisterProvider(CodePagesEncodingProvider.Instance);
string html=RtfPipe.Rtf.ToHtml(tbxMainBody.Rtf);
如此两行代码就实现了第一步的转换。
同样也是先网上查资料,找到了一个ClipboardHelper的类,同样也是mit授权的。把代码加入到工程,然后在ContentManagerForm中增加一个专门用于复制成html格式到剪贴板的按钮:
按钮处理代码:
private void btnCopyAsHtml_Click(object sender, EventArgs e)
{
Encoding.RegisterProvider(CodePagesEncodingProvider.Instance);
string html=RtfPipe.Rtf.ToHtml(tbxMainBody.Rtf);
ClipboardHelper.CopyToClipboard(html, "");
}
在使用了类库的基础上,三行代码就完成了我想要的功能。
功能演示:
以上解决了从软件复制到头条的问题。
还有一种场景,就是把浏览器当成来源,从浏览器复制到软件的功能。如果是纯文本RichEdit编辑器自带就支持,如果是图文混排的,就需要从html到rtf的转换,我找了一下相关的类库,貌似没有类似rftpipe这种免费且直接支持字符转换的库,很多都是通过文档来转换,而且还是收费的。好不容易找到一个符合要求的,结果这个项目比较老,是在Framework下开发的,不支持.netcore。
鉴于找到合适的库有点困难,随后仔细分析了下需求,其实这种从浏览器图文混排复制到软件的场景对我来说意义不大,通篇复制是不大可能的,关键位置复制文字做摘抄,真的有特别需要的图片,单张截图就好,所以这个功能暂时搁置吧。
这个小项目伴着教程做到了24节,终于有了一点实际作用了:)
----------------------------------------------------
本教程尽量保证2天一更,项目源码已作为开源项目加入到Gitee,代码内容会随教程实时更新,大家有兴趣的话可以关注我,以获得最及时的更新。私信:
私人日记 可以获取Gitee的链接;
sqlitestudio 可以获取sqlitestudio的链接;
菜鸟 可以获取菜鸟教程链接;
QQ群 可以获取教程交流Q群号;
大家阅读过程中有哪些看不懂或未尽兴的地方,可以在评论区留言,我会先记下来在后续的教程中找机会再说。
教程有帮助的话请大家帮忙关注、转发、扩散,能不能开专栏还需要你们的支持!
前看到网上很多是基于切面类Aspect去实现了,在切面类中定义before after around等逻辑以及要拦截等方法。本文利用注解实现了一套可以扩展等日志记录模块。
@Target(ElementType.METHOD) @Retention(RetentionPolicy.RUNTIME) @Documented public abstract @interface RequiredLogInterceptor { boolean required() default true; String targetGenerator() default ""; OperateType operateType() default OperateType.GET; }
requried:注解是否生效
targetGenerator: 每个模块记录等内容不同,入口参数不同,所以需要个性化定制日志等记录内容,每个模块的日志生成有自己定义的generator类,并且重写generateContent方法。
operateType:当前方法是增加,删除,还是修改
public abstract class ContentGerator { public static String SPLIT="/"; public static String CONTENT_SPLIT=","; public static String VALUE_SPLIT=":"; abstract List<UserOperateLog> generateContent(Object returnValue, Object[] args, OperateType operateType); }
本模块主要是后置通知,主要逻辑如下:
1.拦截方法,判断是否有注解loginterceptor
2. 如果有判断是否执行成功,成功则记录log,失败不记录
3. 获取注解中配置的generator类,利用反射调用generateContent方法,生成个性化日志内容
5.在日志中添加其他公共属性,比如用户id,创建时间等等。所有个性化定制的日志信息都是在generator类中产生。
public class LogAfterInterceptor implements AfterReturningAdvice { @Autowired private LogService logService; @Override public void afterReturning(Object returnValue, Method method, Object[] args, Object target) throws Throwable { RequiredLogInterceptor requiredLogInterceptor=AnnotationUtils.findAnnotation(method, RequiredLogInterceptor.class); if (requiredLogInterceptor !=null) { if(returnValue!=null&&returnValue instanceof Response){ Response response=(Response)returnValue; String code=response.getCode(); String code200=MegCodeEnums.ResponseCodeEnum.C200.getCode(); String code201=MegCodeEnums.ResponseCodeEnum.C201.getCode(); if (!Strings.isNullOrEmpty(code)&&!code.equalsIgnoreCase(code200)&&!code.equalsIgnoreCase(code201)){ return; } } String targetGeneratorName=requiredLogInterceptor.targetGenerator(); OperateType operateType=requiredLogInterceptor.operateType(); Class targetGeneratorclass=Class.forName("com.puhui.flowplatform.manage.log."+targetGeneratorName); Method executeMethod=targetGeneratorclass.getMethod("generateContent",Object.class,Object[].class,OperateType.class); ContentGerator targetGeneratorBean=(ContentGerator)SpringContextHolder.getBean(targetGeneratorclass); List<UserOperateLog> userOperateLogList=(List<UserOperateLog>)executeMethod.invoke(targetGeneratorBean,returnValue,args,operateType); if(CollectionUtils.isNotEmpty(userOperateLogList)){ userOperateLogList.forEach(userOperateLog -> { userOperateLog.setCreateTime(new Date()); //token long userId=0L; if (args.length>0&&args[0] instanceof String){ userId=CommonUtils.getManageCurUserId(args[0].toString()); } userOperateLog.setUserId(userId); }); logService.batchInsertLog(userOperateLogList); } } } }
继承统一的ContentGenerator类,便于共享一些常量。根据当前操作类型,生成对应的日志内容就可以了。如果需要新增模块, 先定义自己的日志generator类,然后添加注解到对应模块就可以。
@Service public class ContentGeneratorForRoleMgt extends ContentGerator { @Autowired private MenuService menuService; private String generateMenus(VoRole voRole){ List<Menus> menusList=voRole.getMenusList(); StringBuffer stringBuffer=new StringBuffer(); if (CollectionUtils.isNotEmpty(menusList)){ menusList.forEach(menus -> { Long menuId=menus.getId(); Menus menusTemp=menuService.queryMenuByMenuId(menuId); stringBuffer.append(menusTemp.getDisplayTitle()+CONTENT_SPLIT); }); stringBuffer.deleteCharAt(stringBuffer.length() - 1); } return stringBuffer.toString(); } @Override public List<UserOperateLog> generateContent(Object returnValue, Object[] args, OperateType operateType) { { List<UserOperateLog> userOperateLogList=new ArrayList<>(); UserOperateLog userOperateLog=new UserOperateLog(); if (operateType==OperateType.ADD||operateType==OperateType.UPDATE){ VoRole voRole=(VoRole)args[1]; String menus=generateMenus(voRole); userOperateLog.setOperateContent("角色名称"+VALUE_SPLIT+voRole.getDisplayName()+SPLIT+"权限"+VALUE_SPLIT+menus); userOperateLog.setOperateType(operateType==OperateType.ADD?LogOperateTypeEnum.ADD_ROLE.getCode():LogOperateTypeEnum.UPDATE_ROLE.getCode()); } if (operateType==OperateType.DELETE){ if(returnValue!=null){ Response response=(Response) returnValue; String roleName=response.getData().toString(); userOperateLog.setOperateContent(roleName); userOperateLog.setOperateType(LogOperateTypeEnum.DELETE_ROLE.getCode()); } } userOperateLogList.add(userOperateLog); return userOperateLogList; } } }
@PutMapping(value="roles/{roleId}") @RequiredLogInterceptor(targetGenerator="ContentGeneratorForRoleMgt",operateType=OperateType.UPDATE) @ApiOperation(value="修改角色", httpMethod="PUT", response=Response.class, notes="修改角色") public Response<Object> updateRole(@RequestHeader String token,@RequestBody VoRole voRole, @PathVariable("roleId") String roleId) { LOGGER.info("updateRole入参:{}", JSONObject.toJSONString(voRole));
public class SpringMvcConfig extends WebMvcConfigurerAdapter { @Override public void configureMessageConverters(List<HttpMessageConverter<?>> converters) { super.configureMessageConverters(converters); // 初始化转换器 FastJsonHttpMessageConverter fastConvert=new FastJsonHttpMessageConverter(); // 初始化一个转换器配置 FastJsonConfig fastJsonConfig=new FastJsonConfig(); fastJsonConfig.setSerializerFeatures(SerializerFeature.PrettyFormat); // 将配置设置给转换器并添加到HttpMessageConverter转换器列表中 fastConvert.setFastJsonConfig(fastJsonConfig); converters.add(fastConvert); } @Override public void addResourceHandlers(ResourceHandlerRegistry registry) { registry.addResourceHandler("/swagger-ui.html").addResourceLocations( ResourceUtils.CLASSPATH_URL_PREFIX + "/META-INF/resources/"); registry.addResourceHandler("/static/**").addResourceLocations(ResourceUtils.CLASSPATH_URL_PREFIX + "/static/", ResourceUtils.CLASSPATH_URL_PREFIX + "/dist/static/"); registry.addResourceHandler("/page/**").addResourceLocations(ResourceUtils.CLASSPATH_URL_PREFIX + "/dist/"); super.addResourceHandlers(registry); } @Bean public ViewResolver viewResolver() { FreeMarkerViewResolver resolver=new FreeMarkerViewResolver(); resolver.setCache(true); resolver.setPrefix(ResourceUtils.CLASSPATH_URL_PREFIX + "templates/"); resolver.setSuffix(".ftl"); resolver.setContentType("text/html; charset=UTF-8"); return resolver; } // 创建Advice或Advisor @Bean public BeforeAdvice beforeControllerInterceptor() { return new BeforeControllerInterceptor(); } @Bean public AfterAdvice logAfterInterceptor() { return new LogAfterInterceptor(); } // 创建Advice或Advisor @Bean public BeforeAdvice logBeforeInterceptor() { return new LogBeforeInterceptor(); } // 使用BeanNameAutoProxyCreator来创建代理 @Bean public BeanNameAutoProxyCreator beanAutoProxyCreator() { BeanNameAutoProxyCreator beanNameAutoProxyCreator=new BeanNameAutoProxyCreator(); beanNameAutoProxyCreator.setProxyTargetClass(true); // 设置要创建代理的那些Bean的名字 beanNameAutoProxyCreator.setBeanNames("*Controller"); // // 设置拦截链名字(这些拦截器是有先后顺序的) beanNameAutoProxyCreator.setInterceptorNames("logAfterInterceptor"); return beanNameAutoProxyCreator; } @Bean public BeanNameAutoProxyCreator beanBeforeAutoProxyCreator() { BeanNameAutoProxyCreator beanNameAutoProxyCreator=new BeanNameAutoProxyCreator(); beanNameAutoProxyCreator.setProxyTargetClass(true); // 设置要创建代理的那些Bean的名字 beanNameAutoProxyCreator.setBeanNames("*Controller"); // 设置拦截链名字(这些拦截器是有先后顺序的) beanNameAutoProxyCreator.setInterceptorNames("beforeControllerInterceptor"); beanNameAutoProxyCreator.setInterceptorNames("logBeforeInterceptor");
本来实现都代码版本中,所有都日志生成代码都在后置拦截器中,并且根据当前执行都方法都classname和methodname去判断当前都方法,出现很多if 判断,且method name都不一样,有的是addXXX,有的是createXXX,显然设计不合理。后来重新进行了设计,有什么不足,希望大家可以指出。
*请认真填写需求信息,我们会在24小时内与您取得联系。