51工具盒子

依楼听风雨
笑看云卷云舒,淡观潮起潮落

查看详细日志、MySQL之二进制文件

查看详细日志、MySQL之二进制文件

查看详细日志

网站提示无法访问了,先使用 systemctl status xxx 查看软件日志记录,然后发现两个软件都是指向了数据库

systemctl status xxx 这个命令查询的日志记录不全只剩下了最后一部分几条记录,也容易不理解 只知道有错误了

● xxx1.service - xxx1
   Loaded: loaded (/usr/lib/systemd/system/xxx1.service; enabled; vendor preset: disabled)
   Active: failed (Result: start-limit) since Fri 2024-09-27 01:47:19 CST; 14h ago
 Main PID: 4864 (code=exited, status=1/FAILURE)
`Sep 27 01:47:18 anwen systemd[1]: Unit xxx1.service entered failed state.
Sep 27 01:47:18 anwen systemd[1]: xxx1.service failed.
Sep 27 01:47:19 anwen systemd[1]: xxx1.service holdoff time over, scheduling restart.
Sep 27 01:47:19 anwen systemd[1]: Stopped xxx1.
Sep 27 01:47:19 anwen systemd[1]: start request repeated too quickly for xxx1.service
Sep 27 01:47:19 anwen systemd[1]: Failed to start xxx1.
Sep 27 01:47:19 anwen systemd[1]: Unit xxx1.service entered failed state.
Sep 27 01:47:19 anwen systemd[1]: xxx1.service failed.`

● xxx2.service - Xxx2 Service
   Loaded: loaded (/etc/systemd/system/xxx2.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2024-09-27 01:47:20 CST; 20h ago
 Main PID: 3615 (code=exited, status=1/FAILURE)

Sep 27 16:14:02 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:02 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:02 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:03 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:03 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:03 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:04 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:05 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:06 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Sep 27 16:14:06 anwen systemd[1]: [/etc/systemd/system/xxx2.service:8] Failed to parse service restart specifier, ignoring: unless-stopped
Hint: Some lines were ellipsized, use -l to show in full.

虽然第二个无法查看具体的,用另一个命令查看指定日期内的日志

journalctl -u {服务名} --since "2024-09-26" --until "2024-09-27"

运行发现...好尴尬...我确实搭建好后没去用过,暂时没用而已...嘿嘿

-- Logs begin at Fri 2024-09-27 01:46:58 CST, end at Fri 2024-09-27 22:40:01 CST. --

好吧,既然无法查询,就换一个命令查看最近100条日志吧...反正只要最后的一部分就行,目前应用停止后还没启动一直在停止状态,也不用担心日志被刷新很多

journalctl -u {服务名} -n 100

使用新命令查询详细日志

Sep 27 01:47:20 anwen xxx2[3615]: time="2024-09-27T01:47:20+08:00" level=info msg="load config success from file: /opt/xxx2/config.yaml"
Sep 27 01:47:20 anwen xxx2[3615]: time="2024-09-27T01:47:20+08:00" level=info msg="restore config success"
Sep 27 01:47:20 anwen xxx2[3615]: time="2024-09-27T01:47:20+08:00" level=info msg="load config from env with prefix: xxx2_"
Sep 27 01:47:20 anwen xxx2[3615]: time="2024-09-27T01:47:20+08:00" level=info msg="load config success from env"
Sep 27 01:47:20 anwen xxx2[3615]: time="2024-09-27T01:47:20+08:00" level=info msg="log: enable log to stdout and file: /opt/xxx2/log/log.log"
Sep 27 01:47:20 anwen xxx2[3615]: time=2024-09-27 01:47:20 level=info msg=mysql database tcp: 127.0.0.1:3306
Sep 27 01:47:20 anwen xxx2[3615]: time=2024-09-27 01:47:20 level=info msg=github.com/xxx2-org/xxx2/internal/bootstrap/db.go:37
Sep 27 01:47:20 anwen xxx2[3615]: [error] failed to initialize database, got error dial tcp 127.0.0.1:3306: connect: connection refused
Sep 27 01:47:20 anwen xxx2[3615]: time=2024-09-27 01:47:20 level=fatal msg=failed to connect database: dial tcp 127.0.0.1:3306: connect: connection refused
Sep 27 01:47:20 anwen systemd[1]: xxx2.service: main process exited, code=exited, status=1/FAILURE
Sep 27 01:47:20 anwen systemd[1]: Unit xxx2.service entered failed state.
Sep 27 01:47:20 anwen systemd[1]: xxx2.service failed.

看到最终指向了 failed to connect database: dial tcp 127.0.0.1:3306: connect: connection refused ,连不上3306端口号(数据库端口)

其实可以更简单

直接去看两个软件自带的日志记录

  • 我开始就是先使用 systemctl status xxx 看运行状态,看到停止了,看到两个软件的时间就前后相差1秒,我就直接去看软件自带记录了

xxx1自带日志记录

FATA[2024-09-27 01:47:14] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused 
FATA[2024-09-27 01:47:15] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused 
FATA[2024-09-27 01:47:17] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused 
FATA[2024-09-27 01:47:18] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused 
FATA[2024-09-27 01:47:18] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused 

xxx2自带日志记录

time="2024-09-27T01:47:20+08:00" level=info msg="log: enable log to stdout and file: /opt/xxx2/log/log.log"
time=2024-09-27 01:47:20 level=info msg=mysql database tcp: 127.0.0.1:3306
time=2024-09-27 01:47:20 level=info msg=github.com/xxx2-org/xxx2/internal/bootstrap/db.go:37
[error] failed to initialize database, got error dial tcp 127.0.0.1:3306: connect: connection refused
time=2024-09-27 01:47:20 level=fatal msg=failed to connect database: dial tcp 127.0.0.1:3306: connect: connection refused

诺,简单粗暴吧...都直接指向了连接不上 3306 端口号

(后来通过 查询最近100条日志命令 发现 xxx1 其它重试了5次启动,然后5次还是不行才彻底停止,我说日志怎么是5条记录)

Sep 27 01:47:12 anwen systemd[1]: Started xxx1.
Sep 27 01:47:15 anwen systemd[1]: Stopped xxx1.

Sep 27 01:47:15 anwen systemd\[1\]: Started xxx1.
Sep 27 01:47:17 anwen systemd\[1\]: Stopped xxx1.


Sep 27 01:47:17 anwen systemd\[1\]: Started xxx1.
Sep 27 01:47:18 anwen systemd\[1\]: Stopped xxx1.


Sep 27 01:47:18 anwen systemd\[1\]: Started xxx1.
Sep 27 01:47:18 anwen systemd\[1\]: Stopped xxx1.


Sep 27 01:47:18 anwen systemd\[1\]: Started xxx1.
Sep 27 01:47:19 anwen systemd\[1\]: Stopped xxx1.

`Sep 27 01:47:19 anwen systemd[1]: start request repeated too quickly for xxx1.service
Sep 27 01:47:19 anwen systemd[1]: Failed to start xxx1.
Sep 27 01:47:19 anwen systemd[1]: Unit xxx1.service entered failed state.
Sep 27 01:47:19 anwen systemd[1]: xxx1.service failed.`

后来通过查询原来是因为短时间内一直重启导致服务启动请求重复过快,导致系统限制了其重启,这是一个保护机制,防止服务持续失败...

MySQL二进制日志查询

通过上述日志知道了错误信息是由数据库引起的,就想看看数据库在当时的时间节点发生了什么...通过一顿折腾找了好几个查看日志的位置

终于在第三位置找到了有可能存储了当时发生了什么的日志,那就是MySQL二进制日志

具体作用通过温馨提示描述:Mysql二进制日志是记录当前的操作日志,可用于数据恢复,数据备份。(我也不太懂,也是第一次接触这个感兴趣的可以自己了解一下)

如何开启二进制日志:在 MySQL 配置文件(通常是 my.cnfmy.ini)中,检查是否启用了二进制日志。你应该看到类似以下的配置:

[mysqld]
log-bin=mysql-bin

如果你开启了可以看看具体有几个二进制命令文件,步骤如下命令

mysql -u {数据库用户名} -p {数据库密码}

登录好后输入 SHOW BINARY LOGS; 可以看到列表,但是看不到那个文件是那个时间的,不过最新的记录在最后一个肯定是有的

mysql> SHOW BINARY LOGS;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       177 |
| mysql-bin.000002 |       437 |
| mysql-bin.000003 |       685 |
| mysql-bin.000004 |       177 |
| mysql-bin.000005 |       946 |
| mysql-bin.000006 |    395937 |
| mysql-bin.000007 |       177 |
| mysql-bin.000008 |  13045489 |
| mysql-bin.000009 |    197233 |
+------------------+-----------+
9 rows in set (0.00 sec)

不过如果想知道时间也是简单的,可以找到文件目录,如果找不到可以用命令搜索(一般就在MySQL目录下的data文件夹)

如果你知道数据目录,可以使用指定文件夹搜索

find /path/to/datadir -name 'mysql-bin.*'

如果数据文件夹都不知道在哪儿,可以使用全局搜索命令(可能比较慢)

find / -name 'mysql-bin.*' 2>/dev/null
[root@anwen ~]# find / -name 'mysql-bin.*' 2>/dev/null
/www/server/data/mysql-bin.000001
/www/server/data/mysql-bin.000002
/www/server/data/mysql-bin.000003
/www/server/data/mysql-bin.000004
/www/server/data/mysql-bin.000005
/www/server/data/mysql-bin.000006
/www/server/data/mysql-bin.000007
/www/server/data/mysql-bin.000008
/www/server/data/mysql-bin.000009
/www/server/data/mysql-bin.index

搜索到了我们进入 cd /www/server/data 目录,然后看到目录中文件太多了,可以使用 参数查询 mysql-bin.* 这样就只列出指定文件名了

[root@anwen data]# cd /www/server/data
[root@anwen data]# ls -l mysql-bin.*
-rw-r----- 1 mysql mysql      177 Sep 20 08:55 mysql-bin.000001
-rw-r----- 1 mysql mysql      437 Sep 20 08:55 mysql-bin.000002
-rw-r----- 1 mysql mysql      685 Sep 20 08:55 mysql-bin.000003
-rw-r----- 1 mysql mysql      177 Sep 20 08:55 mysql-bin.000004
-rw-r----- 1 mysql mysql      946 Sep 20 08:55 mysql-bin.000005
-rw-r----- 1 mysql mysql   395937 Sep 20 16:33 mysql-bin.000006
-rw-r----- 1 mysql mysql      177 Sep 20 16:33 mysql-bin.000007
-rw-r----- 1 mysql mysql 13045489 Sep 27 01:47 mysql-bin.000008
-rw-r----- 1 mysql mysql   152659 Sep 27 23:27 mysql-bin.000009
-rw-r----- 1 mysql mysql      171 Sep 27 01:47 mysql-bin.index

能看到列表中出现了时间,尝试着查看最后一个.000009文件,使用命令查询指定时段内的日志

mysqlbinlog --start-datetime="2024-09-27 01:45:00" --stop-datetime="2024-09-27 01:50:00" /www/server/data/mysql-bin.000009
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#240927  1:47:21 server id 1  end_log_pos 123 CRC32 0xee0c9ad0  Start: binlog v 4, server v 5.7.44-log created 240927  1:47:21 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
KZ71Zg8BAAAAdwAAAHsAAAABAAQANS43LjQ0LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAApnvVmEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AdCaDO4=
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 31, event_type: 35
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

虽然出现了日志,但是没看懂写的啥,只知道时间符合我的应用停止的时间,只知道当时 binlog 也非正常情况停止了...然后我的两个应用也停止运行了

如果你不确定时间是在那个 mysql-bin 文件,可以把数值改成 * 号 例如 .000009 改成 .*

结语

呃呃呃...就这样了,最后只知道了数据库出现了异常错误,但是不知道为什么错误,继续观察吧先......希望早点知道结果(或者有知道的大佬也可以说一下)

还有一个就是 查看 mysql-bin.000008 文件出现的日志和 000009 的一样,时间是和 xxx1 上次停止的时间是一致的..

#240920 16:34:35 server id 1  end_log_pos 123 CRC32 0xd3bf8a3a  Start: binlog v 4, server v 5.7.44-log created 240920 16:34:35 at startup
`FATA[2024-09-20 16:33:58] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused
FATA[2024-09-20 16:33:58] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused
FATA[2024-09-20 16:33:59] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused
FATA[2024-09-20 16:33:59] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused
FATA[2024-09-20 16:34:01] failed to connect database:dial tcp 127.0.0.1:3306: connect: connection refused `

赞(1)
未经允许不得转载:工具盒子 » 查看详细日志、MySQL之二进制文件