获取微信服务器响应时间,微信第三方平台 - 报警群，内容: 微信服务器向公众号服务开发者推送component_verify_ticket时，开发者5秒内没有返回 次数: 30分钟 9次 的分析解决 ...

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&timestamp=1606464908&nonce=1528041077&encrypt_type=aes&msg_signature=ce607cecc737d31ec1f4edeb853e00539f492732",

"url": "http://auth.channel-pub.wjdev.chinamcloud.cn/wx-msg-event/ticket?signa