记一次由Python的__file__导致的“bug”

引子

最近在参与一个Python项目，在其中写Python代码时碰到个很奇怪的现象，执行一个打开日志功能的Python脚本，日志文件有时在Python脚本的同目录创建，有时在项目的log目录中创建，鼓捣了好一会才搞清楚原因，其实并不是代码bug，而是执行Python脚本的姿势错了，追根溯源的debug过程很有意思，遂记录一下。

场景还原

项目工程位于centos，Python3.6.8

为了简化与保密，假设项目工程根目录是/..x/，则日志目录是/..x/log，而我的Python脚本在/..x/scheduler中，为了还原场景，在/..x/scheduler中新建了一个test.py，导入了公共的日志模块，代码如下：

import xxxx # 关于日志的模块，其中已经定义好了LOG_DIR='/..x/log'

if __name__ == '__main__':
    log_add_default_logger(__file__, LOG_DIR)
    log_info("llll")

调用log_info函数就可以直接往日志中写一行

log_add_default_logger()是公共日志库提供的接口，一般情况下（项目开发者所希望的），日志文件的绝对路径名是/..x/log/test.py.20200520.log，观察了一下，/..x/log中有很多类似于这种命名的文件（先提示一下，后缀.20200520.log是在log_info内部某函数添加的，获取当前系统的日期，所以与log_add_default_logger无关）

我用 vscode remote 连接了 centos ，用 vscode 打开test.py文件，在编辑器区域单击鼠标右键，点击"Run Python File in Terminal"，可以直接运行test.py脚本，这种“快速运行”
的方式用起来很爽，其效果等同于：

[root@VM /..x/scheduler]$ /usr/bin/python3 /..x/scheduler/test.py

现在应该写入日志文件了，猜猜log_info("llll")中的llll输出在哪？

选项1：/..x/scheduler/test.py.20200520.log
选项2：/..x/log/test.py.20200520.log

答案是选项1，我第一次也是懵的，为啥别人的日志文件都乖乖输出在/..x/log目录中，而我的日志文件输出在了同目录（/..x/scheduler）？

查看/..x/scheduler/test.py.20200520.log的内容：

[2020-05-20 20:36:39,042][9677][MainThread][INFO][log.py:494][test.py:<module>:16][/..x/scheduler/test.py] : llll

唔......看来得看看log_add_default_logger内部做了啥

在 vscode 项目中ctrl+鼠标左键单击log_add_default_logger(__file__, LOG_DIR)层层 dive into，发现了这行代码：

# 某个函数内
filename = os.path.join(log_dir, log_id) # log_id就是传入的__file__

看来还挺简单的，就是用Python os模块自带的join函数，把路径与文件名组合起来，最后就形成了绝对路径filename，那接下来就调试一下，首先修改一下test.py：

import xxxx # 关于日志的模块，其中已经定义好了LOG_DIR='/..x/log'

if __name__ == '__main__':
    log_add_default_logger(__file__, LOG_DIR)
    print("__file__: " + __file__)
    print("LOG_DIR: " + LOG_DIR)
    print("os.path.join(LOG_DIR, __file__): " + os.path.join(LOG_DIR, __file__))
    log_info("llll")

继续在vscode中“快速运行”，terminal输出如下：

[root@VM /..x/scheduler]$ /usr/bin/python3 /..x/scheduler/test.py
__file__: /..x/scheduler/test.py
LOG_DIR: /..x/log
os.path.join(LOG_DIR, __file__): /..x/scheduler/test.py

看到第三行输出了吗，组合起来之后不是/..x/log/test.py，而是/..x/scheduler/test.py，看来罪魁祸首是这个os.path.join()函数？

想到这，我想起centos有两个Python版本，一个是3.6.8，一个是3.7.2，但两个版本对于这个场景无甚差别，看来不是Python版本的原因，也就不是os.path.join()的原因，/..x/log与/..x/scheduler/test.py进行join的结果就是/..x/scheduler/test.py没错

于是Google，查到这篇文章：https://blog.csdn.net/cjh6311882/article/details/22078347，这是由于__file__输出绝对路径所导致的！

保持test.py不变，不使用vscode的“快速运行”了，老老实实在terminal手动执行脚本：

[root@VM /..x/scheduler]$ python3 test.py # python3 等同于 /usr/bin/python3
__file__: test.py
LOG_DIR: /..x/log
os.path.join(LOG_DIR, __file__): /..x/log/test.py

BINGO! 看来是执行Python脚本的方式错误，不能用绝对路径调用，查看日志文件，果然在/..x/log/中！

[2020-05-20 21:16:01,302][17384][MainThread][INFO][log.py:494][test.py:<module>:16][test.py] : llll

注意到日志文件中的输出，文件名是[test.py]，回头看看错误姿势的日志文件内容，文件名是[/..x/scheduler/test.py]，它们俩不同是因为__file__不同，至此，这次debug过程前因后果都说清楚了

布置作业

位于/..x/scheduler中的脚本以后会由作业系统周期性调用，假设现在让你用Linux中的crontab模拟一下，你是聪明的，你知道要怎么编写crontab才能准确地让日志文件输出到目录/..x/log中吗？

（提示：* * * * * python3 /..x/scheduler/test.py会让日志文件输出到目录/..x/scheduler中

欢迎留言讨论 :)

记一次由Python的file导致的“bug”

记一次由Python的file导致的“bug”

引子

场景还原

布置作业