Bug #41600 agent angel process spawning too soon - causing duplicate UUID error
Submitted: 18 Dec 2008 19:18 Modified: 27 Feb 2009 11:58
Reporter: Lig Isler-Turmelle Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Enterprise Monitor: Agent Severity:S2 (Serious)
Version:2.0.0.7111 , 2.0.2.7126 OS:Any
Assigned to: MC Brown CPU Architecture:Any
Tags: mem_discuss_me

[18 Dec 2008 19:18] Lig Isler-Turmelle
Description:
2008-12-17 18:58:58: (message) agent_mysqld.c:313: [mysql] mysqld is local and directly connected
2008-12-17 18:58:58: ((error)) agent_mysqld.c:444: [mysql] mysql_real_query("SELECT value FROM mysql.inventory WHERE name = 'uuid'") failed: SELECT command denied to user 'ent_agent'@'127.0.0.1' for table 'inventory' (errno=1142)
2008-12-17 18:58:58: (debug) chassis.c:282: 15134 returned: 15134
2008-12-17 18:58:58: (message) chassis.c:304: [angel] PID=15134 died on signal=6 (it used 0 kBytes max) ... waiting 3min before restart
2008-12-17 18:59:00: (debug) chassis.c:244: we are the child: 15149
2008-12-17 18:59:00: (message) chassis.c:259: [angel] we try to keep PID=15149 alive
2008-12-17 18:59:00: (debug) chassis.c:277: waiting for 15149
2008-12-17 18:59:00: (message) mysql-proxy 0.7.0 started
2008-12-17 18:59:00: (message) MySQL Monitor Agent 2.0.0.7111 started.

g_error essentially logs a fatal error, and calls abort(). this terminates the program, and then the angel respawns with the same UUID, but a -1 session resync request, which the MEM server denies because the old session is still active. 

This was caused by a permissions denied error (1142) on the mysql.inventory table.

How to repeat:
1) create a user that does NOT have SELECT permissions on the mysql.inventory table ( I gave mine SELECT access to every database BUT the mysql database).  With all other agent permissions granted

mysql> show grants for 'agent_test'@'localhost';
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for agent_test@localhost                                                                                                                                        |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT INSERT, PROCESS, SHOW DATABASES, SUPER, REPLICATION CLIENT ON *.* TO 'agent_test'@'localhost' IDENTIFIED BY PASSWORD '*40EBE145368E7CEEC449ACD84470736718BF7307' |                                                                                                                | 
| GRANT SELECT ON `sakila`.* TO 'agent_test'@'localhost'                                                                                                                 | 
| GRANT SELECT ON `test`.* TO 'agent_test'@'localhost'                                                                                                                   | 
| GRANT SELECT ON `world`.* TO 'agent_test'@'localhost'                                                                                                                  | 
| GRANT INSERT, CREATE ON `mysql`.* TO 'agent_test'@'localhost'                                                                                                          |                                                                                                                 | 
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

2) set the limited agent user to be used by the agent for the monitored DB (agent-instance.ini)
3) restart the agent so it uses the new limited user
4) see the agent error log
5) set it back to a user that has the correct permissions - wait for the session  to timeout and restart the agent.  Error disappears.

except from my log:
2008-12-18 13:38:16: ((error)) agent_mysqld.c:444: [mysql] mysql_real_query("SELECT value FROM mysql.inventory WHERE name = 'uuid'") failed: SELECT command denied to user 'agent_test'@'localhost' for table 'inventory' (errno=1142)
2008-12-18 13:38:23: (critical) exception received from server: E1402: DuplicateAgentUuidException: [dbd0e622-4c40-45a4-b7ca-8308193a1a41]
2008-12-18 13:38:55: (critical) last message repeated 9 times
2008-12-18 13:38:55: (critical) exception received from server: E1402: DuplicateAgentUuidException: [dbd0e622-4c40-45a4-b7ca-8308193a1a41]

Suggested fix:
n/a
[30 Dec 2008 13:26] Mark Leith
Patch submitted to Jan/Kay
[9 Jan 2009 16:40] Diego Medina
Now I see this entry on the log

2009-01-09 11:36:58: (critical) agent_mysqld.c:609: agent connecting to mysql-server failed: mysql_real_connect(host = '127.0.0.1', port = 5130, socket = ''): Access denied for user 'agent_test'@'localhost' (using password: YES) (mysql-errno = 1045)

but the agent is still running and on the Dashboard it shows the agent running but the monitored mysqld as stopped.
[28 Jan 2009 20:35] Mark Leith
This happens when the agent lacks CREATE privileges on the mysql schema too.
[24 Feb 2009 20:31] Diego Medina
Verified fixed on 2.0.5.7145

Not having enough privileges does not crash the agent any more, and there are no more duplicate UUID errors.
[27 Feb 2009 11:58] Tony Bedford
An entry was added to the 2.0.5 changelog:

The agent angel process was spawning too soon, which caused a duplicate UUID error.

g_error() logged a fatal error, and called abort(). This terminated the program. Then the angel respawned with the same UUID, but with a -1 session resync request, which the MEM server denied because the old session was still active. This resulted in a permissions denied error (1142) on the mysql.inventory table.

2008-12-17 18:58:58: (message) agent_mysqld.c:313: [mysql] mysqld is local and directly connected
2008-12-17 18:58:58: ((error)) agent_mysqld.c:444: [mysql] mysql_real_query("SELECT value
FROM mysql.inventory WHERE name = 'uuid'") failed: SELECT command denied to user
'ent_agent'@'127.0.0.1' for table 'inventory' (errno=1142)
2008-12-17 18:58:58: (debug) chassis.c:282: 15134 returned: 15134
2008-12-17 18:58:58: (message) chassis.c:304: [angel] PID=15134 died on signal=6 (it used
0 kBytes max) ... waiting 3min before restart
2008-12-17 18:59:00: (debug) chassis.c:244: we are the child: 15149
2008-12-17 18:59:00: (message) chassis.c:259: [angel] we try to keep PID=15149 alive
2008-12-17 18:59:00: (debug) chassis.c:277: waiting for 15149
2008-12-17 18:59:00: (message) mysql-proxy 0.7.0 started
2008-12-17 18:59:00: (message) MySQL Monitor Agent 2.0.0.7111 started.