Failed to record MySQL requests when the MySQL sends error message first

[dxsup]

Description

A Java process sent requests to a MySQL and the MySQL server replied with an error message:

The client did connect to the MySQL and the server did reply. The metric kindling_tcp_connect_total recorded successful connection:

But I can't find the values in the metric kindling_topology_request_total:

Debug

I have checked the syscall events of the client. The events sequence is outside of the expected range. I put part of the sequence below.

40071 14:09:19.108152558 0 com.mchange.v2. (21858) > socket domain=2(AF_INET) type=1 proto=0 
40072 14:09:19.108175028 1 com.mchange.v2. (21859) > switch next=32677(kindling-collec) pgft_maj=0 pgft_min=1155 vm_size=5488384 vm_rss=275592 vm_swap=0 
40075 14:09:19.108201814 0 com.mchange.v2. (21858) < socket fd=165(<4>) 
40076 14:09:19.108207811 0 com.mchange.v2. (21858) > setsockopt 
40078 14:09:19.108210438 0 com.mchange.v2. (21858) < setsockopt res=0 fd=165(<4>) level=2(SOL_TCP) optname=0(UNKNOWN) val=.... optlen=4 
40080 14:09:19.108214794 0 com.mchange.v2. (21858) > setsockopt 
40081 14:09:19.108216278 0 com.mchange.v2. (21858) < setsockopt res=0 fd=165(<4>) level=1(SOL_SOCKET) optname=9(SO_KEEPALIVE) val=1 optlen=4 
40086 14:09:19.108244368 0 com.mchange.v2. (21858) > connect fd=165(<4>) addr=10.107.225.118:3306 
40153 14:09:19.108931171 0 com.mchange.v2. (21860) > switch next=21858(com.mchange.v2.) pgft_maj=0 pgft_min=1312 vm_size=5488384 vm_rss=275592 vm_swap=0 
40154 14:09:19.108938968 0 com.mchange.v2. (21858) < connect res=0 tuple=192.168.94.90:36842->10.107.225.118:3306 
40155 14:09:19.108946198 0 com.mchange.v2. (21858) > getsockname 
40156 14:09:19.108948491 0 com.mchange.v2. (21858) < getsockname 
40163 14:09:19.108978258 0 com.mchange.v2. (21858) > ioctl fd=165(<4t>192.168.94.90:36842->10.107.225.118:3306) request=541B argument=7F35779F823C 
40164 14:09:19.108981552 0 com.mchange.v2. (21858) < ioctl res=0 
40166 14:09:19.108987532 0 com.mchange.v2. (21858) > recvfrom fd=165(<4t>192.168.94.90:36842->10.107.225.118:3306) size=4 
40167 14:09:19.108994082 0 com.mchange.v2. (21858) > switch next=32536(kindling-collec) pgft_maj=0 pgft_min=1140 vm_size=5488384 vm_rss=275592 vm_swap=0 
40177 14:09:19.109382612 1 com.mchange.v2. (21859) < recvfrom res=4 data=k... tuple=NULL 
40185 14:09:19.109447419 0 com.mchange.v2. (21858) > ioctl fd=165(<4t>192.168.94.90:36842->10.107.225.118:3306) request=541B argument=7F35779F823C 
40186 14:09:19.109451242 0 com.mchange.v2. (21858) < ioctl res=0 
40187 14:09:19.109456742 0 com.mchange.v2. (21858) > recvfrom fd=165(<4t>192.168.94.90:36842->10.107.225.118:3306) size=107 
40188 14:09:19.109461535 0 com.mchange.v2. (21858) < recvfrom res=107 data=.i.Host '192.168.94.90' is blocked because of many connection errors; unblock wi tuple=NULL 
40194 14:09:19.109575559 0 com.mchange.v2. (21858) > close fd=165(<u>) 
40196 14:09:19.109579412 0 com.mchange.v2. (21858) < close res=0 

call-mysql-syscall.txt

It seems like the MySQL server sends messages to the client first after the connection is established. This case is not considered before.

Further Information

This issue is gone after I fixed the errors that the MySQL server complained about. The syscall events sequence was changed.

930222 15:17:07.994411755 1 http-nio-8080-e (1988.6564) > ioctl fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) request=541B argument=7F35C2F34D3C 
930223 15:17:07.994415655 1 http-nio-8080-e (1988.6564) < ioctl res=0 
930225 15:17:07.994424122 1 http-nio-8080-e (1988.6564) > sendto fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) size=26 tuple=NULL 
930231 15:17:07.994497032 1 http-nio-8080-e (1988.6564) < sendto res=26 data=.....select * from student 
930232 15:17:07.994506735 1 http-nio-8080-e (1988.6564) > ioctl fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) request=541B argument=7F35C2F34CCC 
930233 15:17:07.994508665 1 http-nio-8080-e (1988.6564) < ioctl res=0 
930234 15:17:07.994512022 1 http-nio-8080-e (1988.6564) > recvfrom fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) size=4 
930380 15:17:07.995281596 1 http-nio-8080-e (1988.6564) < recvfrom res=4 data=.... tuple=NULL 
930384 15:17:07.995294143 1 http-nio-8080-e (1988.6564) > ioctl fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) request=541B argument=7F35C2F34CCC 
930385 15:17:07.995297229 1 http-nio-8080-e (1988.6564) < ioctl res=0 
930388 15:17:07.995300036 1 http-nio-8080-e (1988.6564) > recvfrom fd=172(<4t>192.168.94.90:44948->10.107.225.118:3306) size=324 
930389 15:17:07.995303853 1 http-nio-8080-e (1988.6564) < recvfrom res=324 [email protected]_id.student_id.?...........<....def.pr tuple=NULL