[DEBUG] 1425367424.116649 - XML-RPC-Server - Enqueuing request (<socket._socketobject object at 0x26a3050>) from (('10.58.46.143', 57627)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367424.116968 - XML-RPC-Session-0 - Processing request (<socket._socketobject object at 0x26a3050>) from (('10.58.46.143', 57627)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367424.117747 - XML-RPC-Session-0 - Finishing request (<socket._socketobject object at 0x26a3050>) from (('10.58.46.143', 57627)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367424.118806 - XML-RPC-Server - Enqueuing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57628)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367424.118983 - XML-RPC-Session-0 - Processing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57628)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367424.119431 - XML-RPC-Session-0 - Statement (SELECT username, protocol, passwordFROM users WHERE username = %s AND protocol = %s, Params(('admin', 'xmlrpc')).
[DEBUG] 1425367424.120792 - XML-RPC-Session-0 - Statement (SELECT p.subsystem, p.component, p.functionFROM users AS u LEFT JOIN user_roles AS ur USING (user_id)    LEFT JOIN role_permissions AS rp USING (role_id)    LEFT JOIN permissions AS p USING (permission_id)WHERE    u.username = %s AND protocol = %s, Params((u'admin', u'xmlrpc')).
[DEBUG] 1425367424.121723 - XML-RPC-Session-0 - Started command (group, promote).
[DEBUG] 1425367424.121945 - XML-RPC-Session-0 - Statement (INSERT INTO log (subject, reported, reporter, message, category, type) VALUES(%s, %s, %s, %s, %s, %s), Params(('group.promote', datetime.datetime(2015, 3, 3, 7, 23, 44), 'mysql.fabric.command', 'Started command (group, promote).', 1, 0)).
[DEBUG] 1425367424.122745 - XML-RPC-Session-0 - Triggering event <mysql.fabric.events.Event object at 0x255c310> in handler <mysql.fabric.events.Handler object at 0x25b0390>
[DEBUG] 1425367424.122840 - XML-RPC-Session-0 - Triggering event <mysql.fabric.events.Event object at 0x255c310>
[DEBUG] 1425367424.123019 - XML-RPC-Session-0 - Created procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.123204 - XML-RPC-Session-0 - Created job (be35ad81-9d97-4602-9240-8c75a18eb403, e9520326-a2e5-4899-a40f-4252c6d54f7c, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367424.123430 - XML-RPC-Session-0 - Statement (BEGIN, Params(()).
[DEBUG] 1425367424.123829 - XML-RPC-Session-0 - Statement (INSERT INTO checkpoints(proc_uuid, lockable_objects, job_uuid, sequence, action_fqn, param_args, param_kwargs) VALUES (%s, %s, %s, %s, %s, %s, %s), Params(('be35ad81-9d97-4602-9240-8c75a18eb403', "c__builtin__\nset\np0\n((lp1\nS'lock'\np2\natp3\nRp4\n.", 'e9520326-a2e5-4899-a40f-4252c6d54f7c', 0, 'mysql.fabric.services.highavailability._define_ha_operation', "(S'my_group'\np0\nNI00\ntp1\n.", '(dp0\n.')).
[DEBUG] 1425367424.124256 - XML-RPC-Session-0 - Statement (COMMIT, Params(()).
[DEBUG] 1425367424.124729 - XML-RPC-Session-0 - Enqueued procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.124891 - Executor-2 - Locking procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.125005 - Executor-2 - LockManager - Enqueuing request for procedure (<Procedure object: uuid=be35ad81-9d97-4602-9240-8c75a18eb403, complete=False, exec_jobs=[], sche_jobs=['e9520326-a2e5-4899-a40f-4252c6d54f7c']>) on objects(set(['lock'])).
[DEBUG] 1425367424.125148 - Executor-2 - Locked procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.125272 - Executor-2 - Executing procedure (<Procedure object: uuid=be35ad81-9d97-4602-9240-8c75a18eb403, complete=False, exec_jobs=[], sche_jobs=['e9520326-a2e5-4899-a40f-4252c6d54f7c']>).
[DEBUG] 1425367424.125381 - Executor-2 - Reading next job from queue, found <Job object: uuid=e9520326-a2e5-4899-a40f-4252c6d54f7c, status=[{'diagnosis': '', 'state': 3, 'when': 1425367424.123189, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x255c310>.', 'success': 2}]>.
[DEBUG] 1425367424.125485 - Executor-2 - Processing job (be35ad81-9d97-4602-9240-8c75a18eb403, e9520326-a2e5-4899-a40f-4252c6d54f7c, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367424.125701 - Executor-2 - Statement (UPDATE checkpoints set started = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367424.12556, 'be35ad81-9d97-4602-9240-8c75a18eb403', 'e9520326-a2e5-4899-a40f-4252c6d54f7c')).
[DEBUG] 1425367424.126414 - Executor-2 - Statement (BEGIN, Params(()).
[DEBUG] 1425367424.126656 - Executor-2 - Executing _define_ha_operation
[DEBUG] 1425367424.126761 - Executor-2 - Statement (SELECT group_id, description, master_uuid, master_defined, status FROM groups WHERE group_id = %s, Params(('my_group',)).
[DEBUG] 1425367424.127368 - Executor-2 - Statement (SELECT server_uuid, server_address, mode, status, weight, group_id FROM servers WHERE server_uuid = %s, Params(('1d2a312e-a539-11e4-bd95-40a8f01f6f10',)).
[DEBUG] 1425367424.127952 - Executor-2 - Triggering event <mysql.fabric.events.Event object at 0x26c0390> in handler <mysql.fabric.events.Handler object at 0x25b0390>
[DEBUG] 1425367424.128042 - Executor-2 - Triggering event <mysql.fabric.events.Event object at 0x26c0390>
[DEBUG] 1425367424.128216 - Executor-2 - Created job (be35ad81-9d97-4602-9240-8c75a18eb403, 0bf7af0a-0dde-46ab-9184-2e36f6b16175, mysql.fabric.services.highavailability._find_candidate_switch, Success).
[DEBUG] 1425367424.128438 - Executor-2 - Statement (INSERT INTO checkpoints(proc_uuid, lockable_objects, job_uuid, sequence, action_fqn, param_args, param_kwargs) VALUES (%s, %s, %s, %s, %s, %s, %s), Params(('be35ad81-9d97-4602-9240-8c75a18eb403', "c__builtin__\nset\np0\n((lp1\nS'lock'\np2\natp3\nRp4\n.", '0bf7af0a-0dde-46ab-9184-2e36f6b16175', 1, 'mysql.fabric.services.highavailability._find_candidate_switch', "(S'my_group'\np0\ntp1\n.", '(dp0\n.')).
[DEBUG] 1425367424.128842 - Executor-2 - Statement (UPDATE checkpoints set finished = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367424.1288061, 'be35ad81-9d97-4602-9240-8c75a18eb403', 'e9520326-a2e5-4899-a40f-4252c6d54f7c')).
[DEBUG] 1425367424.129236 - Executor-2 - Statement (COMMIT, Params(()).
[DEBUG] 1425367424.129614 - Executor-2 - Complete job (be35ad81-9d97-4602-9240-8c75a18eb403, e9520326-a2e5-4899-a40f-4252c6d54f7c, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367424.129748 - Executor-2 - Reading next job from queue, found <Job object: uuid=0bf7af0a-0dde-46ab-9184-2e36f6b16175, status=[{'diagnosis': '', 'state': 3, 'when': 1425367424.128202, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x26c0390>.', 'success': 2}]>.
[DEBUG] 1425367424.129849 - Executor-2 - Processing job (be35ad81-9d97-4602-9240-8c75a18eb403, 0bf7af0a-0dde-46ab-9184-2e36f6b16175, mysql.fabric.services.highavailability._find_candidate_switch, Success).
[DEBUG] 1425367424.130015 - Executor-2 - Statement (UPDATE checkpoints set started = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367424.129921, 'be35ad81-9d97-4602-9240-8c75a18eb403', '0bf7af0a-0dde-46ab-9184-2e36f6b16175')).
[DEBUG] 1425367424.130611 - Executor-2 - Statement (BEGIN, Params(()).
[DEBUG] 1425367424.130836 - Executor-2 - Executing _find_candidate_switch
[DEBUG] 1425367424.130932 - Executor-2 - Statement (SELECT group_id, description, master_uuid, master_defined, status FROM groups WHERE group_id = %s, Params(('my_group',)).
[DEBUG] 1425367424.131492 - Executor-2 - Statement (SELECT server_uuid, server_address, mode, status, weight, group_id FROM servers WHERE group_id = %s, Params((u'my_group',)).
[DEBUG] 1425367424.132352 - Executor-2 - Using connection (<mysql.connector.connection.MySQLConnection object at 0x7f0e7801f810>).
[DEBUG] 1425367424.132452 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_UUID as SERVER_UUID, Params(()).
[DEBUG] 1425367424.132817 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_ID as SERVER_ID, Params(()).
[DEBUG] 1425367424.133141 - Executor-2 - Statement (SELECT @@GLOBAL.VERSION as VERSION, Params(()).
[DEBUG] 1425367424.133480 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_MODE as GTID_MODE, Params(()).
[DEBUG] 1425367424.133802 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_BIN as LOG_BIN, Params(()).
[DEBUG] 1425367424.134117 - Executor-2 - Statement (SELECT @@GLOBAL.READ_ONLY as READ_ONLY, Params(()).
[DEBUG] 1425367424.134430 - Executor-2 - Connected to server with uuid (b445213a-a538-11e4-bd92-40a8f01f6f10), server_id (7307), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.134526 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_EXECUTED as GTID_EXECUTED, @@GLOBAL.GTID_PURGED as GTID_PURGED, @@GLOBAL.GTID_OWNED as GTID_OWNED, Params(()).
[DEBUG] 1425367424.135361 - Executor-2 - Start executing function: check_master_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.135469 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_SLAVE_UPDATES as LOG_SLAVE_UPDATES, Params(()).
[DEBUG] 1425367424.135793 - Executor-2 - Start executing function: has_appropriate_privileges((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.135891 - Executor-2 - Statement (SHOW GRANTS, Params(()).
[DEBUG] 1425367424.136224 - Executor-2 - Finish executing function: has_appropriate_privileges.
[DEBUG] 1425367424.136309 - Executor-2 - Finish executing function: check_master_issues.
[DEBUG] 1425367424.136383 - Executor-2 - Start executing function: check_slave_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.136462 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.136543 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.140163 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.140276 - Executor-2 - Finish executing function: check_slave_issues.
[DEBUG] 1425367424.140357 - Executor-2 - Start executing function: slave_has_master((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.140438 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086950>,), {}).
[DEBUG] 1425367424.140523 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.143978 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.144088 - Executor-2 - Finish executing function: slave_has_master.
[WARNING] 1425367424.144175 - Executor-2 - Candidate (b445213a-a538-11e4-bd92-40a8f01f6f10) cannot become a master due to the following reasons: issues to become a master ({'is_gtid_not_enabled': False, 'is_slave_updates_not_enabled': False, 'is_not_running': False, 'is_binlog_not_enabled': False, 'no_rpl_user': False}), prerequistes as a slave ({'sql_error': False, 'io_error': u"error reconnecting to master 'user_fabric@10.58.46.143:7306' - retry-time: 60  retries: 6", 'io_not_running': True, 'sql_not_running': False, 'is_not_configured': False, 'is_not_running': False}), valid master (True).
[DEBUG] 1425367424.144388 - Executor-2 - Using connection (<mysql.connector.connection.MySQLConnection object at 0x2761290>).
[DEBUG] 1425367424.144484 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_UUID as SERVER_UUID, Params(()).
[DEBUG] 1425367424.144846 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_ID as SERVER_ID, Params(()).
[DEBUG] 1425367424.145169 - Executor-2 - Statement (SELECT @@GLOBAL.VERSION as VERSION, Params(()).
[DEBUG] 1425367424.145509 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_MODE as GTID_MODE, Params(()).
[DEBUG] 1425367424.145829 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_BIN as LOG_BIN, Params(()).
[DEBUG] 1425367424.146144 - Executor-2 - Statement (SELECT @@GLOBAL.READ_ONLY as READ_ONLY, Params(()).
[DEBUG] 1425367424.146455 - Executor-2 - Connected to server with uuid (b77574f3-b25b-11e4-933c-40a8f01f6f10), server_id (7309), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.146549 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_EXECUTED as GTID_EXECUTED, @@GLOBAL.GTID_PURGED as GTID_PURGED, @@GLOBAL.GTID_OWNED as GTID_OWNED, Params(()).
[DEBUG] 1425367424.147323 - Executor-2 - Start executing function: check_master_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.147429 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_SLAVE_UPDATES as LOG_SLAVE_UPDATES, Params(()).
[DEBUG] 1425367424.147754 - Executor-2 - Start executing function: has_appropriate_privileges((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.147852 - Executor-2 - Statement (SHOW GRANTS, Params(()).
[DEBUG] 1425367424.148176 - Executor-2 - Finish executing function: has_appropriate_privileges.
[DEBUG] 1425367424.148265 - Executor-2 - Finish executing function: check_master_issues.
[DEBUG] 1425367424.148341 - Executor-2 - Start executing function: check_slave_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.148418 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.148500 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.152156 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.152267 - Executor-2 - Finish executing function: check_slave_issues.
[DEBUG] 1425367424.152351 - Executor-2 - Start executing function: slave_has_master((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.152435 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea4086f50>,), {}).
[DEBUG] 1425367424.152523 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.155974 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.156084 - Executor-2 - Finish executing function: slave_has_master.
[WARNING] 1425367424.156168 - Executor-2 - Candidate (b77574f3-b25b-11e4-933c-40a8f01f6f10) cannot become a master due to the following reasons: issues to become a master ({'is_gtid_not_enabled': False, 'is_slave_updates_not_enabled': False, 'is_not_running': False, 'is_binlog_not_enabled': False, 'no_rpl_user': False}), prerequistes as a slave ({'sql_error': False, 'io_error': u"error reconnecting to master 'user_fabric@10.58.46.143:7306' - retry-time: 60  retries: 6", 'io_not_running': True, 'sql_not_running': False, 'is_not_configured': False, 'is_not_running': False}), valid master (True).
[DEBUG] 1425367424.156380 - Executor-2 - Using connection (<mysql.connector.connection.MySQLConnection object at 0x269cdd0>).
[DEBUG] 1425367424.156474 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_UUID as SERVER_UUID, Params(()).
[DEBUG] 1425367424.156832 - Executor-2 - Statement (SELECT @@GLOBAL.SERVER_ID as SERVER_ID, Params(()).
[DEBUG] 1425367424.157158 - Executor-2 - Statement (SELECT @@GLOBAL.VERSION as VERSION, Params(()).
[DEBUG] 1425367424.157503 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_MODE as GTID_MODE, Params(()).
[DEBUG] 1425367424.157826 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_BIN as LOG_BIN, Params(()).
[DEBUG] 1425367424.158142 - Executor-2 - Statement (SELECT @@GLOBAL.READ_ONLY as READ_ONLY, Params(()).
[DEBUG] 1425367424.158452 - Executor-2 - Connected to server with uuid (ddfec00f-a540-11e4-bdc7-40a8f01f6f10), server_id (7308), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.158548 - Executor-2 - Statement (SELECT @@GLOBAL.GTID_EXECUTED as GTID_EXECUTED, @@GLOBAL.GTID_PURGED as GTID_PURGED, @@GLOBAL.GTID_OWNED as GTID_OWNED, Params(()).
[DEBUG] 1425367424.159323 - Executor-2 - Start executing function: check_master_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.159428 - Executor-2 - Statement (SELECT @@GLOBAL.LOG_SLAVE_UPDATES as LOG_SLAVE_UPDATES, Params(()).
[DEBUG] 1425367424.159749 - Executor-2 - Start executing function: has_appropriate_privileges((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.159847 - Executor-2 - Statement (SHOW GRANTS, Params(()).
[DEBUG] 1425367424.160169 - Executor-2 - Finish executing function: has_appropriate_privileges.
[DEBUG] 1425367424.160258 - Executor-2 - Finish executing function: check_master_issues.
[DEBUG] 1425367424.160333 - Executor-2 - Start executing function: check_slave_issues((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.160412 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.160496 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.163958 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.164062 - Executor-2 - Finish executing function: check_slave_issues.
[DEBUG] 1425367424.164142 - Executor-2 - Start executing function: slave_has_master((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.164225 - Executor-2 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0ea40865d0>,), {}).
[DEBUG] 1425367424.164309 - Executor-2 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367424.167766 - Executor-2 - Finish executing function: get_slave_status.
[DEBUG] 1425367424.167876 - Executor-2 - Finish executing function: slave_has_master.
[WARNING] 1425367424.167962 - Executor-2 - Candidate (ddfec00f-a540-11e4-bdc7-40a8f01f6f10) cannot become a master due to the following reasons: issues to become a master ({'is_gtid_not_enabled': False, 'is_slave_updates_not_enabled': False, 'is_not_running': False, 'is_binlog_not_enabled': False, 'no_rpl_user': False}), prerequistes as a slave ({'sql_error': False, 'io_error': u"error reconnecting to master 'user_fabric@10.58.46.143:7306' - retry-time: 60  retries: 6", 'io_not_running': True, 'sql_not_running': False, 'is_not_configured': False, 'is_not_running': False}), valid master (True).
[DEBUG] 1425367424.168060 - Executor-2 - Disconnecting from server with uuid (b77574f3-b25b-11e4-933c-40a8f01f6f10), server_id (7309), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.168154 - Executor-2 - Disconnecting from server with uuid (b445213a-a538-11e4-bd92-40a8f01f6f10), server_id (7307), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.168268 - Executor-2 - _find_candidate_switch failed, executing compensation
[DEBUG] 1425367424.168348 - Executor-2 - There is no valid candidate that can be automatically chosen in group (my_group). Please, choose one manually.
[DEBUG] 1425367424.168429 - Executor-2 - Statement (ROLLBACK, Params(()).
[DEBUG] 1425367424.169207 - Executor-2 - Complete job (be35ad81-9d97-4602-9240-8c75a18eb403, 0bf7af0a-0dde-46ab-9184-2e36f6b16175, mysql.fabric.services.highavailability._find_candidate_switch, Error).
[DEBUG] 1425367424.169415 - Executor-2 - Statement (DELETE FROM checkpoints WHERE proc_uuid = %s, Params(('be35ad81-9d97-4602-9240-8c75a18eb403',)).
[DEBUG] 1425367424.169921 - Executor-2 - Complete procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.170017 - Executor-2 - Disconnecting from server with uuid (ddfec00f-a540-11e4-bdc7-40a8f01f6f10), server_id (7308), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367424.170132 - XML-RPC-Session-0 - Result after wait: uuid='be35ad81-9d97-4602-9240-8c75a18eb403', status='[{'diagnosis': '', 'state': 3, 'when': 1425367424.123189, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x255c310>.', 'success': 2}, {'diagnosis': '', 'state': 4, 'when': 1425367424.1254721, 'description': 'Executing action (_define_ha_operation).', 'success': 2}, {'diagnosis': '', 'state': 5, 'when': 1425367424.1296, 'description': 'Executed action (_define_ha_operation).', 'success': 2}, {'diagnosis': '', 'state': 3, 'when': 1425367424.128202, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x26c0390>.', 'success': 2}, {'diagnosis': '', 'state': 4, 'when': 1425367424.129837, 'description': 'Executing action (_find_candidate_switch).', 'success': 2}, {'diagnosis': 'Traceback (most recent call last):\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/executor.py", line 378, in execute\n    self.__result = self.__action(*self.__args, **self.__kwargs)\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/events.py", line 80, in wrapped\n    return wrapped.function(*args, **kwargs)\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/services/highavailability.py", line 303, in _find_candidate_switch\n    slave_uuid = _do_find_candidate(group_id, FIND_CANDIDATE_SWITCH)\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/services/highavailability.py", line 380, in _do_find_candidate\n    (group_id, )\nGroupError: There is no valid candidate that can be automatically chosen in group (my_group). Please, choose one manually.\n', 'state': 5, 'when': 1425367424.1686649, 'description': 'Tried to execute action (_find_candidate_switch).', 'success': 1}]', result='False'
[DEBUG] 1425367424.170252 - Executor-2 - LockManager - Dequeuing request for procedure (<Procedure object: uuid=be35ad81-9d97-4602-9240-8c75a18eb403, complete=True, exec_jobs=['e9520326-a2e5-4899-a40f-4252c6d54f7c', '0bf7af0a-0dde-46ab-9184-2e36f6b16175'], sche_jobs=[]>).
[DEBUG] 1425367424.170476 - XML-RPC-Session-0 - Failure: error='GroupError: There is no valid candidate that can be automatically chosen in group (my_group). Please, choose one manually.'
[DEBUG] 1425367424.170546 - Executor-2 - Released procedure - <Procedure object: uuid=be35ad81-9d97-4602-9240-8c75a18eb403, complete=True, exec_jobs=['e9520326-a2e5-4899-a40f-4252c6d54f7c', '0bf7af0a-0dde-46ab-9184-2e36f6b16175'], sche_jobs=[]> objects set(['lock']).
[DEBUG] 1425367424.170657 - XML-RPC-Session-0 - Finished command (group, promote).
[DEBUG] 1425367424.170779 - Executor-2 - Possible affected procedures set([]).
[DEBUG] 1425367424.170988 - Executor-2 - Unlocked procedure (be35ad81-9d97-4602-9240-8c75a18eb403).
[DEBUG] 1425367424.171133 - XML-RPC-Session-0 - Statement (INSERT INTO log (subject, reported, reporter, message, category, type) VALUES(%s, %s, %s, %s, %s, %s), Params(('group.promote', datetime.datetime(2015, 3, 3, 7, 23, 44), 'mysql.fabric.command', 'Finished command (group, promote).', 1, 2)).
[DEBUG] 1425367424.171751 - XML-RPC-Session-0 - Encoded packet: [1, '5ca1ab1e-a007-feed-f00d-cab3fe13249e', 1, 'GroupError: There is no valid candidate that can be automatically chosen in group (my_group). Please, choose one manually.', []]
[DEBUG] 1425367424.172086 - XML-RPC-Session-0 - Finishing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57628)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367465.961203 - Thread-28 - purged 1 expired clients
[DEBUG] 1425367499.664061 - XML-RPC-Server - Enqueuing request (<socket._socketobject object at 0x7f0ea4092a60>) from (('10.58.46.143', 57636)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367499.664303 - XML-RPC-Session-0 - Processing request (<socket._socketobject object at 0x7f0ea4092a60>) from (('10.58.46.143', 57636)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367499.665074 - XML-RPC-Session-0 - Finishing request (<socket._socketobject object at 0x7f0ea4092a60>) from (('10.58.46.143', 57636)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367499.666170 - XML-RPC-Server - Enqueuing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57637)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367499.666323 - XML-RPC-Session-0 - Processing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57637)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367499.666745 - XML-RPC-Session-0 - Statement (SELECT username, protocol, passwordFROM users WHERE username = %s AND protocol = %s, Params(('admin', 'xmlrpc')).
[DEBUG] 1425367499.668091 - XML-RPC-Session-0 - Statement (SELECT p.subsystem, p.component, p.functionFROM users AS u LEFT JOIN user_roles AS ur USING (user_id)    LEFT JOIN role_permissions AS rp USING (role_id)    LEFT JOIN permissions AS p USING (permission_id)WHERE    u.username = %s AND protocol = %s, Params((u'admin', u'xmlrpc')).
[DEBUG] 1425367499.669015 - XML-RPC-Session-0 - Started command (group, promote).
[DEBUG] 1425367499.669238 - XML-RPC-Session-0 - Statement (INSERT INTO log (subject, reported, reporter, message, category, type) VALUES(%s, %s, %s, %s, %s, %s), Params(('group.promote', datetime.datetime(2015, 3, 3, 7, 24, 59), 'mysql.fabric.command', 'Started command (group, promote).', 1, 0)).
[DEBUG] 1425367499.669998 - XML-RPC-Session-0 - Triggering event <mysql.fabric.events.Event object at 0x255c310> in handler <mysql.fabric.events.Handler object at 0x25b0390>
[DEBUG] 1425367499.670091 - XML-RPC-Session-0 - Triggering event <mysql.fabric.events.Event object at 0x255c310>
[DEBUG] 1425367499.670285 - XML-RPC-Session-0 - Created procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.670470 - XML-RPC-Session-0 - Created job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 3523d54d-cf47-487e-a851-01da47ad743a, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367499.670676 - XML-RPC-Session-0 - Statement (BEGIN, Params(()).
[DEBUG] 1425367499.671072 - XML-RPC-Session-0 - Statement (INSERT INTO checkpoints(proc_uuid, lockable_objects, job_uuid, sequence, action_fqn, param_args, param_kwargs) VALUES (%s, %s, %s, %s, %s, %s, %s), Params(('e6139ddb-3570-40ac-8e21-7f3f553568c6', "c__builtin__\nset\np0\n((lp1\nS'lock'\np2\natp3\nRp4\n.", '3523d54d-cf47-487e-a851-01da47ad743a', 0, 'mysql.fabric.services.highavailability._define_ha_operation', "(S'my_group'\np0\nS'b445213a-a538-11e4-bd92-40a8f01f6f10'\np1\nI00\ntp2\n.", '(dp0\n.')).
[DEBUG] 1425367499.671512 - XML-RPC-Session-0 - Statement (COMMIT, Params(()).
[DEBUG] 1425367499.671968 - XML-RPC-Session-0 - Enqueued procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.672123 - Executor-3 - Locking procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.672244 - Executor-3 - LockManager - Enqueuing request for procedure (<Procedure object: uuid=e6139ddb-3570-40ac-8e21-7f3f553568c6, complete=False, exec_jobs=[], sche_jobs=['3523d54d-cf47-487e-a851-01da47ad743a']>) on objects(set(['lock'])).
[DEBUG] 1425367499.672394 - Executor-3 - Locked procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.672514 - Executor-3 - Executing procedure (<Procedure object: uuid=e6139ddb-3570-40ac-8e21-7f3f553568c6, complete=False, exec_jobs=[], sche_jobs=['3523d54d-cf47-487e-a851-01da47ad743a']>).
[DEBUG] 1425367499.672620 - Executor-3 - Reading next job from queue, found <Job object: uuid=3523d54d-cf47-487e-a851-01da47ad743a, status=[{'diagnosis': '', 'state': 3, 'when': 1425367499.670455, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x255c310>.', 'success': 2}]>.
[DEBUG] 1425367499.672721 - Executor-3 - Processing job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 3523d54d-cf47-487e-a851-01da47ad743a, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367499.672923 - Executor-3 - Statement (UPDATE checkpoints set started = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367499.6727951, 'e6139ddb-3570-40ac-8e21-7f3f553568c6', '3523d54d-cf47-487e-a851-01da47ad743a')).
[DEBUG] 1425367499.673645 - Executor-3 - Statement (BEGIN, Params(()).
[DEBUG] 1425367499.673878 - Executor-3 - Executing _define_ha_operation
[DEBUG] 1425367499.673976 - Executor-3 - Statement (SELECT group_id, description, master_uuid, master_defined, status FROM groups WHERE group_id = %s, Params(('my_group',)).
[DEBUG] 1425367499.674574 - Executor-3 - Statement (SELECT server_uuid, server_address, mode, status, weight, group_id FROM servers WHERE server_uuid = %s, Params(('1d2a312e-a539-11e4-bd95-40a8f01f6f10',)).
[DEBUG] 1425367499.675153 - Executor-3 - Triggering event <mysql.fabric.events.Event object at 0x26c03d0> in handler <mysql.fabric.events.Handler object at 0x25b0390>
[DEBUG] 1425367499.675245 - Executor-3 - Triggering event <mysql.fabric.events.Event object at 0x26c03d0>
[DEBUG] 1425367499.675413 - Executor-3 - Created job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 8687df4e-a2ef-4862-829a-bf5652c1d541, mysql.fabric.services.highavailability._check_candidate_switch, Success).
[DEBUG] 1425367499.675635 - Executor-3 - Statement (INSERT INTO checkpoints(proc_uuid, lockable_objects, job_uuid, sequence, action_fqn, param_args, param_kwargs) VALUES (%s, %s, %s, %s, %s, %s, %s), Params(('e6139ddb-3570-40ac-8e21-7f3f553568c6', "c__builtin__\nset\np0\n((lp1\nS'lock'\np2\natp3\nRp4\n.", '8687df4e-a2ef-4862-829a-bf5652c1d541', 1, 'mysql.fabric.services.highavailability._check_candidate_switch', "(S'my_group'\np0\nS'b445213a-a538-11e4-bd92-40a8f01f6f10'\np1\ntp2\n.", '(dp0\n.')).
[DEBUG] 1425367499.676039 - Executor-3 - Statement (UPDATE checkpoints set finished = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367499.6760039, 'e6139ddb-3570-40ac-8e21-7f3f553568c6', '3523d54d-cf47-487e-a851-01da47ad743a')).
[DEBUG] 1425367499.676439 - Executor-3 - Statement (COMMIT, Params(()).
[DEBUG] 1425367499.676786 - Executor-3 - Complete job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 3523d54d-cf47-487e-a851-01da47ad743a, mysql.fabric.services.highavailability._define_ha_operation, Success).
[DEBUG] 1425367499.676909 - Executor-3 - Reading next job from queue, found <Job object: uuid=8687df4e-a2ef-4862-829a-bf5652c1d541, status=[{'diagnosis': '', 'state': 3, 'when': 1425367499.6754, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x26c03d0>.', 'success': 2}]>.
[DEBUG] 1425367499.677008 - Executor-3 - Processing job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 8687df4e-a2ef-4862-829a-bf5652c1d541, mysql.fabric.services.highavailability._check_candidate_switch, Success).
[DEBUG] 1425367499.677172 - Executor-3 - Statement (UPDATE checkpoints set started = %s WHERE proc_uuid = %s and job_uuid = %s, Params((1425367499.677078, 'e6139ddb-3570-40ac-8e21-7f3f553568c6', '8687df4e-a2ef-4862-829a-bf5652c1d541')).
[DEBUG] 1425367499.677774 - Executor-3 - Statement (BEGIN, Params(()).
[DEBUG] 1425367499.678007 - Executor-3 - Executing _check_candidate_switch
[DEBUG] 1425367499.678102 - Executor-3 - Statement (SELECT group_id, description, master_uuid, master_defined, status FROM groups WHERE group_id = %s, Params(('my_group',)).
[DEBUG] 1425367499.678659 - Executor-3 - Statement (SELECT server_uuid, server_address, mode, status, weight, group_id FROM servers WHERE server_uuid = %s, Params(('b445213a-a538-11e4-bd92-40a8f01f6f10',)).
[DEBUG] 1425367499.679321 - Executor-3 - Using connection (<mysql.connector.connection.MySQLConnection object at 0x7f0e7801f810>).
[DEBUG] 1425367499.679422 - Executor-3 - Statement (SELECT @@GLOBAL.SERVER_UUID as SERVER_UUID, Params(()).
[DEBUG] 1425367499.679781 - Executor-3 - Statement (SELECT @@GLOBAL.SERVER_ID as SERVER_ID, Params(()).
[DEBUG] 1425367499.680109 - Executor-3 - Statement (SELECT @@GLOBAL.VERSION as VERSION, Params(()).
[DEBUG] 1425367499.680449 - Executor-3 - Statement (SELECT @@GLOBAL.GTID_MODE as GTID_MODE, Params(()).
[DEBUG] 1425367499.680769 - Executor-3 - Statement (SELECT @@GLOBAL.LOG_BIN as LOG_BIN, Params(()).
[DEBUG] 1425367499.681085 - Executor-3 - Statement (SELECT @@GLOBAL.READ_ONLY as READ_ONLY, Params(()).
[DEBUG] 1425367499.681399 - Executor-3 - Connected to server with uuid (b445213a-a538-11e4-bd92-40a8f01f6f10), server_id (7307), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367499.681492 - Executor-3 - Start executing function: check_master_issues((<mysql.fabric.server.MySQLServer object at 0x7f0e78033750>,), {}).
[DEBUG] 1425367499.681588 - Executor-3 - Statement (SELECT @@GLOBAL.LOG_SLAVE_UPDATES as LOG_SLAVE_UPDATES, Params(()).
[DEBUG] 1425367499.681892 - Executor-3 - Start executing function: has_appropriate_privileges((<mysql.fabric.server.MySQLServer object at 0x7f0e78033750>,), {}).
[DEBUG] 1425367499.681988 - Executor-3 - Statement (SHOW GRANTS, Params(()).
[DEBUG] 1425367499.682316 - Executor-3 - Finish executing function: has_appropriate_privileges.
[DEBUG] 1425367499.682399 - Executor-3 - Finish executing function: check_master_issues.
[DEBUG] 1425367499.682471 - Executor-3 - Start executing function: check_slave_issues((<mysql.fabric.server.MySQLServer object at 0x7f0e78033750>,), {}).
[DEBUG] 1425367499.682550 - Executor-3 - Start executing function: get_slave_status((<mysql.fabric.server.MySQLServer object at 0x7f0e78033750>,), {}).
[DEBUG] 1425367499.682632 - Executor-3 - Statement (SHOW SLAVE STATUS, Params(()).
[DEBUG] 1425367499.686352 - Executor-3 - Finish executing function: get_slave_status.
[DEBUG] 1425367499.686457 - Executor-3 - Finish executing function: check_slave_issues.
[DEBUG] 1425367499.686559 - Executor-3 - _check_candidate_switch failed, executing compensation
[DEBUG] 1425367499.686641 - Executor-3 - Server (b445213a-a538-11e4-bd92-40a8f01f6f10) is not a valid candidate slave due to the following reason: ({'sql_error': False, 'io_error': u"error reconnecting to master 'user_fabric@10.58.46.143:7306' - retry-time: 60  retries: 8", 'io_not_running': True, 'sql_not_running': False, 'is_not_configured': False, 'is_not_running': False}).
[DEBUG] 1425367499.686726 - Executor-3 - Statement (ROLLBACK, Params(()).
[DEBUG] 1425367499.687054 - Executor-3 - Complete job (e6139ddb-3570-40ac-8e21-7f3f553568c6, 8687df4e-a2ef-4862-829a-bf5652c1d541, mysql.fabric.services.highavailability._check_candidate_switch, Error).
[DEBUG] 1425367499.687255 - Executor-3 - Statement (DELETE FROM checkpoints WHERE proc_uuid = %s, Params(('e6139ddb-3570-40ac-8e21-7f3f553568c6',)).
[DEBUG] 1425367499.687751 - Executor-3 - Complete procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.687846 - Executor-3 - Disconnecting from server with uuid (b445213a-a538-11e4-bd92-40a8f01f6f10), server_id (7307), version (5.6.15-log), gtid (True), binlog (True), read_only (True).
[DEBUG] 1425367499.687956 - XML-RPC-Session-0 - Result after wait: uuid='e6139ddb-3570-40ac-8e21-7f3f553568c6', status='[{'diagnosis': '', 'state': 3, 'when': 1425367499.670455, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x255c310>.', 'success': 2}, {'diagnosis': '', 'state': 4, 'when': 1425367499.672708, 'description': 'Executing action (_define_ha_operation).', 'success': 2}, {'diagnosis': '', 'state': 5, 'when': 1425367499.6767721, 'description': 'Executed action (_define_ha_operation).', 'success': 2}, {'diagnosis': '', 'state': 3, 'when': 1425367499.6754, 'description': 'Triggered by <mysql.fabric.events.Event object at 0x26c03d0>.', 'success': 2}, {'diagnosis': '', 'state': 4, 'when': 1425367499.676996, 'description': 'Executing action (_check_candidate_switch).', 'success': 2}, {'diagnosis': 'Traceback (most recent call last):\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/executor.py", line 378, in execute\n    self.__result = self.__action(*self.__args, **self.__kwargs)\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/events.py", line 80, in wrapped\n    return wrapped.function(*args, **kwargs)\n  File "/usr/lib/python2.6/site-packages/mysql/fabric/services/highavailability.py", line 419, in _check_candidate_switch\n    (slave.uuid, why_slave_issues)\nServerError: Server (b445213a-a538-11e4-bd92-40a8f01f6f10) is not a valid candidate slave due to the following reason: ({\'sql_error\': False, \'io_error\': u"error reconnecting to master \'user_fabric@10.58.46.143:7306\' - retry-time: 60  retries: 8", \'io_not_running\': True, \'sql_not_running\': False, \'is_not_configured\': False, \'is_not_running\': False}).\n', 'state': 5, 'when': 1425367499.6869669, 'description': 'Tried to execute action (_check_candidate_switch).', 'success': 1}]', result='False'
[DEBUG] 1425367499.688070 - Executor-3 - LockManager - Dequeuing request for procedure (<Procedure object: uuid=e6139ddb-3570-40ac-8e21-7f3f553568c6, complete=True, exec_jobs=['3523d54d-cf47-487e-a851-01da47ad743a', '8687df4e-a2ef-4862-829a-bf5652c1d541'], sche_jobs=[]>).
[DEBUG] 1425367499.688241 - XML-RPC-Session-0 - Failure: error='ServerError: Server (b445213a-a538-11e4-bd92-40a8f01f6f10) is not a valid candidate slave due to the following reason: ({'sql_error': False, 'io_error': u"error reconnecting to master 'user_fabric@10.58.46.143:7306' - retry-time: 60  retries: 8", 'io_not_running': True, 'sql_not_running': False, 'is_not_configured': False, 'is_not_running': False}).'
[DEBUG] 1425367499.688366 - Executor-3 - Released procedure - <Procedure object: uuid=e6139ddb-3570-40ac-8e21-7f3f553568c6, complete=True, exec_jobs=['3523d54d-cf47-487e-a851-01da47ad743a', '8687df4e-a2ef-4862-829a-bf5652c1d541'], sche_jobs=[]> objects set(['lock']).
[DEBUG] 1425367499.688471 - XML-RPC-Session-0 - Finished command (group, promote).
[DEBUG] 1425367499.688594 - Executor-3 - Possible affected procedures set([]).
[DEBUG] 1425367499.688791 - Executor-3 - Unlocked procedure (e6139ddb-3570-40ac-8e21-7f3f553568c6).
[DEBUG] 1425367499.688947 - XML-RPC-Session-0 - Statement (INSERT INTO log (subject, reported, reporter, message, category, type) VALUES(%s, %s, %s, %s, %s, %s), Params(('group.promote', datetime.datetime(2015, 3, 3, 7, 24, 59), 'mysql.fabric.command', 'Finished command (group, promote).', 1, 2)).
[DEBUG] 1425367499.689550 - XML-RPC-Session-0 - Encoded packet: [1, '5ca1ab1e-a007-feed-f00d-cab3fe13249e', 1, 'ServerError: Server (b445213a-a538-11e4-bd92-40a8f01f6f10) is not a valid candidate slave due to the following reason: ({\'sql_error\': False, \'io_error\': u"error reconnecting to master \'user_fabric@10.58.46.143:7306\' - retry-time: 60  retries: 8", \'io_not_running\': True, \'sql_not_running\': False, \'is_not_configured\': False, \'is_not_running\': False}).', []]
[DEBUG] 1425367499.689984 - XML-RPC-Session-0 - Finishing request (<socket._socketobject object at 0x2643f30>) from (('10.58.46.143', 57637)) through thread (<SessionThread(XML-RPC-Session-0, started daemon 139700557825792)>).
[DEBUG] 1425367585.961504 - Thread-29 - purged 1 expired clients