微信公众号：[海涛技术漫谈]
欢迎关注公众号，一起在程序员的道路上成长。有任何问题或建议，欢迎公众号留言
遇到的问题
本周在工作中，遇到个莫名其妙的问题，描述如下：工作内容主要是对notebook
进行定制化开发，拦截用户的执行代码，记录到日志中，但是代码包含中文时，每次记录的日志对应部分都是unicode
码，但是debug
发现日志中的信息明明是中文。
问题表现如下：
# notebook中执行 print("中国")
2019-11-24 20:36:53,238 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '\u4e2d\u56fd', 'end_time': '2019-11-24 20:36:53'}
相关python
代码示例：
def _insert_output_log(self, msg_json, msg_type):
log_content = {}
# 日志信息字典
log_content['msg_id'] = msg_json['header']['msg_id']
parent_session_id = msg_json['parent_header']['session']
log_content['parent_msg_id'] = msg_json['parent_header']['msg_id']
log_content['output'] = output
log_content['msg_type'] = msg_type
log_content['end_time'] = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime())
# 记录日志
logger = get_aduit_output_log()
logger.warning(json.dumps(log_content))
# 系统自带日志,记录到stdout
self.log.warning(‘output log: %r’, json.dumps(log_content))
# log 工具类中相关方法
def get_aduit_output_log():
logger_name = "aduit_output_log"
logger = logging.getLogger(logger_name)
logger.setLevel(logging.WARN)
# use TimedRotatingFileHandler
log_path = ADUIT_PATH_PREFIX + "/notebook_code_output"
handler = logging.handlers.TimedRotatingFileHandler(log_path, 'midnight', 1, 0)
handler.setLevel(logging.WARN)
handler.suffix = "%Y%m%d.log"
# create formatter
formatter = logging.Formatter("%(asctime)s %(levelname)s {0} {1} %(message)s".format("code_output", "mlp_notebook"))
handler.setFormatter(formatter)
logger.addHandler(handler)
return logger
初步排查解决
首先，估计大家和我一样，最先想到的是相关文件是否在首行指定了编码为utf-8
，一顿修改后，打包发布，但是然并卵，问题依然存在。
然后，添加日志打印，发现，数据在log_content
中，还是正常的中文，但是dumps
后就变成了unicode
编码，猜测是json将字典转为字符串时，会进行编码，于是本地起了个python shell
验证猜想。
# python 为 3.7.3
>>> a = {'code': '中国'}
>>> a
{'code': '中国'}
>>> b = json.dumps(a)
>>> b
'{"code": "\\u4e2d\\u56fd"}'
>>> logging.warning(a)
WARNING:root:{'code': '中国'}
>>> logging.warning(json.dumps(a))
WARNING:root:{"code": "\u4e2d\u56fd"}
果然如此，进一步看json.dumps()
的实现，发现确实会encode
，进一步证实了猜测，于是将记录日志的代码改为：
# 前 logger.warning(json.dumps(log_content))
logger.warning(log_content)
旧的去，新的来
本以为到这里，问题就得到解决了，但是发布后，发现改动地方抛了个新的问题，依然是编码问题，头大:
UnicodeEncodeError: 'ascii' codec can't encode characters in position 91-94: ordinal not in range(128)
Google
后，发现问题处在记录日志工具类中，创建日志handler
的时候未指定编码，默认会使用ascii
码去进行encode
，无法encode
中文，所以报错，于是修改如下：
# 入参的最后添加encoding，指定utf8
handler = logging.handlers.TimedRotatingFileHandler(log_path, 'midnight', 1, 0, encoding="utf8")
居然还有个问题
发布后，发现日志中的中文已经恢复正常，于是多测试了几个中文，竟然发现新的问题：日志出现了重复
，print
三个词，打印了6条日志，买3送3，牛啤。
# notebook中依次执行 print("你好") print("麻辣") print("香锅")
2019-11-24 20:36:53,238 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '你好', 'end_time': '2019-11-24 20:36:53'}
2019-11-24 20:36:55,38 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '麻辣', 'end_time': '2019-11-24 20:36:53'}
2019-11-24 20:36:55,38 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '麻辣', 'end_time': '2019-11-24 20:36:55'}
2019-11-24 20:36:57,2 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '香锅', 'end_time': '2019-11-24 20:36:55'}
2019-11-24 20:36:57,2 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '香锅', 'end_time': '2019-11-24 20:36:57'}
2019-11-24 20:36:57,2 WARNING {'msg_id': '76cb595f-1e88-4128-b454-6ad6f68f7573', 'parent_msg_id': 'f85a20c6f0b843d19577e2a3299eb3bf', 'output': '香锅', 'end_time': '2019-11-24 20:36:57'}
查看代码，没发现相关代码有出现循环。因为notebook
的服务端和执行代码的内核是通过mq进行通信的，所以理所当然的猜测可能是notebook
，通过消息的重复发送来实现一定程度的容错。
于是，在记录日志的之前，使用全局唯一的消息的msg_id
作为key
做了个标记。但是发布后，发现问题并没有得到解决。
而且，仔细观察，发现两点问题：1.
为什么就我自己定义的日志出现了重复，观察同样位置的系统自带日志并没有重复。2.
重复的日志精确到毫秒级的时间已知。
于是，怀疑网上找的这个logging
的实现有问题，google
了下问题，发现，原来是实现每次get_aduit_output_log()
时吗，会向当前logger
中添加handler
，这样一来，logger
关联的hander
不断递增，所以记录的日志就会发现重复，这也和日志的重复次数是每次递增1，于是，代码改为，每次添加handler
是先判断，everything is done!!!
def get_aduit_output_log():
logger_name = "aduit_output_log"
logger = logging.getLogger(logger_name)
logger.setLevel(logging.WARN)
# use TimedRotatingFileHandler
log_path = ADUIT_PATH_PREFIX + "/notebook_code_output"
# 添加前，先判断是否已经绑定handler
if not logger.handlers:
handler = logging.handlers.TimedRotatingFileHandler(log_path, 'midnight', 1, 0, encoding="utf8")
handler.setLevel(logging.WARN)
handler.suffix = "%Y%m%d.log"
# create formatter
formatter = logging.Formatter(
"%(asctime)s %(levelname)s {0} {1} %(message)s".format("code_output", "mlp_notebook"))
handler.setFormatter(formatter)
logger.addHandler(handler)
return logger
