00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018
00019
00020
00021
00022
00023
00024
00025
00026
00027
00028
00029
00030
00031
00032
00033
00034
00035
00036
00037
00038 from __future__ import with_statement, division
00039
00040 PKG = 'life_test'
00041 import roslib
00042 roslib.load_manifest(PKG)
00043
00044 import csv
00045 import os, sys, math
00046
00047 import rospy
00048
00049 from socket import gethostname
00050
00051 from writing_core import *
00052
00053 import smtplib
00054 from email.mime.multipart import MIMEMultipart
00055 from email.mime.text import MIMEText
00056 from email.mime.base import MIMEBase
00057 from email import Encoders
00058
00059 import tempfile, tarfile
00060
00061 import wg_invent_client
00062
00063 LOG_UPDATE = 7200
00064 INVENT_TIMEOUT = 600
00065
00066 import result_dir
00067 RESULTS_DIR = result_dir.RESULTS_DIR
00068
00069
00070 def _get_csv_header_lst(params):
00071 """
00072 Returns header to a CSV log file as a list
00073 @param params [ TestParam ] : Test parameters
00074 @return [ str ] : Header items
00075 """
00076 hdr = [ 'Time', 'Status', 'Message', 'Monitor Status', 'Elapsed',
00077 'Cum. Time', 'Num. Halts', 'Num. Events' ]
00078
00079 for p in params:
00080 if p.rate:
00081 hdr.append('Cum. %s' % p.name)
00082
00083 hdr.append('Note')
00084
00085 return hdr
00086
00087 def _alert_prefix(lvl):
00088 """
00089 Return email subject prefix based on status level
00090 """
00091 if lvl == 2:
00092 return '--Test Alert--'
00093 if lvl > 2:
00094 return '--Test Report--'
00095 return '--Test Notify--'
00096
00097 class LogEntry(object):
00098 """
00099 Entry in test log. Gets written to CSV output file.
00100 """
00101 def __init__(self, stamp, elapsed, cum_time, status, message, monitor_msg, params, halts, events, note):
00102 """
00103 @param stamp float : Timestamp
00104 @param elapsed float : Seconds elapsed since start
00105 @param cum_time float : Cumulative (running) time
00106 @param status str : Status string
00107 @param message str : Message from manager
00108 @param monitor_msg str : Message from test monitor
00109 @param params [ TestParam ] : Values of parameters
00110 @param halts int : Number of halts
00111 @param events int : Number of events
00112 @param note str : Note from user
00113 """
00114 self.stamp = stamp
00115
00116 self.status = status
00117 self.message = message
00118 self.monitor_msg = monitor_msg
00119 self.params = params
00120 self.note = note
00121
00122
00123 self.elapsed = elapsed
00124 self.cum_time = cum_time
00125
00126 self.halts = halts
00127 self.events = events
00128
00129 def write_to_lst(self):
00130 """
00131 Write data to list, to be written to CSV
00132 @return [ str ] : List of all items
00133 """
00134 lst = [ format_localtime(self.stamp), self.status, self.message, self.monitor_msg,
00135 get_duration_str(self.elapsed),
00136 get_duration_str(self.cum_time), self.halts, self.events ]
00137
00138 for p in self.params:
00139 if p.rate:
00140 lst.append(p.value * self.cum_time)
00141
00142 lst.append(self.note)
00143
00144 return lst
00145
00146
00147 def _get_hrs(seconds):
00148 """
00149 Converts seconds to hours to 0.1 hours precision
00150 @param seconds : Seconds
00151 @return float : Hours to 0.1 decimal places
00152 """
00153 hrsx10 = int(seconds / 360)
00154 return hrsx10 / 10.
00155
00156 class TestRecord(object):
00157 """
00158 Updates CSV record with state changes for a test
00159
00160 """
00161 def __init__(self, test, serial, file_path = None, csv_name = None, send_email = True):
00162 """
00163 @param test LifeTest : Test type, params
00164 @param serial str : Serial number of DUT
00165 @param file_path str : File path of out. Used for unit testing.
00166 """
00167 self._start_time = rospy.get_time()
00168 self._cum_seconds = 0
00169 self._last_update_time = rospy.get_time()
00170
00171
00172 self._was_running = False
00173 self._was_launched = False
00174 self._last_msg = ''
00175
00176 self._num_events = 0
00177 self._num_halts = 0
00178 self._test_complete = False
00179 self._bay = None
00180
00181 self._serial = serial
00182 self._test = test
00183
00184 self._log_entries = []
00185
00186 self._last_log_time = self._last_update_time
00187
00188 self._last_invent_time = 0
00189 self._invent_note_id = None
00190
00191 self._cum_data = {}
00192 for param in test.params:
00193 if param.rate:
00194 self._cum_data[param.name] = 0
00195
00196 if not csv_name:
00197 csv_name = str(self._serial) + '_' + format_localtime_file(self._start_time) + \
00198 '_' + self._test.name + '.csv'
00199 if not csv_name.endswith('.csv'):
00200 csv_name += '.csv'
00201
00202 csv_name = csv_name.replace(' ', '_').replace('/', '-')
00203
00204 if not file_path:
00205 file_path = RESULTS_DIR
00206 else:
00207 file_path = os.path.expanduser(file_path)
00208
00209 if not os.path.isdir(file_path):
00210 os.makedirs(file_path)
00211
00212 self.log_file = os.path.join(file_path, csv_name)
00213
00214
00215 if not os.path.exists(self.log_file):
00216 with open(self.log_file, 'ab') as f:
00217 log_csv = csv.writer(f)
00218 log_csv.writerow(_get_csv_header_lst(self._test.params))
00219
00220 self._has_checked_invent = False
00221 self._invent_hrs_base = 0.0
00222
00223 self._send_email = send_email
00224
00225
00226 def get_elapsed(self):
00227 """
00228 Time since test was started, in seconds.
00229 """
00230 elapsed = rospy.get_time() - self._start_time
00231 return elapsed
00232
00233 def get_cum_time(self):
00234 """
00235 Time that test has been running, in seconds.
00236 """
00237 return self._cum_seconds
00238
00239 def get_active_str(self):
00240 return get_duration_str(self._cum_seconds)
00241
00242 def get_elapsed_str(self):
00243 return get_duration_str(self.get_elapsed())
00244
00245 def update(self, launched, running, stale, note, monitor_msg):
00246 """
00247 Updates test record with current state
00248
00249 Looks at current, previous state to record data and send alerts
00250 \param launched bool : Test launched
00251 \param running bool : Running (status OK)
00252 \param stale bool : Test is stale
00253 \param note str : Notes from operator
00254 \param monitor_msg str : Message from Test Monitor
00255 \return (int, str) : int [0:OK, 1:Notify, 2:Alert]
00256 """
00257 d_seconds = 0
00258 if self._was_running and running:
00259 d_seconds = rospy.get_time() - self._last_update_time
00260
00261 self._cum_seconds += d_seconds
00262
00263 alert = 0
00264 msg = ''
00265 state = 'Running'
00266
00267 if launched and (not running) and stale:
00268 state = 'Stale'
00269 elif launched and (not running):
00270 state = 'Halted'
00271 elif not launched:
00272 state = 'Stopped'
00273
00274 if (not self._was_launched) and launched:
00275 alert = 1
00276 msg = "Launched."
00277 elif self._was_launched and (not launched):
00278 alert = 1
00279 msg = "Shut down."
00280
00281 elif self._was_running and (not running):
00282 alert = 2
00283 self._num_halts += 1
00284 if stale:
00285 msg = "Stale."
00286 else:
00287 msg = "Stopped."
00288 elif (not self._was_running) and running:
00289 alert = 1
00290 msg = "Restarted."
00291
00292 if alert > 0:
00293 self._num_events += 1
00294
00295
00296 for param in self._test.params:
00297 if param.rate:
00298 self._cum_data[param.name] += d_seconds * param.value
00299
00300 self._was_running = running
00301 self._was_launched = launched
00302 self._last_msg = monitor_msg
00303 self._last_update_time = rospy.get_time()
00304
00305
00306 if alert > 0 or note != '' or (running and self._last_log_time - rospy.get_time() > LOG_UPDATE):
00307 entry = LogEntry(rospy.get_time(), self.get_elapsed(), self.get_cum_time(),
00308 state, msg, monitor_msg, self._test.params, self._num_halts,
00309 self._num_events, note)
00310
00311 self._log_entries.append(entry)
00312 self._write_csv_entry(entry)
00313 self._last_log_time = self._last_update_time
00314
00315
00316 if alert > 0:
00317 self.notify_operator(alert, msg)
00318
00319 return (alert, msg)
00320
00321 def _write_csv_entry(self, entry):
00322 """
00323 Writes data to CSV, and to log entries
00324 """
00325 with open(self.log_file, 'ab') as f:
00326 log_csv = csv.writer(f)
00327
00328 log_csv.writerow(entry.write_to_lst())
00329
00330
00331 def csv_filename(self):
00332 return self.log_file
00333
00334 def _get_test_team(self):
00335
00336 if os.environ.has_key('USER') and os.environ['USER'] == 'watts' and gethostname() == 'nsf':
00337 return 'watts@willowgarage.com'
00338
00339 return 'test.team@lists.willowgarage.com'
00340
00341 def _email_subject(self, lvl, msg):
00342 return _alert_prefix(lvl) + " Test %s. MSG: %s" % (self._test.get_title(self._serial), msg)
00343
00344 def make_email_message(self, level, alert_msg = ''):
00345 """
00346 Called during unit testing and operator notificaton
00347 """
00348 msg = MIMEMultipart('alternative')
00349 msg['Subject'] = self._email_subject(level, alert_msg)
00350 msg['From'] = 'test.notify@willowgarage.com'
00351 msg['To'] = self._get_test_team()
00352
00353 msg.attach(MIMEText(self.make_html_test_summary(alert_msg), 'html'))
00354
00355 log_csv = open(self.log_file, 'rb')
00356 log_data = log_csv.read()
00357 log_csv.close()
00358
00359 part = MIMEBase('application', 'octet-stream')
00360 part.set_payload(log_data)
00361 Encoders.encode_base64(part)
00362 part.add_header('Content-Disposition', 'attachment; filename="%s"'
00363 % os.path.basename(self.csv_filename()))
00364
00365 msg.attach(part)
00366
00367 return msg
00368
00369 def notify_operator(self, lvl, alert_msg):
00370 """
00371 Sends email with test info to testing team
00372 """
00373
00374 if not self._send_email:
00375 return True
00376
00377 try:
00378 msg = self.make_email_message(lvl, alert_msg)
00379
00380 s = smtplib.SMTP('localhost')
00381 s.sendmail(msg['From'], msg['To'], msg.as_string())
00382 s.quit()
00383
00384 return True
00385 except Exception, e:
00386 import traceback
00387 rospy.logwarn('Unable to send mail! %s' % traceback.format_exc())
00388 return False
00389
00390 def complete_test(self):
00391 """Test is marked as finished."""
00392 self._test_complete = True
00393
00394 @property
00395 def test_complete(self):
00396 return self._test_complete
00397
00398 def set_bay(self, bay):
00399 """
00400 The bay the test runs on. Can only be called when test isn't launched.
00401 """
00402 self._bay = bay
00403
00404 if not bay:
00405 return
00406
00407 entry = LogEntry(rospy.get_time(), self.get_elapsed(), self.get_cum_time(),
00408 'Stopped', '', '', self._test.params,
00409 self._num_halts, self._num_events,
00410 'Test bay: %s. Power board, breaker: %s, %s' %
00411 (self._bay.name, self._bay.board, self._bay.breaker))
00412
00413 self._log_entries.append(entry)
00414 self._write_csv_entry(entry)
00415
00416 def make_html_test_summary(self, alert_msg = None):
00417 html = ['<html><head><title>Test Log: %s of %s</title>' % (self._test.name, self._serial)]
00418 html.append('<style type=\"text/css\">\
00419 body { color: black; background: white; }\
00420 div.error { background: red; padding: 0.5em; border: none; }\
00421 div.warn { background: orange: padding: 0.5em; border: none; }\
00422 div.pass { background: green; padding: 0.5em; border: none; }\
00423 strong { font-weight: bold; color: red; }\
00424 em { font-style:normal; font-weight: bold; }\
00425 </style>\
00426 </head>\n<body>')
00427
00428 html.append('<H2 align=center>Test Log: %s of %s</H2>' % (self._test.name, self._serial))
00429
00430 if alert_msg:
00431 html.append('<H3>Alert: %s</H3><br>' % alert_msg)
00432
00433 if self._test_complete:
00434 html.append('<H3>Test Complete</H3>')
00435 else:
00436 if self._was_launched and not self._was_running:
00437 html.append('<H3>Test Status: Launched, Halted</H3>')
00438 elif self._was_launched and self._was_running:
00439 html.append('<H3>Test Status: Launched, Running</H3>')
00440 else:
00441 html.append('<H3>Test Status: Shutdown</H3>')
00442
00443 html.append('<H4>Current Message: %s</H4>' % str(self._last_msg))
00444
00445
00446 html.append('<hr size="3">')
00447 html.append('<H4>Test Info</H4>')
00448 html.append('<p>Description: %s</p><br>' % self._test.desc)
00449 html.append(self._make_test_info_table())
00450
00451
00452 html.append('<hr size="3">')
00453 html.append('<H4>Test Parameters</H4>')
00454 html.append(self._test.make_param_table())
00455
00456
00457 html.append('<hr size="3">')
00458 html.append('<H4>Test Results</H4>')
00459 html.append(self._write_table())
00460
00461
00462 html.append('<hr size="3">')
00463 html.append('<H4>Test Log</H4>')
00464 html.append(self._write_summary_log())
00465
00466 html.append('<hr size="3">')
00467 html.append('</body></html>')
00468
00469 return '\n'.join(html)
00470
00471 def _make_test_info_table(self):
00472 """
00473 Writes HTML table of test info
00474 @return str : HTML table
00475 """
00476 html = ['<table border="1" cellpadding="2" cellspacing="0">']
00477 html.append(write_table_row(['Test Name', self._test.name]))
00478 if self._bay:
00479 html.append(write_table_row(['Test Bay', self._bay.name]))
00480 html.append(write_table_row(['Machine', self._bay.machine]))
00481 html.append(write_table_row(['Powerboard', self._bay.board]))
00482 html.append(write_table_row(['Breaker', self._bay.breaker]))
00483
00484
00485 html.append(write_table_row(['Serial', self._serial]))
00486 html.append(write_table_row(['Test Type', self._test.type]))
00487 html.append(write_table_row(['Launch File', self._test.launch_file]))
00488 html.append('</table>')
00489
00490 return '\n'.join(html)
00491
00492 def _write_table(self):
00493 """
00494 Writes HTML table of last state of test
00495 @return str : HTML table
00496 """
00497 html = ['<table border="1" cellpadding="2" cellspacing="0">']
00498 time_str = format_localtime(self._start_time)
00499 html.append(write_table_row(['Start Time', time_str]))
00500 html.append(write_table_row(['Elapsed Time', self.get_elapsed_str()]))
00501 html.append(write_table_row(['Active Time', self.get_active_str()]))
00502 for ky in self._cum_data.keys():
00503 cum_name = "Cum. %s" % ky
00504 html.append(write_table_row([cum_name, self._cum_data[ky]]))
00505
00506 html.append(write_table_row(['Num Halts', self._num_halts]))
00507 html.append(write_table_row(['Num Alerts', self._num_events]))
00508 html.append('</table>')
00509
00510 return '\n'.join(html)
00511
00512 def _write_summary_log(self):
00513 """
00514 Writes HTML table of test events and messages
00515 @return str : HTML table
00516 """
00517 if len(self._log_entries) == 0:
00518 return '<p>No test log.</p>\n'
00519
00520 html = []
00521
00522 html.append('<table border="1" cellpadding="2" cellspacing="0">')
00523 html.append(write_table_row(['Time', 'Entry'], True))
00524
00525 for entry in self._log_entries:
00526 time_str = format_localtime(entry.stamp)
00527 summary = entry.message + ' ' + entry.note
00528
00529 html.append(write_table_row([time_str, summary]))
00530
00531 html.append('</table>')
00532
00533 return '\n'.join(html)
00534
00535
00536 def write_log(self):
00537 """
00538 Writes full log to HTML table form
00539 @return str : Log of test
00540 """
00541 html = [ '<html>' ]
00542
00543 html.append('<table border="1" cellpadding="2" cellspacing="0">')
00544 html.append(write_table_row(_get_csv_header_lst(self._test.params), True))
00545
00546 for entry in self._log_entries:
00547 html.append(write_table_row(entry.write_to_lst()))
00548
00549 html.append('</table>')
00550
00551 html.append('</html>')
00552
00553 return '\n'.join(html)
00554
00555 def write_tar_file(self):
00556 """
00557 Writes CSV, HTML summary into tar file.
00558 Unit testing and loading attachments
00559
00560 ##\return Named temporary file. ".close()" will delete file
00561 """
00562 html_logfile = tempfile.NamedTemporaryFile()
00563 f = open(html_logfile.name, 'w')
00564 f.write(self.make_html_test_summary())
00565 f.close()
00566
00567
00568 tar_filename = tempfile.NamedTemporaryFile()
00569
00570 tf = tarfile.open(tar_filename.name, 'w:')
00571 summary_name = self._serial + '_' + self._test.name.replace(' ', '_').replace('/', '-') \
00572 + '_summary.html'
00573 tf.add(html_logfile.name, arcname=summary_name)
00574 tf.add(self.csv_filename(), arcname=os.path.basename(self.csv_filename()))
00575
00576 tf.close()
00577
00578 html_logfile.close()
00579
00580 return tar_filename
00581
00582 @property
00583 def result(self):
00584 if self._test_complete: return 'Pass'
00585 return 'Not Finished'
00586
00587 def _check_invent_hours(self, iv):
00588 """
00589 Checks Invent for the number of hours that the test has run,
00590 from Invent. Invent stores this data as a Key-Value for the item.
00591 Updates self._invent_hrs_base with data
00592 """
00593 if self._has_checked_invent:
00594 return
00595
00596 if not iv.login():
00597 return
00598
00599 hrs_str = iv.getKV(self._serial, self._test.id + ' Hours')
00600 if not hrs_str:
00601 self._has_checked_invent = True
00602 return
00603
00604 try:
00605 self._invent_hrs_base = float(hrs_str)
00606 except ValueError, e:
00607 print >> sys.stderr, "Unable to recover Invent hours from %s, got %s" % (self._serial, hrs_str)
00608 self._has_checked_invent = True
00609
00610
00611 def _load_attachments(self, iv):
00612 """
00613 Load attachments to Invent
00614 @raise Exception : Exception from Invent
00615 @return bool : True if loaded successfully
00616 """
00617 hrs_str = self.get_active_str()
00618 note = "%s finished. Total active time: %s." % (self._test.name, hrs_str)
00619
00620 tfile = self.write_tar_file()
00621 f = open(tfile.name, 'rb')
00622 tr = f.read()
00623 f.close()
00624
00625 archive_name = self._serial + '_' + self._test.name.replace(' ', '_').replace('/', '-') + '.tar'
00626
00627 my_data = wg_invent_client.TestData(self._test.id, self._test.name, self._start_time, self._serial, self.result)
00628
00629 my_data.set_note(note)
00630 my_data.set_attachment('application/tar', archive_name)
00631
00632 rv = wg_invent_client.submit_log(iv, my_data, tr)
00633
00634 tfile.close()
00635
00636 return rv
00637
00638
00639 def load_attachments(self, iv):
00640 """
00641 Load attachment into inventory system as a tarfile
00642 Loads data as "test".
00643
00644 @param iv Invent : Invent client, to load
00645 @return bool : True if loaded successfully
00646 """
00647 try:
00648 if self.get_cum_time() == 0:
00649 return True
00650
00651 self.update_invent(iv)
00652
00653 return self._load_attachments(iv)
00654 except Exception, e:
00655 import traceback
00656 rospy.logerr('Unable to submit to invent. %s' % traceback.format_exc())
00657 return False
00658
00659 def _get_total_hours(self, iv):
00660 """
00661 Returns string of total hours that this device has run under this
00662 test. Hours from previous tests are pulled from Invent.
00663
00664 \return str : Hours, to 0.1 hour precision. Ex: "10.2"
00665 """
00666 self._check_invent_hours(iv)
00667 return str(_get_hrs(self._cum_seconds + self._invent_hrs_base * 3600.))
00668
00669
00670 def update_invent(self, iv):
00671 """
00672 Update inventory system note with status, and update Key-Value
00673 with cumulative hours.
00674
00675 @param iv Invent : Invent client, to load note
00676 """
00677 if rospy.get_time() - self._last_invent_time < INVENT_TIMEOUT:
00678 return
00679
00680
00681 if self.get_elapsed() == 0 and not self._invent_note_id:
00682 return
00683
00684 self._last_invent_time = rospy.get_time()
00685
00686 total_hours = self._get_total_hours(iv)
00687 iv.setKV(self._serial, self._test.id + ' Hours',
00688 total_hours)
00689
00690 hrs_str = self.get_active_str()
00691
00692 stats = "Stats: Total active time %s." % (hrs_str)
00693
00694 if self._was_launched and self._was_running:
00695 note = "Test running: %s. " % (self._test.name)
00696 elif self._was_launched and not self._was_running:
00697 note = "%s is paused. " % self._test.name
00698 else:
00699 note = "%s stopped. " % self._test.name
00700
00701 self._invent_note_id = iv.setNote(self._serial, note + stats, self._invent_note_id)