Data Backup and Recovery

Snap Creator 4.1 MySQL plugin quiesce operation fails

EEntressangle
3,830 Views
Hello,
 
using snapcreator 4.1.2, I'm trying to perform a backup of a mysql db hosted on a primary NAS, using mysql plugin. A snapmirror is also configured from primary NAS nas40-ctrl2 to backup NAS nas-ctrl2-LMG16.
Everything seems to be fine except the mysql "quiesce" which fails.
 
SCF-00038: Application quiesce for plug-in [mysql] failed with exit code [102]
How can I investigate this issue ?
 
Traces follow, thanks
 
Regards
 
2
Config is attached to policy object
3
Validating policy: SnapMirrorPolicy finished successfully
4
########## Detecting Data ONTAP mode for nas40-ctrl2 ##########
5
STORAGE-03031: Getting system version details of [nas40-ctrl2]
6
STORAGE-03032: Getting system version details of [nas40-ctrl2] finished successfully.
7
########## Agent validation ##########
8
Agent validation completed successfully for agent 10.35.84.19:9090
9
########## Plugin validation ##########
10
Plugin validation completed successfully for plugin mysql
11
Application auto discovery is not enabled skipping .
12
########## Running storage discovery ##########
13
STORAGE-02073: Retrieving SnapMirror relationships
14
STORAGE-02074: Retrieving SnapMirror relationships on controller [nas40-ctrl2] finished successfully
15
STORAGE-02070: Retrieving SnapMirror status
16
STORAGE-02071: Retrieving SnapMirror status on controller [NAS-ctrl2-LMG16] successful
17
STORAGE-02090: Listing Snapshot copies on volume [vol_db_data].
18
STORAGE-02091: Listing Snapshot copies on volume [vol_db_data] finished successfully.
19
########## Storage discovery finished successfully ! ##########
20
########## Pre Application Quiesce commands ##########
21
Pre application quiesce commands are not defined
22
Pre Application Quiesce commands finished successfully
23
Validate volume is not enabled skipping validate volume task.
24
########## Application Quiesce ##########
25
Application Quiesce for plugin : mysql
26
[10.35.84.19:9090 (4.1.1.1)] Operation failed. Reason: The watchdog killed the running operation. Verify that plugins/wrapper/wrapper binary has execute permission set. Increase the WRAPPER_TIMEOUT_IN_MSEC value in agent.properties if operations require more time to complete.
27
[10.35.84.19:9090(4.1.1.1)] SCF-00038: Application quiesce for plug-in [mysql] failed with exit code [102], continuing with backup.
28
Application quiesce result is empty  from plugin mysql. skipping config update operation
29
Application Quiesce for plugin : mysql finished successfully
30
########## Application Quiesce finished successfully ##########
31
########## POST APPLICATION QUIESCE COMMANDS ##########
32
Post application quiesce commands are not defined
33
########## POST APPLICATION QUIESCE COMMANDS FINISHED SUCCESSFULLY  ##########
34
########## Pre NTAP commands ##########
35
Pre NTAP commands are not defined
36
Pre NTAP commands finished successfully
37
########## Generating Info ASUP on nas40-ctrl2 ##########
38
STORAGE-01001: Creating AutoSupport message with event id [0], category [Backup Started], description [INFO: Snap Creator Framework 4.1.2 Backup for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, Started], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]]
39
STORAGE-01002: Creating AutoSupport message with event id [0], category [Backup Started], description [INFO: Snap Creator Framework 4.1.2 Backup for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, Started], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]] successful
40
ASUP finished successfully on nas40-ctrl2
41
########## Running NetApp Snapshot copy Rename on Primary devices ##########
42
########## Running NetApp Snapshot copy Rename on Secondary devices ##########
43
########## File system plug-in not defined. Skipping file system quiesce ##########
44
########## SNAPSHOT CREATE COMMANDS ##########
45
########## Snapshot copy create commands finished successfully ##########
46
########## Taking Snapshot copy on Primary nas40-ctrl2:vol_db_data ##########
47
STORAGE-02007: Creating Snapshot copy [titisnapshot-SnapMirrorPolicy_20151015173001] on volume [vol_db_data]
48
STORAGE-02008: Snapshot copy [titisnapshot-SnapMirrorPolicy_20151015173001] on volume [vol_db_data] created successfully
49
Snapshot copy create of titisnapshot-SnapMirrorPolicy_20151015173001 on nas40-ctrl2:vol_db_data Completed Successfully
50
########## File system plug-in not defined. Skipping file system unquiesce ##########
51
########## Pre Application Unquiesce commands ##########
52
Pre Application Unquiesce commands are not defined
53
Pre Application Unquiesce commands finished successfully 
54
########## Application Unquiesce ##########
55
Application Unquiesce for plugin: mysql
56
[10.35.84.19:9090 (4.1.1.1)] Operation failed. Verify that plugins/wrapper/wrapper binary has execute permission set. Increase the WRAPPER_TIMEOUT_IN_MSEC value in agent.properties if operations require more time to complete.
57
SCF-00033: Application unquiesce for plug-in [mysql] failed with exit code [102], proceeding with backup!
58
Application unquiesce result is empty from plugin mysql. skipping config update operation
59
Application UnQuiesce for plugin: mysql finished successfully
60
########## Application Unquiesce finished successfully ##########
61
########## Metadata Snapshot Create Commands Started  ##########
62
########## POST APPLICATION UNQUIESCE COMMANDS ##########
63
Post application unquiesce commands are not defined
64
########## POST APPLICATION UNQUIESCE COMMANDS FINISHED SUCCESSFULLY  ##########
65
########## Generating Info ASUP on nas40-ctrl2 ##########
66
STORAGE-01001: Creating AutoSupport message with event id [0], category [Backup Completed], description [INFO: Snap Creator Framework 4.1.2 Backup for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, finished], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]]
67
STORAGE-01002: Creating AutoSupport message with event id [0], category [Backup Completed], description [INFO: Snap Creator Framework 4.1.2 Backup for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, finished], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]] successful
68
ASUP finished successfully on nas40-ctrl2
69
Generating Info ASUP on NAS-ctrl2-LMG16
70
STORAGE-01001: Creating AutoSupport message with event id [0], category [SnapMirror Backup of NAS-ctrl2-LMG16:vol_db_data Started], description [INFO: Snap Creator Framework 4.1.2 SnapMirror Backup of NAS-ctrl2-LMG16:vol_db_data for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, Started], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]]
71
STORAGE-01002: Creating AutoSupport message with event id [0], category [SnapMirror Backup of NAS-ctrl2-LMG16:vol_db_data Started], description [INFO: Snap Creator Framework 4.1.2 SnapMirror Backup of NAS-ctrl2-LMG16:vol_db_data for titisnapshot ACTION: backup POLICY: SnapMirrorPolicy Plugin: mysql [Supported] Volumes: vol_db_data, Started], level [INFO], hostname [LMG40MDFOAM2 [10.35.84.19:9090]] successful
72
########## Running SnapMirror Update for source relationship nas40-ctrl2:vol_db_data ##########
73
STORAGE-02083: Updating SnapMirror relationship [nas40-ctrl2:vol_db_data -> NAS-ctrl2-LMG16:vol_db_data].
74
STORAGE-02084: Updating SnapMirror relationship [nas40-ctrl2:vol_db_data -> NAS-ctrl2-LMG16:vol_db_data] started successfully.
75
########## Post Data Transfer commands ##########
76
No commands defined
77
Post Data Transfer commands finished successfully
78
########## Post NTAP commands ##########
79
No Post NTAP commands defined
80
Post NTAP commands finished successfully
81
########## ARCHIVE COMMANDS ##########
82
Archive commands are not defined
83
########## Running Snapshot copy Delete on Primary ##########
84
Currently 5 snapshots exist. The retention count is specified as 1. The excess snapshots could not be deleted because they are not older than the retention age (1 days) for nas40-ctrl2:vol_db_data
85
########## Application cleanup ##########
86
Performing cleanup on : mysql
87
[10.35.84.19:9090 (4.1.1.1)] Operation failed. Verify that plugins/wrapper/wrapper binary has execute permission set. Increase the WRAPPER_TIMEOUT_IN_MSEC value in agent.properties if operations require more time to complete.
88
[10.35.84.19:9090(4.1.1.1)] SCF-00074: Cleanup for plug-in [mysql] failed with error [null] and exit code [102], Exiting!
89
Task: appCleanup with config:SnapMirrorProfile@MySqlConfig3 failed
90
########## Agent Workflow Finalization ##########
91
Agent Workflow Finalization started
92
[10.35.84.19:9090 (4.1.1.1)] Finalized workflow with id 35
93
Agent Workflow Finalization finished successfully
94
########## Snap Creator Framework 4.1.2 failed ##########
95
Pre Exit commands are not defined. Skipping !
1 ACCEPTED SOLUTION

EEntressangle
3,762 Views

Solved issue. In MySQL, you have to be careful about what is set in "Host" field. I had put the IP@ of Mysql server, whereas the host name was needed to match the mysql user corresponding host. I put "localhost" and it works now.

 

 [2015-10-19 15:29:28,432] INFO: Application Quiesce for plugin : mysql
[2015-10-19 15:29:39,041] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing databases
[2015-10-19 15:29:39,041] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing database bmsc
[2015-10-19 15:29:39,041] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Connection to bmsc successfully established
[2015-10-19 15:29:39,041] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Executing sql command 'flush tables with read lock' for database bmsc
[2015-10-19 15:29:39,042] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Executing sql command 'flush logs' for database bmsc
[2015-10-19 15:29:39,042] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing database bmsc finished successfully
[2015-10-19 15:29:39,042] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing databases finished successfully

View solution in original post

3 REPLIES 3

ssaravan
3,806 Views

Please check agent logs to find out more details to find out what is causing quiesce failure.

EEntressangle
3,801 Views

Thanks for your help.

 

I got the following logs :

 

[2015-10-16 15:33:14,663] INFO: Application Quiesce for plugin : mysql
12
[2015-10-16 15:33:25,014] INFO: [10.35.84.19:9090 (4.1.1.1)] (Fri Oct 16 15:33:22 2015) Quiescing databases
13
[2015-10-16 15:33:25,014] INFO: [10.35.84.19:9090 (4.1.1.1)] (Fri Oct 16 15:33:22 2015) Quiescing database bmsc
14
[2015-10-16 15:33:25,014] ERROR: [10.35.84.19:9090 (4.1.1.1)] (Fri Oct 16 15:33:22 2015) #42000Access denied; you need (at least one of) the RELOAD privilege(s) for this operation
15
[2015-10-16 15:33:25,014] ERROR: [10.35.84.19:9090 (4.1.1.1)] (Fri Oct 16 15:33:22 2015) [mys-00003] Quiescing databases finished with errors
16
[2015-10-16 15:33:25,015] ERROR: [10.35.84.19:9090(4.1.1.1)] SCF-00038: Application quiesce for plug-in [mysql] failed with exit code [1], continuing with backup.
17
[2015-10-16 15:33:25,016] INFO: Application quiesce result is empty  from plugin mysql. skipping config update operation
 
So I entered the following command in mysql CLI :
 
mysql>  grant RELOAD on *.* to 'root'@'localhost';
Query OK, 0 rows affected (0.00 sec)
 
But unfortunately problem still persists. Any idea ?
 
Thanks,
 
Regards

EEntressangle
3,763 Views

Solved issue. In MySQL, you have to be careful about what is set in "Host" field. I had put the IP@ of Mysql server, whereas the host name was needed to match the mysql user corresponding host. I put "localhost" and it works now.

 

 [2015-10-19 15:29:28,432] INFO: Application Quiesce for plugin : mysql
[2015-10-19 15:29:39,041] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing databases
[2015-10-19 15:29:39,041] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing database bmsc
[2015-10-19 15:29:39,041] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Connection to bmsc successfully established
[2015-10-19 15:29:39,041] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Executing sql command 'flush tables with read lock' for database bmsc
[2015-10-19 15:29:39,042] DEBUG: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Executing sql command 'flush logs' for database bmsc
[2015-10-19 15:29:39,042] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing database bmsc finished successfully
[2015-10-19 15:29:39,042] INFO: [10.35.84.19:9090 (4.1.1.1)] (Mon Oct 19 15:29:36 2015) Quiescing databases finished successfully

Public