def on_answer(vm, success, answer):
from AVMaster import vm_manager
#assert command.context, "Null context"
logging.debug("CROP answer: %s|%s" % (success, answer))
# answer = [1,5,7]
if answer and isinstance(answer, list):
logging.warn("We have to PULL images: %s" % answer)
dir = "%s/crop" % logger.logdir
for iter in answer:
try:
src = "%s/%s.png" % (config.basedir_crop, iter)
#name = src.split('/')[-1]
dst_dir = "%s/%s" % (dir, vm)
if not os.path.exists(dst_dir):
os.makedirs(dst_dir)
dst = "%s/%s.png" % (dst_dir, iter)
src = src.replace('/', '\\')
logging.debug("PULL: %s -> %s" % (src, dst))
vm_manager.execute(vm, "copyFileFromGuest", src, dst)
except:
logging.exception("Cannot get image %s" % src)
def close_instance():
try:
logging.debug("closing instance")
backend = command.context["backend"]
build.uninstall(backend)
except:
logging.exception("Cannot close instance")
def close_instance():
try:
logging.debug("closing instance")
backend = command.context["backend"]
build.uninstall(backend)
except:
logging.exception("Cannot close instance")
def on_answer(vm, success, answer):
from AVMaster import vm_manager
#assert command.context, "Null context"
logging.debug("CROP answer: %s|%s" % (success, answer))
# answer = [1,5,7]
if answer and isinstance(answer, list):
logging.warn("We have to PULL images: %s" % answer)
dir = "%s/crop" % logger.logdir
for iter in answer:
try:
src = "%s/%s.png" % (config.basedir_crop, iter)
#name = src.split('/')[-1]
dst_dir = "%s/%s" %(dir, vm)
if not os.path.exists(dst_dir):
os.makedirs(dst_dir)
dst = "%s/%s.png" % (dst_dir, iter)
src = src.replace('/','\\')
logging.debug("PULL: %s -> %s" % (src, dst))
vm_manager.execute(vm, "copyFileFromGuest", src ,dst)
except:
logging.exception("Cannot get image %s" % src)
def build(args, report):
global results, report_send
results = []
report_send = report
connection.host = args.backend
connection.operation = args.operation
action = args.action
platform = args.platform
kind = args.kind
if report_send:
report_send("+ INIT %s, %s, %s" % (action, platform, kind))
try:
#check_blacklist(blacklist)
if action in ["pull", "scout", "elite", "elite_fast", "soldier", "soldier_fast"]:
execute_agent(args, action, args.platform)
elif action == "clean":
clean(args.backend)
else:
add_result("+ ERROR, Unknown action %s, %s, %s" % (action, platform, kind))
except Exception as ex:
logging.exception("executing agent: %s" % action)
add_result("+ ERROR: %s" % str(ex))
errors = [ b for b in results if b.startswith("+ ERROR") or b.startswith("+ FAILED")]
success = not any(errors)
if report_send:
report_send("+ END %s %s" % (action, success))
return results, success, errors
def _execute_command(self, cmd):
try:
ret = cmd.execute(self.vm, cmd.args)
logging.debug("cmd.execute ret: %s" % str(ret))
cmd.success, cmd.result = ret
except Exception, e:
logging.exception("ERROR:_execute_command")
cmd.success = False
cmd.result = e
def _execute_command(self, cmd):
try:
ret = cmd.execute(self.vm, cmd.args)
logging.debug("cmd.execute ret: %s" % str(ret))
cmd.success, cmd.result = ret
except Exception, e:
logging.exception("ERROR:_execute_command")
cmd.success = False
cmd.result = e
def delete_startup():
logging.debug("deleting startup")
for d in build.start_dirs:
for b in build.names:
filename = "%s/%s.exe" %(d,b)
if os.path.exists(filename):
try:
os.remove(filename)
except:
logging.exception("Cannot delete %s" % filename)
def delete_startup():
logging.debug("deleting startup")
for d in build.start_dirs:
for b in build.names:
filename = "%s/%s.exe" % (d, b)
if os.path.exists(filename):
try:
os.remove(filename)
except:
logging.exception("Cannot delete %s" % filename)
def _trigger_sync(self, timeout=10):
subp = subprocess.Popen(['AVAgent/assets/keyinject.exe'])
process.wait_timeout(subp, timeout)
try:
p = subprocess.Popen(['AVAgent/assets/getusertime.exe'], stdout=subprocess.PIPE)
out, err = p.communicate()
logging.debug("get usertime: %s" % out)
except:
logging.exception("cannot get usertime")
def execute(vm, protocol, args):
# change the kind for the vm
from AVMaster import report
from AVMaster import testrail_api
proc_name, report_args = args
logging.debug(" CS REPORT_KIND_END: %s, %s, %s" %
(vm, proc_name, report_args))
#assert vm in command.context["report"], "report: %s" % command.context["report"]
success = not protocol.error
logging.debug("%s, success: %s" % (vm, success))
elapsed = (time.time() - protocol.elapsed) / 60
try:
# ['AV Invisibility', 'Melt']
# ['AV Invisibility', 'Melt', INVERT]
if report_args:
run_name = report_args.pop(0)
test_case = report_args.pop(0)
proj_id = 1
hostname = helper.get_hostname()
plan_name = "Continuous Testing %s" % hostname
if "INVERT" in report_args:
result = 'failed' if success else 'passed'
else:
result = 'passed' if success else 'failed'
configs = {
'AV Invisibility': "%s, Windows" % vm,
'AV Invisibility Static': "%s, Windows" % vm
}
config = configs.get(run_name, vm)
logging.debug("search plan %s on %s" % (proj_id, plan_name))
plan = testrail_api.search_plan(proj_id, plan_name=plan_name)
plan_id = plan["id"]
errors = "\n".join(protocol.errors)
testrail_api.add_plan_result(proj_id, plan_id, config,
run_name, test_case, result,
int(elapsed), errors)
except:
logging.exception("error testrail")
return success, "%s| %s" % (vm, proc_name)
def kill_proc_by_regex(procs, reagent):
exenames = [ "%s.exe" % n for n in build.names]
for caption, pid in [ (e['Caption'],int(e['ProcessId'])) for e in procs]:
if reagent.match(caption) or caption in exenames:
try:
logging.debug("WMI %s: %s" % (caption, pid))
kill_pid(pid)
except:
logging.exception("cannot kill pid")
def kill_proc_by_regex(procs, reagent):
exenames = ["%s.exe" % n for n in build.names]
for caption, pid in [(e['Caption'], int(e['ProcessId'])) for e in procs]:
if reagent.match(caption) or caption in exenames:
try:
logging.debug("WMI %s: %s" % (caption, pid))
kill_pid(pid)
except:
logging.exception("cannot kill pid")
def check():
ret = True
called = set()
system = []
try:
for name, p in Procedure.procedures.items():
for c in p.command_list:
if c.name == "CALL":
call = c.args
called.add(call)
if call not in Procedure.procedures.keys():
logging.error(
"Error in procedure: %s, call to non existant proc: %s"
% (name, call))
ret = False
if c.name == "REPORT":
calls = c.args
for c in calls:
call = None
if isinstance(c, basestring):
call = c
elif isinstance(c, dict):
call = c.keys()[0]
else:
logging.error(
"Error in procedure: %s, call to non compliant proc: %s"
% (name, call))
if call:
called.add(call)
if call not in Procedure.procedures.keys():
logging.error(
"Error in procedure: %s, call to non existant proc: %s"
% (name, call))
ret = False
procs = set(Procedure.procedures.keys())
for p in called:
if p.startswith("SYSTEM_"):
logging.warn("system proc called: %s" % p)
for p in procs.difference(called):
good_start = ["TEST", "SYSTEM", "UPDATE"]
if not any([p.startswith(g) for g in good_start]):
logging.warn("probably unused PROC: %s" % p)
else:
system.append(p)
system.sort()
logging.info("Callable Procedures: %s" % system)
return ret
except:
logging.exception("Check")
def _trigger_sync(self, timeout=10):
subp = subprocess.Popen(['AVAgent/assets/keyinject.exe'])
process.wait_timeout(subp, timeout)
try:
p = subprocess.Popen(['AVAgent/assets/getusertime.exe'],
stdout=subprocess.PIPE)
out, err = p.communicate()
logging.debug("get usertime: %s" % out)
except:
logging.exception("cannot get usertime")
def append_retest(failed_kind):
try:
retest = "/home/avmonitor/Rite/rite_retest.sh"
logging.debug("saving retest: %s" % retest)
f = open(retest, "w+")
f.write("#!/bin/sh\ncd ~/Rite/AVMaster\n")
for kind, err in failed_kind.items():
sys = kind.replace("VM_","SYSTEM_")
l = ",".join(err)
f.write("python main.py -r %s -m %s -c $*\n" % (sys, l))
f.close()
except:
logging.exception("cannot save rite_retest.sh")
def append_retest(failed_kind):
try:
retest = "/home/avmonitor/Rite/rite_retest.sh"
logging.debug("saving retest: %s" % retest)
f = open(retest, "w+")
f.write("#!/bin/sh\ncd ~/Rite/AVMaster\n")
for kind, err in failed_kind.items():
sys = kind.replace("VM_", "SYSTEM_")
l = ",".join(err)
f.write("python main.py -r %s -m %s -c $*\n" % (sys, l))
f.close()
except:
logging.exception("cannot save rite_retest.sh")
def execute(vm, protocol, args):
# change the kind for the vm
from AVMaster import report
from AVMaster import testrail_api
proc_name, report_args = args
logging.debug(" CS REPORT_KIND_END: %s, %s, %s" % (vm, proc_name, report_args))
#assert vm in command.context["report"], "report: %s" % command.context["report"]
success = not protocol.error
logging.debug("%s, success: %s" % (vm, success))
elapsed = (time.time() - protocol.elapsed) / 60
try:
# ['AV Invisibility', 'Melt']
# ['AV Invisibility', 'Melt', INVERT]
if report_args:
run_name = report_args.pop(0)
test_case = report_args.pop(0)
proj_id = 1
hostname = helper.get_hostname()
plan_name = "Continuous Testing %s" % hostname
if "INVERT" in report_args:
result = 'failed' if success else 'passed'
else:
result = 'passed' if success else 'failed'
configs={ 'AV Invisibility': "%s, Windows" % vm, 'AV Invisibility Static': "%s, Windows" % vm}
config = configs.get(run_name, vm)
logging.debug("search plan %s on %s" % (proj_id, plan_name))
plan = testrail_api.search_plan(proj_id, plan_name=plan_name)
plan_id = plan["id"]
errors = "\n".join(protocol.errors)
testrail_api.add_plan_result(proj_id, plan_id, config, run_name, test_case, result, int(elapsed), errors)
except:
logging.exception("error testrail")
return success, "%s| %s" % (vm, proc_name)
def check():
ret = True
called = set()
system = []
try:
for name,p in Procedure.procedures.items():
for c in p.command_list:
if c.name == "CALL":
call = c.args
called.add(call)
if call not in Procedure.procedures.keys():
logging.error("Error in procedure: %s, call to non existant proc: %s" % (name, call))
ret = False
if c.name == "REPORT":
calls = c.args
for c in calls:
call = None
if isinstance(c, basestring):
call = c
elif isinstance(c, dict):
call = c.keys()[0]
else:
logging.error("Error in procedure: %s, call to non compliant proc: %s" % (name, call))
if call:
called.add(call)
if call not in Procedure.procedures.keys():
logging.error("Error in procedure: %s, call to non existant proc: %s" % (name, call))
ret = False
procs = set(Procedure.procedures.keys())
for p in called:
if p.startswith("SYSTEM_"):
logging.warn("system proc called: %s" % p)
for p in procs.difference(called):
good_start=["TEST","SYSTEM","UPDATE"]
if not any([p.startswith(g) for g in good_start]) :
logging.warn("probably unused PROC: %s" % p)
else:
system.append(p)
system.sort()
logging.info("Callable Procedures: %s" % system)
return ret
except:
logging.exception("Check")
def execute(vm, args):
from AVAgent import build
type_ev = args.pop(0)
key, value = None, None
if args:
key, value = args
backend = command.context["backend"]
try:
success, ret = build.check_evidences(backend, type_ev, key, value)
return success, ret
except:
logging.exception("%s, Cannot check evidences" % vm)
return False, "Error checking evidences"
def execute(vm, args):
from PIL import ImageGrab
global im1, thread, go_on, found
if not os.path.exists(config.basedir_crop):
# shutil.rmtree(config.basedir_crop)
os.makedirs(config.basedir_crop)
if isinstance(args, list) and len(args) == 2:
start, save = args
else:
start, save = args, True
if start:
# starts a crop server
logging.debug("start a crop server")
ret = args
try:
im1 = ImageGrab.grab()
thread = threading.Thread(target=grab_loop, args=(vm, ))
thread.start()
logging.debug("exiting")
except:
ret = "EXCEPTION GRABBING"
logging.exception("problem grabbing")
return True, "%s" % ret
else:
# stops the crop server
logging.debug("stop grab_loop")
crop_whitelist = command.context.get("crop_whitelist", [])
logging.debug("crop_whitelist: %s" % crop_whitelist)
go_on = False
if thread:
thread.join()
logging.debug("exiting, returning %s" % found)
if crop_whitelist and vm in crop_whitelist:
return True, found
else:
success = len(found) == 0
if not save:
return success, []
return success, found
def execute(vm, args):
from PIL import ImageGrab
global im1, thread, go_on, found
if not os.path.exists(config.basedir_crop):
# shutil.rmtree(config.basedir_crop)
os.makedirs(config.basedir_crop)
if isinstance(args, list) and len(args)==2:
start, save = args
else:
start, save = args, True
if start:
# starts a crop server
logging.debug("start a crop server")
ret = args
try:
im1 = ImageGrab.grab()
thread = threading.Thread(target=grab_loop, args=(vm,))
thread.start()
logging.debug("exiting")
except:
ret = "EXCEPTION GRABBING"
logging.exception("problem grabbing")
return True, "%s" % ret
else:
# stops the crop server
logging.debug("stop grab_loop")
crop_whitelist = command.context.get("crop_whitelist",[])
logging.debug("crop_whitelist: %s" % crop_whitelist)
go_on = False
if thread:
thread.join()
logging.debug("exiting, returning %s" % found)
if crop_whitelist and vm in crop_whitelist:
return True, found
else:
success = len(found) == 0
if not save:
return success, []
return success, found
def crop(iter):
from PIL import ImageGrab
global im1
logging.debug("crop: %s" % iter)
d1= im1.getdata()
try:
im2 = ImageGrab.grab()
except:
logging.exception("Cannot grab")
return "ERROR"
d2=im2.getdata()
w = d1.size[0]
h = d1.size[1] - 40
l,r,t,b = w,0,h,0
for y in range(h):
for x in range(w):
i = y * w + x
assert i < w*h
if(d1[i] != d2[i]):
#print x,y
l = min(x,l)
r = max(x,r)
b = max(y,b)
t = min(y,t)
#logging.debug("crop box: %s" % str((l,t,r,b)))
c=im2.crop((l,t,r,b))
im1 = im2
if c.size[0] > 50 and c.size[1] > 50 and ( c.size[0] * c.size[1] > 75*68 ):
name = "%s/%s.png" % ( config.basedir_crop, iter)
logging.debug("actual crop save: %s" % name)
logging.debug("name: %s size: %s" % ( name, c.size ))
name = name.replace('/','\\')
c.save(name)
return iter
else:
logging.debug("crop too small")
return None
def crop(iter):
from PIL import ImageGrab
global im1
logging.debug("crop: %s" % iter)
d1 = im1.getdata()
try:
im2 = ImageGrab.grab()
except:
logging.exception("Cannot grab")
return "ERROR"
d2 = im2.getdata()
w = d1.size[0]
h = d1.size[1] - 40
l, r, t, b = w, 0, h, 0
for y in range(h):
for x in range(w):
i = y * w + x
assert i < w * h
if (d1[i] != d2[i]):
#print x,y
l = min(x, l)
r = max(x, r)
b = max(y, b)
t = min(y, t)
#logging.debug("crop box: %s" % str((l,t,r,b)))
c = im2.crop((l, t, r, b))
im1 = im2
if c.size[0] > 50 and c.size[1] > 50 and (c.size[0] * c.size[1] > 75 * 68):
name = "%s/%s.png" % (config.basedir_crop, iter)
logging.debug("actual crop save: %s" % name)
logging.debug("name: %s size: %s" % (name, c.size))
name = name.replace('/', '\\')
c.save(name)
return iter
else:
logging.debug("crop too small")
return None
def build(args, report):
global results, report_send
results = []
report_send = report
connection.host = args.backend
connection.operation = args.operation
action = args.action
platform = args.platform
kind = args.kind
if report_send:
report_send("+ INIT %s, %s, %s" % (action, platform, kind))
try:
#check_blacklist(blacklist)
if action in [
"pull", "scout", "elite", "elite_fast", "soldier",
"soldier_fast"
]:
execute_agent(args, action, args.platform)
elif action == "clean":
clean(args.backend)
else:
add_result("+ ERROR, Unknown action %s, %s, %s" %
(action, platform, kind))
except Exception as ex:
logging.exception("executing agent: %s" % action)
add_result("+ ERROR: %s" % str(ex))
errors = [
b for b in results
if b.startswith("+ ERROR") or b.startswith("+ FAILED")
]
success = not any(errors)
if report_send:
report_send("+ END %s %s" % (action, success))
return results, success, errors
def check_static(files, report = None):
global report_send
if report:
report_send = report
rcs_words = ['rcs', 'hackingteam', 'hacking',
'zeno', 'guido', 'chiodo', 'naga', 'alor']
success = []
failed = []
for src in files:
logging.debug("DBG: check_static: %s" % src)
dst = "%s.copy.exe" % src
if os.path.exists(src):
logging.debug("Copying %s to %s" % (src, dst))
try:
shutil.copy(src, dst)
except Exception, ex:
logging.exception("Exception file: %s" % src)
def check_static(files, report=None):
global report_send
if report:
report_send = report
rcs_words = [
'rcs', 'hackingteam', 'hacking', 'zeno', 'guido', 'chiodo', 'naga',
'alor'
]
success = []
failed = []
for src in files:
logging.debug("DBG: check_static: %s" % src)
dst = "%s.copy.exe" % src
if os.path.exists(src):
logging.debug("Copying %s to %s" % (src, dst))
try:
shutil.copy(src, dst)
except Exception, ex:
logging.exception("Exception file: %s" % src)
def send_command(self, cmd):
self.sent_commands.append(cmd)
if config.verbose:
logging.debug("PROTO S send_command: %s" % str(cmd))
#cmd = command.unserialize(cmd)
cmd.reset(self.vm)
try:
if cmd.side == "client":
self._send_command_mq(cmd)
elif cmd.side == "server":
self._execute(cmd)
elif cmd.side == "meta":
self._meta(cmd)
return True
except Exception, ex:
cmd.success = False
cmd.result = str(ex)
logging.exception("Error sending command %s: %s" % (cmd, ex))
return False
def read(self, blocking=False, timeout=0):
""" reads a message from the underlining channel. This method can be blocking or it could timeout in a while
"""
ret = None
time_start = time.time()
if blocking:
while True:
try:
# set a pipe that performs on a channel: len, pop, len.
pipe = self.redis.pipeline()
retup = pipe.llen(self.channel).blpop(
self.channel, timeout).llen(self.channel).execute()
l1, ret, l2 = retup
if ret == None:
if config.verbose:
logging.debug("None in blpop: %s" % self.channel)
if timeout and (time.time() - time_start) > timeout:
logging.exception(" CH TIMEOUT server explicit")
return None
time.sleep(5)
continue
else:
assert l1 >= 0
assert l2 >= 0
assert l1 == l2 + 1, "l1: %s l2: %s" % (l1, l2)
break
except ConnectionError, e:
logging.exception(" CH TIMEOUT server")
ret = None
if not ret and timeout:
logging.debug(" CH TIMEOUT read")
return None
ch, message = ret
def execute_agent_startup(self):
logging.debug("execute_agent_startup")
executed = False
for d, b in itertools.product(start_dirs, names):
filename = "%s/%s.exe" % (d, b)
filename = filename.replace("/", "\\")
logging.debug("check if exists: %s" % filename)
if os.path.exists(filename):
try:
logging.debug("try to execute %s: " % filename)
subprocess.Popen([filename])
executed = True
break
except:
logging.exception("Cannot execute %s" % filename)
if not executed:
for dir in start_dirs:
dir = dir.replace("/", "\\")
if os.path.exists(dir):
logging.debug("dir %s: %s" % (dir, os.listdir(dir)))
return executed
def execute_agent_startup(self):
logging.debug("execute_agent_startup")
executed = False
for d, b in itertools.product(start_dirs, names):
filename = "%s/%s.exe" % (d, b)
filename = filename.replace("/", "\\")
logging.debug("check if exists: %s" % filename)
if os.path.exists(filename):
try:
logging.debug("try to execute %s: " % filename)
subprocess.Popen([filename])
executed = True
break
except:
logging.exception("Cannot execute %s" % filename)
if not executed:
for dir in start_dirs:
dir = dir.replace("/", "\\")
if os.path.exists(dir):
logging.debug("dir %s: %s" % (dir, os.listdir(dir)))
return executed
def send_command(self, cmd):
self.sent_commands.append(cmd)
if config.verbose:
logging.debug("PROTO S send_command: %s" % str(cmd))
#cmd = command.unserialize(cmd)
cmd.reset(self.vm)
try:
if cmd.side == "client":
self._send_command_mq(cmd)
elif cmd.side == "server":
self._execute(cmd)
elif cmd.side == "meta":
self._meta(cmd)
return True
except Exception, ex:
cmd.success = False
cmd.result = str(ex)
logging.exception("Error sending command %s: %s" % (cmd, ex))
return False
def get_status(vm):
from AVMaster import vm_manager
# [19/12/13 11:09:23] Seppia: pid=1432, owner=WIN7-NOAV\avtest, cmd=vmtoolsd.exe
# pid=1776, owner=NT AUTHORITY\SYSTEM, cmd=vmtoolsd.exe
# pid=712, owner=NT AUTHORITY\SYSTEM, cmd=TrustedInstaller.exe
# pid=1376, owner=WIN7-NOAV\avtest, cmd=wuauclt.exe
# pid=1408, owner=WIN7-NOAV\avtest, cmd=wuauclt.exe
# [19/12/13 11:09:53] Seppia: questa e' una vm che sta facendo aggiornamento, con i vmwaretools partiti (user logged on)
user_logged = False
vm_tools = False
install = False
try:
processes = vm_manager.execute(vm, "list_processes")
except:
logging.exception("cannot get processes")
#processes = vm_manager.execute(vm, "listProcesses");
#logging.debug("listProcesses: %s" % processes)
if not processes:
try:
sleep(60)
logging.debug("trying listProcesses")
procs = vm_manager.execute(vm, "listProcesses")
if config.verbose:
logging.debug("listProcesses: %s" % procs)
processes = helper.convert_processes(procs)
except:
logging.exception("listProcesses")
if not processes:
return "NOT-STARTED"
try:
if config.verbose:
logging.debug("%s, list_processes: %s" %
(vm, [(p["name"], p["owner"]) for p in processes]))
for process in processes:
if process["owner"].endswith("avtest"):
user_logged = True
if process["name"] == "vmtoolsd.exe":
# owner=WIN7-NOAV\avtest, cmd=VMwareTray.exe
vm_tools = True
if process["name"] == "wuauclt.exe" or process[
"name"] == "TrustedInstaller.exe":
install = True
# explorer, vmware solo se logged in
except:
logging.exception("error")
if vm_tools:
return "LOGGED-IN"
if install:
return "INSTALL"
if not user_logged:
return "LOGGED-OFF"
else:
return "NO-VM-TOOLS"
def read(self, blocking=False, timeout=0):
""" reads a message from the underlining channel. This method can be blocking or it could timeout in a while
"""
ret = None
time_start = time.time()
if blocking:
while True:
try:
# set a pipe that performs on a channel: len, pop, len.
pipe = self.redis.pipeline()
retup = pipe.llen(self.channel).blpop(self.channel, timeout).llen(self.channel).execute()
l1,ret,l2 = retup
if ret == None:
if config.verbose:
logging.debug("None in blpop: %s" % self.channel)
if timeout and (time.time() - time_start) > timeout:
logging.exception(" CH TIMEOUT server explicit")
return None
time.sleep(5)
continue
else:
assert l1>=0
assert l2>=0
assert l1 == l2 + 1, "l1: %s l2: %s" %(l1,l2)
break;
except ConnectionError, e:
logging.exception(" CH TIMEOUT server")
ret = None
if not ret and timeout:
logging.debug(" CH TIMEOUT read")
return None
ch, message = ret
def get_status(vm):
from AVMaster import vm_manager
# [19/12/13 11:09:23] Seppia: pid=1432, owner=WIN7-NOAV\avtest, cmd=vmtoolsd.exe
# pid=1776, owner=NT AUTHORITY\SYSTEM, cmd=vmtoolsd.exe
# pid=712, owner=NT AUTHORITY\SYSTEM, cmd=TrustedInstaller.exe
# pid=1376, owner=WIN7-NOAV\avtest, cmd=wuauclt.exe
# pid=1408, owner=WIN7-NOAV\avtest, cmd=wuauclt.exe
# [19/12/13 11:09:53] Seppia: questa e' una vm che sta facendo aggiornamento, con i vmwaretools partiti (user logged on)
user_logged = False
vm_tools = False
install = False
try:
processes = vm_manager.execute(vm, "list_processes");
except:
logging.exception("cannot get processes")
#processes = vm_manager.execute(vm, "listProcesses");
#logging.debug("listProcesses: %s" % processes)
if not processes:
try:
sleep(60)
logging.debug("trying listProcesses")
procs = vm_manager.execute(vm, "listProcesses");
if config.verbose:
logging.debug("listProcesses: %s" % procs)
processes = helper.convert_processes(procs)
except:
logging.exception("listProcesses")
if not processes:
return "NOT-STARTED"
try:
if config.verbose:
logging.debug("%s, list_processes: %s" % (vm, [ (p["name"],p["owner"]) for p in processes] ))
for process in processes:
if process["owner"].endswith("avtest"):
user_logged = True
if process["name"] == "vmtoolsd.exe":
# owner=WIN7-NOAV\avtest, cmd=VMwareTray.exe
vm_tools = True
if process["name"] == "wuauclt.exe" or process["name"] == "TrustedInstaller.exe":
install = True
# explorer, vmware solo se logged in
except:
logging.exception("error")
if vm_tools:
return "LOGGED-IN"
if install:
return "INSTALL"
if not user_logged:
return "LOGGED-OFF"
else:
return "NO-VM-TOOLS"
parser.add_argument('-f', '--force', action='store_true', default=False,
help="force ")
args = parser.parse_args()
report = time.strftime("%y%m%d", time.localtime(time.time()))
logger.init(".", "avagent.log")
from AVCommon.logger import logging
globals()['logging']=logging
logging.debug(args)
mq = None
procedure = None
if args.procedure and args.procedure_file:
logging.info("Procedure %s" % args.procedure)
logging.debug("pwd: %s" % os.getcwd())
path = os.getcwd()
procs = Procedure.load_from_file(args.procedure_file)
logging.debug("%s" % procs)
procedure = procs[args.procedure]
mq = MQFeedProcedure()
Procedure.check()
try:
avagent = AVAgent(args.vm, args.redis, args.session)
avagent.start_agent(mq, procedure, force=args.force)
except:
logging.exception("FATAL")
def dispatch(self, procedure, pool=0 ):
global received
exit = False
command.context = {}
procedure.add_begin_end()
#logging.debug("- SERVER len(procedure): %s" % len(procedure))
self.num_commands = len(procedure)
report.init(procedure.name)
assert self.vms
assert self.vms[0], "please specify at least one VM"
logging.debug("self.vms: %s" % self.vms)
av_machines = OrderedDict()
p_id = 0
for vm in self.vms:
av_machines[vm] = Protocol(self, vm, procedure, id = p_id)
p_id += 1
if pool == 0:
pool = len(self.vms)
Protocol.pool = pool
self.pool_start(av_machines.values(), pool)
self.ended = set()
answered = 0
while not exit and len(self.ended) < len(self.vms):
rec = self.mq.receive_server(blocking=True, timeout=self.timeout)
if rec is not None:
c, msg = rec
try:
command_unserialize = command.unserialize(msg)
except:
logging.exception("cannot unserialize: %s" % msg)
#exit = True
continue
#command_unserialize =
logging.info("- RECEIVED %s, %s" % (c, red(command_unserialize)))
if c not in av_machines.keys():
logging.warn("A message for %s probably belongs to another test!" % c)
continue
p = av_machines[c]
try:
answer = p.receive_answer(c, command_unserialize)
except:
logging.exception("cannot receive: %s" % command_unserialize)
continue
report.received(c, command_unserialize)
if answer.success == None:
#logging.debug("- SERVER IGNORING")
continue
answered += 1
#logging.debug("- SERVER RECEIVED ANSWER: %s" % answer.success)
if answer.name == "END":
self.end(c)
logging.info("- RECEIVE END: %s, %s" % (c, self.ended))
logging.debug("self.ended: (%s/%s) %s" % (len(self.ended), len(self.vms), self.ended))
elif p.on_error != "DISABLED" and (answer.success or p.on_error == "CONTINUE"):
r = p.send_next_command()
cmd = p.last_command
report.sent(p.vm, cmd)
logging.info("- SENT: %s, %s" % (c, red(cmd)))
if not r:
logging.info("- SENDING ERROR, ENDING: %s" %c)
self.end(c)
logging.debug("self.ended: (%s/%s) %s" % (len(self.ended), len(self.vms), self.ended))
else:
# answer.success == False
# deve skippare fino al command: END_PROC
if p.on_error == "SKIP":
logging.debug("on_error == %s" % p.on_error)
r = p.send_next_call()
cmd = p.last_command
if cmd:
report.sent(p.vm, cmd)
else:
logging.info("- RECEIVE ERROR, ENDING: %s" %c)
self.end(c)
logging.debug("self.ended: (%s/%s) %s" % (len(self.ended), len(self.vms), self.ended))
elif p.on_error == "DISABLED":
logging.debug("on_error == DISABLED")
r = p.send_next_proc()
cmd = p.last_command
if cmd:
report.sent(p.vm, cmd)
else:
logging.info("- RECEIVE ERROR, ENDING: %s" %c)
self.end(c)
logging.debug("self.ended: (%s/%s) %s" % (len(self.ended), len(self.vms), self.ended))
else:
assert p.on_error == "STOP"
logging.info("- RECEIVE ERROR, STOP: %s" %c)
self.end(c)
logging.debug("self.ended: (%s/%s) %s" % (len(self.ended), len(self.vms), self.ended))
else:
logging.info("- SERVER RECEIVED empty")
exit = True
report.finish()
logging.debug("answered: %s, ended: %s, num_commands: %s" % ( answered, len(self.ended), self.num_commands))
assert len(self.ended) == len(self.vms), "answered: %s, ended: %s, num_commands: %s" % ( answered, len(self.ended), len(self.vms))
#assert answered >= (len(self.vms) * (self.num_commands)), "answered: %s, len(vms): %s, num_commands: %s" % (answered , len(self.vms), self.num_commands)
return answered
logging.debug("upgrade: %s" % params)
try:
self._call_post('agent/upgrade', params)
return True
except:
return False
def instance_can_upgrade(self, instance_id):
try:
value = self._call_get('agent/can_upgrade/%s' % instance_id)
return value
except HTTPError, ex:
logging.error("cannot get can_upgrade")
return "Error%s" % ex.code
except Exception, ex:
logging.exception("cannot get can_upgrade")
return "error"
def instance_level(self, instance_id):
params = {'_id': instance_id}
try:
info = self.instance_info(instance_id)
logging.debug("info: %s" %(info))
return info["level"]
except:
return False
def instance_info(self, instance_id):
agents = self._call_get('agent')
# pp.pprint(agents)
logging.debug("upgrade: %s" % params)
try:
self._call_post('agent/upgrade', params)
return True
except:
return False
def instance_can_upgrade(self, instance_id):
try:
value = self._call_get('agent/can_upgrade/%s' % instance_id)
return value
except HTTPError, ex:
logging.error("cannot get can_upgrade")
return "Error%s" % ex.code
except Exception, ex:
logging.exception("cannot get can_upgrade")
return "error"
def instance_level(self, instance_id):
params = {'_id': instance_id}
try:
info = self.instance_info(instance_id)
logging.debug("info: %s" % (info))
return info["level"]
except:
return False
def instance_info(self, instance_id):
agents = self._call_get('agent')
# pp.pprint(agents)
def dispatch(self, procedure, pool=0):
global received
exit = False
command.context = {}
procedure.add_begin_end()
#logging.debug("- SERVER len(procedure): %s" % len(procedure))
self.num_commands = len(procedure)
report.init(procedure.name)
assert self.vms
assert self.vms[0], "please specify at least one VM"
logging.debug("self.vms: %s" % self.vms)
av_machines = OrderedDict()
p_id = 0
for vm in self.vms:
av_machines[vm] = Protocol(self, vm, procedure, id=p_id)
p_id += 1
if pool == 0:
pool = len(self.vms)
Protocol.pool = pool
self.pool_start(av_machines.values(), pool)
self.ended = set()
answered = 0
while not exit and len(self.ended) < len(self.vms):
rec = self.mq.receive_server(blocking=True, timeout=self.timeout)
if rec is not None:
c, msg = rec
try:
command_unserialize = command.unserialize(msg)
except:
logging.exception("cannot unserialize: %s" % msg)
#exit = True
continue
#command_unserialize =
logging.info("- RECEIVED %s, %s" %
(c, red(command_unserialize)))
if c not in av_machines.keys():
logging.warn(
"A message for %s probably belongs to another test!" %
c)
continue
p = av_machines[c]
try:
answer = p.receive_answer(c, command_unserialize)
except:
logging.exception("cannot receive: %s" %
command_unserialize)
continue
report.received(c, command_unserialize)
if answer.success == None:
#logging.debug("- SERVER IGNORING")
continue
answered += 1
#logging.debug("- SERVER RECEIVED ANSWER: %s" % answer.success)
if answer.name == "END":
self.end(c)
logging.info("- RECEIVE END: %s, %s" % (c, self.ended))
logging.debug("self.ended: (%s/%s) %s" %
(len(self.ended), len(self.vms), self.ended))
elif p.on_error != "DISABLED" and (answer.success or p.on_error
== "CONTINUE"):
r = p.send_next_command()
cmd = p.last_command
report.sent(p.vm, cmd)
logging.info("- SENT: %s, %s" % (c, red(cmd)))
if not r:
logging.info("- SENDING ERROR, ENDING: %s" % c)
self.end(c)
logging.debug(
"self.ended: (%s/%s) %s" %
(len(self.ended), len(self.vms), self.ended))
else:
# answer.success == False
# deve skippare fino al command: END_PROC
if p.on_error == "SKIP":
logging.debug("on_error == %s" % p.on_error)
r = p.send_next_call()
cmd = p.last_command
if cmd:
report.sent(p.vm, cmd)
else:
logging.info("- RECEIVE ERROR, ENDING: %s" % c)
self.end(c)
logging.debug(
"self.ended: (%s/%s) %s" %
(len(self.ended), len(self.vms), self.ended))
elif p.on_error == "DISABLED":
logging.debug("on_error == DISABLED")
r = p.send_next_proc()
cmd = p.last_command
if cmd:
report.sent(p.vm, cmd)
else:
logging.info("- RECEIVE ERROR, ENDING: %s" % c)
self.end(c)
logging.debug(
"self.ended: (%s/%s) %s" %
(len(self.ended), len(self.vms), self.ended))
else:
assert p.on_error == "STOP"
logging.info("- RECEIVE ERROR, STOP: %s" % c)
self.end(c)
logging.debug(
"self.ended: (%s/%s) %s" %
(len(self.ended), len(self.vms), self.ended))
else:
logging.info("- SERVER RECEIVED empty")
exit = True
report.finish()
logging.debug("answered: %s, ended: %s, num_commands: %s" %
(answered, len(self.ended), self.num_commands))
assert len(self.ended) == len(
self.vms), "answered: %s, ended: %s, num_commands: %s" % (
answered, len(self.ended), len(self.vms))
#assert answered >= (len(self.vms) * (self.num_commands)), "answered: %s, len(vms): %s, num_commands: %s" % (answered , len(self.vms), self.num_commands)
return answered
