Quantum| Tracing vmPRO Controller Commands (DRAFT - WAITING EDIT) |
Under vmPRO, Controller Commands, are logged in controller.log. Often, these will show what objects have been called om ControllerCommands.py. However, the log entries may not show exactly what the controller has done. This article follows one such scenario and shows how to interpret the entries in controller.log.
Here, the contents of ControllerCommands.py were shown by running update_backup_policy from the vmPRO GUI. As shown in the listing bellow, the command was given a PID and completed without error.
2014-02-11 10:06:48: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (318eceaa-5cc8-4b37-8391-2a1c6bd96e07)
2014-02-11 10:06:48: controller/INFO:: ControllerCommands.py:3339 Enter command: update_backup_policy (318eceaa-5cc8-4b37-8391-2a1c6bd96e07), pid: 16621
2014-02-11 10:06:49: controller/INFO:: ControllerCommands.py:3343 Exit command normally: update_backup_policy (318eceaa-5cc8-4b37-8391-2a1c6bd96e07), pid: 16621
Here, by looking at the support bundle, we can see that the customer has made policy changes seven times since the logs have rolled:
C:\Users\jmcnerny.QUANTUM\AppData\Local\Temp\7zO758E.tmp\controller.5 (1 hits)
Line 16543: 2013-12-16 06:36:02: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (5eb5c1a5-c6fd-41d8-a1f9-baee48925442)
C:\Users\jmcnerny.QUANTUM\AppData\Local\Temp\7zO761C.tmp\controller.3 (1 hits)
Line 8405: 2014-01-06 08:43:11: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (aa880c67-0cb7-4f37-ba35-5ab9d569287a)
C:\Users\jmcnerny.QUANTUM\AppData\Local\Temp\7zO7708.tmp\controller (5 hits)
Line 4680: 2014-02-11 10:06:48: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (318eceaa-5cc8-4b37-8391-2a1c6bd96e07)
Line 16216: 2014-02-17 06:28:45: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (47270d87-fb21-4634-94b1-110df84f829e)
Line 18755: 2014-02-18 14:13:58: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (084dfe29-c222-417f-b812-44bbdb5a33e2)
Line 18784: 2014-02-18 14:33:56: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (dd5c2840-54c7-4a51-9011-3c74d2539324)
Line 18789: 2014-02-18 14:38:53: controller/INFO:: ControllerCommands.py:3410 New controller command: update_backup_policy (fbc7b8b7-e7ba-40e0-80b3-6a388dae497b
However, this doesn't tell us what the controller changed. But by taking a closer look at ControllerCommands.py, we can see there are many different variables that can change in a Policy:
####Taken from ControllerCommands.py####
d = c.get_json_args_obj()
bp = backup_policy.read_by_uuid(self.db, d.get('uuid', ''))
if bp is None:
bp = backup_policy()
bp.parseFromDict(d)
if bp.get_uuid() is None or bp.get_uuid() == '':
bp.set_uuid(str(uuid.uuid4()))
if bp.get_target_id() is not None and bp.get_target_id() != '':
nas = backup_target.read_by_uuid(self.db, bp.get_target_id(), as_dict=True)
_t = Tomato.TomatoOps()
if not _t.tomato_check_mount_writable(nas):
ce.raise_sme_storage_not_writable(nas['name'])
bp.dbWrite(self.db)
return
####End of code####
Most importantly, we can see the changes are written to a database after the appropriate flow control is executed, as seen from the dbWrite method bp.dbWrite(self.db).
Since the controller gives use the UUID of the command, you can reference the SQL dump found in /var/ of the support bundle. If you are viewing the file as text a search for 'COPY command' will give you the command history. Here we can see UUID of the command fbc7b8b7-e7ba-40e0-80b3-6a388dae497b belongs to entry_id 124059. We saw this command from Line 18789 at 2014-02-18 14:38:53 in the first lastest iternation of the controller log.
entry_id
gen_id
uuid
cmd_id
json_args
target_uuid
caller_uuid
queued_time
begin_exec_time
end_exec_time
124069
2
fbc7b8b7-e7ba-40e0-80b3-6a388dae497b
update_backup_policy
{"schedule_week": ""
"retain_years": 0
"uuid": "41bbbce5-c044-6c00-5c9b-33d776ee48c5"
"copy_mode": "backup"
"enabled_month": 0
"retain_weeks": 0
124067
2
dd5c2840-54c7-4a51-9011-3c74d2539324
update_backup_policy
{"schedule_week": ""
"retain_years": 0
"uuid": "41bbbce5-c044-6c00-5c9b-33d776ee48c5"
"copy_mode": "backup"
"enabled_month": 0
"retain_weeks": 0
123441
2
47270d87-fb21-4634-94b1-110df84f829e
update_backup_policy
{"schedule_week": ""
"retain_years": 0
"uuid": "41bbbce5-c044-6c00-5c9b-33d776ee48c5"
"copy_mode": "backup"
"enabled_month": 0
"retain_weeks": 0
124059
2
084dfe29-c222-417f-b812-44bbdb5a33e2
update_backup_policy
{"schedule_week": ""
"retain_years": 0
"uuid": "41bbbce5-c044-6c00-5c9b-33d776ee48c5"
"copy_mode": "backup"
"enabled_month": 0
"retain_weeks": 0
We can also deduce that although the controller log rotation has caught 7 changes in the policy, our 'command' data table in the SQL dump still has only record of 4 of those commands. If you compare the log with the data table you'll see those are the most recent commands. Also you will find another UUID 41bbbce5-c044-6c00-5c9b-33d776ee48c5. A search further into the SQL dump will show that this UUID belongs to the Policy itself, stored in the 'backup_policy' table.
entry_id,
gen_id,
uuid,
name,
enabled,
enabled_week,
enabled_month,
enabled_year,
target_id,
email_enabled,
schedule,
schedule_week,
schedule_month,
schedule_year,
retain_days,
retain_weeks,
retain_months,
retain_years,
copy_mode,
copy_time_month,
copy_time_year,
is_default,
config_backup_enabled
1
\N
ac01656e-83f5-4926-8c4a-e58b56af53ce
DEFAULT
0
0
0
0
1
0
0
0
0
0
backup
use_current
use_current
1
1
2
18
41bbbce5-c044-6c00-5c9b-33d776ee48c5
Critical
1
0
0
0
f125c975-2b1f-49ce-9c24-554850f3a3c6
1
1800
120
0
0
0
backup
use_current
use_current
0
1
By reading both tables you can tell what each command (example command fbc7b8b7-e7ba-40e0-80b3-6a388dae497b) changed in the policy (example policy 41bbbce5-c044-6c00-5c9b-33d776ee48c5) from the controller logging.
This can be helful with many commands done by the controller in tracking back what has happened historically in the environment.
The appliance Data Base file collected in /var/log in a the vmPRO support bundle 'postgresql' can be viewed in any common text editor. However, the columns can misalign quickly leading to confusion. The above example illustrates this well. Everything surrounded by { } brackets really only belongs to the JSON column, effectively flushing everything to the right. This makes it seem like "retain_years": belongs to the 'target_uuid' column. It doesn't. There are better but more time intensive ways to look at the Data Base.
Using psql to interpret the appliance database.
Using pgadmin to interpret the appliance database.
This page was generated by the BrainKeeper Enterprise Wiki, © 2018 |