1、在微信的第三方平台,错误告警通过微信群来通知,每个第三方平台对应唯一的告警群,扫码加入即可接收告警通知。如图1
图1
2、在告警群中频繁接收到告警通知。分析其规律,发现其间隔时间为 40 分钟。11:25、12:15、12:55、13:35、14:15。如图2
图2Appid:
昵称:
时间: 2020-11-27 13:35:05
内容: 微信服务器向公众号服务开发者推送component_verify_ticket时,开发者5秒内没有返回
次数: 30分钟 9次
报警排查指引,请见: https://mmbizurl.cn/s/MpkaZb8yg
3、参考验证票据,网址:https://developers.weixin.qq.com/doc/oplatform/Third-party_Platforms/api/component_verify_ticket.html 。
4、查看代码实现
/**
* Component Verify Ticket 协议接收
*/
public function actionTicket()
{
$bathPath = Yii::$app->getBasePath();
try {
$requestRowBody = Yii::$app->getRequest()->getRawBody();
$requestQueryParams = Yii::$app->getRequest()->getQueryParams();
@file_put_contents($bathPath . '/runtime/requestRowBody.txt', var_export($requestRowBody, true), LOCK_EX);
@file_put_contents($bathPath . '/runtime/requestQueryParams.txt', var_export($requestQueryParams, true), LOCK_EX);
$appId = Yii::$app->params['wxOpen']['component']['appId'];
$appSecret = Yii::$app->params['wxOpen']['component']['appSecret'];
$token = Yii::$app->params['wxOpen']['component']['token'];
$encodingAesKey = Yii::$app->params['wxOpen']['component']['symmetricKey'];
$msg = '';
$pc = new WXBizMsgCrypt($token, $encodingAesKey, $appId);
// 解密 xml 数据
$errCode = $pc->decryptMsg($requestQueryParams['msg_signature'], $requestQueryParams['timestamp'], $requestQueryParams['nonce'], $requestRowBody, $msg);
@file_put_contents($bathPath . '/runtime/decrypt_result.txt', $errCode, LOCK_EX);
// 解密成功
if ($errCode == 0) {
$ticketData = $this->xmlToArray($msg);
if (isset($ticketData['ComponentVerifyTicket'])) {
$redisCommandkeyPrefix = Yii::$app->params['redisCommand']['keyPrefix'];
$componentVerifyTicketKey = $redisCommandkeyPrefix . $ticketData['AppId'] . ':component_verify_ticket';
$this->redis->set($componentVerifyTicketKey, $ticketData['ComponentVerifyTicket']);
// 获取第三方平台component_access_token
$this->getComponentAccessToken($appId, $appSecret);
}
}
@file_put_contents($bathPath . '/runtime/msgXml.txt', $msg, LOCK_EX);
} catch (\Throwable $th) {
@file_put_contents($bathPath . '/runtime/actionTicketError.txt', $th->getMessage(), LOCK_EX);
}
exit('success');
}
5、先查看已经生成的日志文件的创建时间,发现皆在 14:35 生成的。如图3
图3[root@b21d3b4237a2 runtime]# ls -lt
total 28
drwxrwxr-x 2 nginx nginx 4096 Nov 27 14:35 debug
-rw-r--r-- 1 nginx nginx 305 Nov 27 14:35 msgXml.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:35 decrypt_result.txt
-rw-r--r-- 1 nginx nginx 219 Nov 27 14:35 requestQueryParams.txt
-rw-r--r-- 1 nginx nginx 573 Nov 27 14:35 requestRowBody.txt
-rw-r--r-- 1 nginx nginx 18 Nov 26 17:24 actionReceive.txt
drwxrwxr-x 5 nginx nginx 4096 Nov 26 15:15 cache
[root@b21d3b4237a2 runtime]#
6、决定逐一打印输出程序运行过程中的服务器时间,以排查分析是哪一个环节导致的响应时间过长。
public function init()
{
file_put_contents(Yii::getAlias('@runtime') . '/wx-msg-event-ticket-' . Date('Y-m-d-H-i-s') . '-' . microtime(true) . '-' . mt_rand() . '.txt', print_r('1', true), FILE_APPEND | LOCK_EX);
parent::init();
require __DIR__ . '/../vendor/wx_biz_msg_crypt/wxBizMsgCrypt.php';
$this->redis = Yii::$app->redis;
file_put_contents(Yii::getAlias('@runtime') . '/wx-msg-event-ticket-' . Date('Y-m-d-H-i-s') . '-' . microtime(true) . '-' . mt_rand() . '.txt', print_r('1', true), FILE_APPEND | LOCK_EX);
}
/**
* Component Verify Ticket 协议接收
*/
public function actionTicket()
{
file_put_contents(Yii::getAlias('@runtime') . '/wx-msg-event-ticket-' . Date('Y-m-d-H-i-s') . '-' . microtime(true) . '-' . mt_rand() . '.txt', print_r('1', true), FILE_APPEND | LOCK_EX);
$bathPath = Yii::$app->getBasePath();
try {
$requestRowBody = Yii::$app->getRequest()->getRawBody();
$requestQueryParams = Yii::$app->getRequest()->getQueryParams();
@file_put_contents($bathPath . '/runtime/requestRowBody.txt', var_export($requestRowBody, true), LOCK_EX);
@file_put_contents($bathPath . '/runtime/requestQueryParams.txt', var_export($requestQueryParams, true), LOCK_EX);
$appId = Yii::$app->params['wxOpen']['component']['appId'];
$appSecret = Yii::$app->params['wxOpen']['component']['appSecret'];
$token = Yii::$app->params['wxOpen']['component']['token'];
$encodingAesKey = Yii::$app->params['wxOpen']['component']['symmetricKey'];
$msg = '';
$pc = new WXBizMsgCrypt($token, $encodingAesKey, $appId);
// 解密 xml 数据
$errCode = $pc->decryptMsg($requestQueryParams['msg_signature'], $requestQueryParams['timestamp'], $requestQueryParams['nonce'], $requestRowBody, $msg);
@file_put_contents($bathPath . '/runtime/decrypt_result.txt', $errCode, LOCK_EX);
// 解密成功
if ($errCode == 0) {
$ticketData = $this->xmlToArray($msg);
if (isset($ticketData['ComponentVerifyTicket'])) {
$redisCommandkeyPrefix = Yii::$app->params['redisCommand']['keyPrefix'];
$componentVerifyTicketKey = $redisCommandkeyPrefix . $ticketData['AppId'] . ':component_verify_ticket';
$this->redis->set($componentVerifyTicketKey, $ticketData['ComponentVerifyTicket']);
// 获取第三方平台component_access_token
$this->getComponentAccessToken($appId, $appSecret);
}
}
@file_put_contents($bathPath . '/runtime/msgXml.txt', $msg, LOCK_EX);
} catch (\Throwable $th) {
@file_put_contents($bathPath . '/runtime/actionTicketError.txt', $th->getMessage(), LOCK_EX);
}
file_put_contents(Yii::getAlias('@runtime') . '/wx-msg-event-ticket-' . Date('Y-m-d-H-i-s') . '-' . microtime(true) . '-' . mt_rand() . '.txt', print_r('1', true), FILE_APPEND | LOCK_EX);
exit('success');
}
7、在时间: 2020-11-27 14:55:05 告警一次。再次查看已经生成的日志文件的创建时间,发现皆在 14:55:05 生成的。间隔 2020-11-27-14-55-05-1606460105.8643 – 2020-11-27-14-55-05-1606460105.8318 = 3.25毫秒。最终决定再多观察几次。等待再一次告警时,查看日志文件的生成时间。如图4
图4[root@b21d3b4237a2 runtime]# ls -lt
total 44
drwxrwxr-x 2 nginx nginx 4096 Nov 27 14:55 debug
-rw-r--r-- 1 nginx nginx 305 Nov 27 14:55 msgXml.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:55 wx-msg-event-ticket-2020-11-27-14-55-05-1606460105.8643-1726079413.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:55 decrypt_result.txt
-rw-r--r-- 1 nginx nginx 220 Nov 27 14:55 requestQueryParams.txt
-rw-r--r-- 1 nginx nginx 573 Nov 27 14:55 requestRowBody.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:55 wx-msg-event-ticket-2020-11-27-14-55-05-1606460105.8354-582349057.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:55 wx-msg-event-ticket-2020-11-27-14-55-05-1606460105.8339-222161532.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 14:55 wx-msg-event-ticket-2020-11-27-14-55-05-1606460105.8318-1104390728.txt
-rw-r--r-- 1 nginx nginx 18 Nov 26 17:24 actionReceive.txt
drwxrwxr-x 5 nginx nginx 4096 Nov 26 15:15 cache
[root@b21d3b4237a2 runtime]#
8、在时间: 2020-11-27 15:35:14 告警一次。查看已经生成的日志文件的创建时间,发现皆在 15:35:14/15:35:15 生成的。间隔 2020-11-27-15-35-15-1606462515.0053 – 2020-11-27-15-35-14-1606462514.9779 = 2.74 毫秒。也未超过 5 秒钟。如图5
图5[root@b21d3b4237a2 runtime]# ls -lt
total 40
drwxrwxr-x 2 nginx nginx 4096 Nov 27 15:35 debug
-rw-r--r-- 1 nginx nginx 305 Nov 27 15:35 msgXml.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 15:35 wx-msg-event-ticket-2020-11-27-15-35-15-1606462515.0053-1335632384.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 15:35 decrypt_result.txt
-rw-r--r-- 1 nginx nginx 219 Nov 27 15:35 requestQueryParams.txt
-rw-r--r-- 1 nginx nginx 573 Nov 27 15:35 requestRowBody.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 15:35 wx-msg-event-ticket-2020-11-27-15-35-14-1606462514.9782-618938486.txt
drwxrwxr-x 5 nginx nginx 4096 Nov 27 15:35 cache
-rw-r--r-- 1 nginx nginx 1 Nov 27 15:35 wx-msg-event-ticket-2020-11-27-15-35-14-1606462514.9777-1594643539.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 15:35 wx-msg-event-ticket-2020-11-27-15-35-14-1606462514.9779-342752895.txt
9、在时间: 2020-11-27 15:35:14 告警一次。查看已经生成的日志文件的创建时间,发现皆在 16:15:08/16:15:09 生成的。间隔 2020-11-27-16-15-08-1606464908.3973 – 2020-11-27-16-15-08-1606464908.3718 = 2.55 毫秒。间隔 2020-11-27-16-15-09-1606464909.8787 – 2020-11-27-16-15-09-1606464909.8577 = 2.10 毫秒。也未超过 5 秒钟。不过确是连续请求了 2 次,总计生成了 8 个具有时间戳的日志文件。或许是因为第一次请求超时,然后重试了一次。
[root@b21d3b4237a2 runtime]# ls -lt
total 56
drwxrwxr-x 2 nginx nginx 4096 Nov 27 16:15 debug
-rw-r--r-- 1 nginx nginx 305 Nov 27 16:15 msgXml.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-09-1606464909.8787-571586970.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 decrypt_result.txt
-rw-r--r-- 1 nginx nginx 220 Nov 27 16:15 requestQueryParams.txt
-rw-r--r-- 1 nginx nginx 573 Nov 27 16:15 requestRowBody.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-09-1606464909.858-528516846.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-09-1606464909.8575-1518393836.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-09-1606464909.8577-2077551670.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-08-1606464908.3973-362685582.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-08-1606464908.3713-1831294750.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-08-1606464908.3715-929485623.txt
-rw-r--r-- 1 nginx nginx 1 Nov 27 16:15 wx-msg-event-ticket-2020-11-27-16-15-08-1606464908.3718-843415591.txt
drwxrwxr-x 5 nginx nginx 4096 Nov 27 16:15 cache
10、查看第 8 步骤的 Nginx 日志,总计请求了 2 次。如图6
图6{
"request": {
"headers": {
"referer": "-",
"host": "auth.channel-pub.wjdev.chinamcloud.cn",
"x-request-id": "-",
"x-forwarded-for": "81.69.19.7, 10.42.0.1",
"user-agent": "Mozilla/4.0"
},
"method": "POST",
"uri": "/wx-msg-event/ticket?signature=476b7eacb0c523eaa0e8db5f7cca491a46e572fd×tamp=1606464908&nonce=1528041077&encrypt_type=aes&msg_signature=ce607cecc737d31ec1f4edeb853e00539f492732",
"url": "http://auth.channel-pub.wjdev.chinamcloud.cn/wx-msg-event/ticket?signa