Add better logging to AUTest. [chromiumos/third_party/autotest : master]

1 view
Skip to first unread message

Chris Sosa (Code Review)

unread,
May 23, 2013, 10:55:06 PM5/23/13
to
Chris Sosa has uploaded a new change for review.

https://gerrit.chromium.org/gerrit/56556


Change subject: Add better logging to AUTest.
......................................................................

Add better logging to AUTest.

1) Reports an autoserv errors (thrown when we fail to shutdown / reboot)
during machine_install as likely infra issues and points readers to not
file bugs against AU.
2) Fixes all expected msgs to actually print out the name of the event
type / event result -- not just the numbers which aren't very readable.
3) Dumps update_engine.log when we fail our expected chain.

BUG=chromium:241944
TEST=Running it now.

Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
---
M server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
1 file changed, 68 insertions(+), 26 deletions(-)


git pull ssh://gerrit.chromium.org:29418/chromiumos/third_party/autotest refs/changes/56/56556/1

diff --git a/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py b/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
index 948e88d..9c18816 100755
--- a/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
+++ b/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
@@ -29,8 +29,10 @@
def __init__(self, event_type=None, event_result=None, version=None,
previous_version=None):
self._expected_attrs = {
- 'event_type': event_type,
- 'event_result': event_result,
+ 'event_type':
+ autoupdate_EndToEndTest.EVENT_TYPE_DICT[event_type],
+ 'event_result':
+ autoupdate_EndToEndTest.EVENT_RESULT_DICT[event_result],
'version': version,
'previous_version': previous_version,
}
@@ -66,6 +68,12 @@
@return True if actual value is present and matches, False otherwise.

"""
+ helper_dict = None
+ if attr_name == 'event_type':
+ helper_dict = autoupdate_EndToEndTest.EVENT_TYPE_DICT
+ elif attr_name == 'event_result':
+ helper_dict = autoupdate_EndToEndTest.EVENT_RESULT_DICT_DICT
+
if not (actual_attr_val and
str(actual_attr_val) == str(expected_attr_val)):
if ('version' in attr_name and actual_attr_val and expected_attr_val
@@ -73,12 +81,16 @@
# We allow for version like 2940.0.0 in 2940.0.0-a1 to allow
# this test to pass for developer images and non-release images.
logging.info("Expected version %s in %s but doesn't "
- "match exactly")
+ "match exactly", expected_attr_val,
+ actual_attr_val)
return True

- logging.error(
- 'actual %s (%s) not as expected (%s)',
- attr_name, actual_attr_val, expected_attr_val)
+ logging.error('Failed to verify attr type %s', attr_name)
+ if helper_dict:
+ logging.error(
+ 'actual value "%s" not as expected "%s"',
+ helper_dict[str(actual_attr_val)],
+ helper_dict[str(expected_attr_val)])
return False

return True
@@ -431,6 +443,18 @@
self._devserver_ssh.run('rm -f %s' % self._devserver_output)


+def MakeTwoWay(dictionary):
+ """Adds val->keys to a dictionary making it bi-directional.
+
+ @param dictionary: A python dictionary.
+ """
+ new_dictionary = {}
+ for key, val in dictionary.iteritems():
+ new_dictionary[str(val)] = key
+
+ dictionary.update(new_dictionary)
+
+
class autoupdate_EndToEndTest(test.test):
"""Complete update test between two Chrome OS releases.

@@ -471,16 +495,18 @@
_DEVSERVER_HOSTLOG_REQUEST_TIMEOUT_SECONDS = 30

# Omaha event types/results, from update_engine/omaha_request_action.h
- EVENT_TYPE_UNKNOWN = 0
- EVENT_TYPE_DOWNLOAD_COMPLETE = 1
- EVENT_TYPE_INSTALL_COMPLETE = 2
- EVENT_TYPE_UPDATE_COMPLETE = 3
- EVENT_TYPE_DOWNLOAD_STARTED = 13
- EVENT_TYPE_DOWNLOAD_FINISHED = 14
- EVENT_RESULT_ERROR = 0
- EVENT_RESULT_SUCCESS = 1
- EVENT_RESULT_SUCCESS_REBOOT = 2
- EVENT_RESULT_UPDATE_DEFERRED = 9
+ # These are stored in dict form in order to easily print out the keys.
+ EVENT_TYPE_DICT = dict(
+ unknown=0, download_complete=1, install_complete=2,
+ update_complete=3, download_started=13, download_finished=14)
+
+
+ EVENT_RESULT_DICT = dict(
+ error=0, success=1, success_reboot=2, update_deferred=9)
+
+ # Make dicts bi directional.
+ MakeTwoWay(EVENT_TYPE_DICT)
+ MakeTwoWay(EVENT_RESULT_DICT)


def _servo_dut_power_up(self):
@@ -698,9 +724,17 @@
self._install_mp_image(image_url)

else:
- self._host.machine_install(self._payload_to_update_url(image_url),
- force_update=True)
-
+ try:
+ self._host.machine_install(
+ self._payload_to_update_url(image_url),
+ force_update=True)
+ except error.AutoservRunError:
+ logging.fatal('Error re-imaging the machine with the source '
+ 'image %s', image_url)
+ raise error.TestFail(
+ 'Could not update to pre-conditions of test. This is '
+ 'most likely a problem with the autotest lab and not '
+ 'autoupdate.')

def _stage_images_onto_devserver(self, lorry_devserver, test_conf):
"""Stages images that will be used by the test onto the devserver.
@@ -836,21 +870,25 @@
version=test_conf['source_release'])),
(self._WAIT_FOR_DOWNLOAD_STARTED_SECONDS,
ExpectedUpdateEvent(
- event_type=self.EVENT_TYPE_DOWNLOAD_STARTED,
+ event_type='download_started',
event_result=self.EVENT_RESULT_SUCCESS,
version=test_conf['source_release'])),
(self._WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS,
ExpectedUpdateEvent(
- event_type=self.EVENT_TYPE_DOWNLOAD_FINISHED,
- event_result=self.EVENT_RESULT_SUCCESS,
+ event_type='download_finished',
+ event_result='result_success',
version=test_conf['source_release'])),
(self._WAIT_FOR_UPDATE_COMPLETED_SECONDS,
ExpectedUpdateEvent(
- event_type=self.EVENT_TYPE_UPDATE_COMPLETE,
- event_result=self.EVENT_RESULT_SUCCESS,
+ event_type='update_complete',
+ event_result='result_success',
version=test_conf['source_release'])))

if not log_verifier.verify_expected_event_chain(chain):
+ if not use_servo:
+ logging.error('Test failed -- dumping update_engine.log')
+ self._host.run('tail -n 20 /var/log/update_engine.log')
+
raise error.TestFail(
'could not verify that update was successful')

@@ -880,11 +918,15 @@
chain = ExpectedUpdateEventChain(
(self._WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS,
ExpectedUpdateEvent(
- event_type=self.EVENT_TYPE_UPDATE_COMPLETE,
- event_result=self.EVENT_RESULT_SUCCESS_REBOOT,
+ event_type='update_complete',
+ event_result='success_reboot',
version=test_conf['target_release'],
previous_version=test_conf['source_release'])))
if not log_verifier.verify_expected_event_chain(chain):
+ if not use_servo:
+ logging.error('Test failed -- dumping update_engine.log')
+ self._host.run('tail -n 20 /var/log/update_engine.log')
+
raise error.TestFail('could not verify that machine rebooted '
'after update')


--
To view, visit https://gerrit.chromium.org/gerrit/56556
To unsubscribe, visit https://gerrit.chromium.org/gerrit/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 1
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Gilad Arnold (Code Review)

unread,
May 24, 2013, 1:27:09 AM5/24/13
to Chris Sosa, ChromeBot
Gilad Arnold has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 2: (4 inline comments)

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 459: dictionary.update(new_dictionary)
Aahhh! (see below)


Line 513: MakeTwoWay(EVENT_RESULT_DICT)
Great stuff. But why not place the dicts inside ExpectedUpdateEvent? This way autoupdate_EndToEndTest can just pass in keys (readable strings like 'download_complete'), ExpectedUpdateEvent handles the value conversion as needed, and you don't need the bidirectional nightmare.


Line 894: self._host.run('tail -n 20 /var/log/update_engine.log')
This is potentially huge and I'm not convinced the cause will be evident in the last 20 lines. Perhaps only dump ERROR lines?


Line 932: self._host.run('tail -n 20 /var/log/update_engine.log')
Duplicate code ==> helper method? ;-)
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 2
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>
Gerrit-Reviewer: ChromeBot <chrom...@google.com>
Gerrit-Reviewer: Gilad Arnold <gar...@chromium.org>

Chris Sosa (Code Review)

unread,
May 28, 2013, 4:18:59 PM5/28/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 2: (3 inline comments)

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 513: MakeTwoWay(EVENT_RESULT_DICT)
You still need it because you need to re-look up the code that we get reported in the json file from the devserver. This is in numeric values so I need convert backwards. You're right I don't need to convert for my expectations.


Line 894: self._host.run('tail -n 20 /var/log/update_engine.log')
Done


Line 932: self._host.run('tail -n 20 /var/log/update_engine.log')
Done
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 2
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
May 28, 2013, 9:06:43 PM5/28/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 2: (1 inline comment)

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 513: MakeTwoWay(EVENT_RESULT_DICT)
I actually ended up understanding what you meant after thinking about it more. This cleaned up the code a bit -- see my new patch.
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 2
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
May 28, 2013, 9:07:00 PM5/28/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 4: Verified

ptal -- this should be good to go.
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 4
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>
Gerrit-Reviewer: Chris Sosa <so...@chromium.org>

Gilad Arnold (Code Review)

unread,
May 29, 2013, 4:32:09 PM5/29/13
to Chris Sosa, ChromeBot
Gilad Arnold has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 4: (10 inline comments)

Thanks for revising! Few more questions/comments remaining.

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 39: '9':'update_deferred'}
I'd use numeric values for keys, which seems to represent their true nature.


Line 47: raise ValueError('event_type %s is not valid.' % event_type)
Nit: why do we need a period at the end of an exception string? (elsewhere too)


Line 94: helper_dict = self.EVENT_RESULT_DICT
Or, you could have a dictionary mapping attr_name ('event_type', 'event_result') to a value translation dictionary (self.EVENT_TYPE_DICT or self.EVENT_RESULT_DICT, respectively). Then these lines turn into:

helper_dict = self.VALUE_MAPS.get(attr_name)

regardless of how many attr_names you may want to translate.


Line 98: return True
(a) this is a change to the function semantics, whereas we used to return False if actual_attr_val is None/empty---intentional? (b) we should do this first thing in the function, no?


Line 105: str(actual_attr_val),
Make the keys in the dictionaries integers and you won't need this str() conversions


Line 106: 'Unknown value: %s' % str(actual_attr_val))
Use %d and omit the str() conversion


Line 108: if not str(actual_attr_val) == str(expected_attr_val):
(a) why the str() conversions? At this point, actual_attr_val and expected_attr_val should have the same type, no? (b) not a == b <==> a != b ?


Line 119: str(actual_attr_val), str(expected_attr_val))
Redundant str() conversions, %s should do the job


Line 818:
Remove empty line


Line 905: 'update failed to apply. see logs for the culprit.')
s/./,/
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 4
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
May 29, 2013, 5:28:15 PM5/29/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 4: (10 inline comments)

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 39: '9':'update_deferred'}
We were inferring strings before and I'd rather keep it this way and not rely on what I get formatted to me to keep these as integers as opposed to accidentally converting to string. String provides a reasonable way to represent all this sort of data.


Line 47: raise ValueError('event_type %s is not valid.' % event_type)
The google style guides prefer periods at the end of all sentences in docstrings so I've applied this to all my sentences.


Line 94: helper_dict = self.EVENT_RESULT_DICT
I like the idea but don't think it adds very much to this code since there are only two attr names and I don't expect any more.


Line 98: return True
(a) Fixed. Got confused between expected / actual. We only get to this point if expected is not None (due to verify) so we'd only get here is if expected != None and actual == None in which case we should return False (b) done.


Line 105: str(actual_attr_val),
Replied above.


Line 106: 'Unknown value: %s' % str(actual_attr_val))
Cleaned this up to only convert in one place.


Line 108: if not str(actual_attr_val) == str(expected_attr_val):
Cleaned this up to only convert in one place.


Line 119: str(actual_attr_val), str(expected_attr_val))
Cleaned this up to only convert in one place.


Line 818:
Done


Line 905: 'update failed to apply. see logs for the culprit.')
Done
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 4
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Gilad Arnold (Code Review)

unread,
May 29, 2013, 5:42:18 PM5/29/13
to Chris Sosa, ChromeBot
Gilad Arnold has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 5: Looks good to me, approved

(3 inline comments)

See comments inline. Lgtm otherwise.

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 90: # None values are assumed to be 'any'.
...assumed to be missing?


Line 104: actual_attr_val = str(actual_attr_val)
I don't really see why we need to be converting values to their string representation for this function to work properly. First, you're changing the semantics because it could be that str(a) == str(b) but a != b (or even type(a) != type(b)). Second, even if it's not damaging for our use cases (which I agree it isn't currently), it does seem redundant: from what I'm reading, the code would work equally well as is without this conversion.


Line 114: if ('version' in attr_name and actual_attr_val and expected_attr_val
actual_attr_val must evaluate to True at this point, redundant
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 5
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
May 29, 2013, 8:49:58 PM5/29/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 5: (3 inline comments)

....................................................
File server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py
Line 90: # None values are assumed to be 'any'.
Done


Line 104: actual_attr_val = str(actual_attr_val)
This is just a precaution. I don't see much reason to change from string to int and the pre-existing code used strings for some reason (I didn't do it first ;)) and I don't want to randomly have this break because of some earlier assumption.


Line 114: if ('version' in attr_name and actual_attr_val and expected_attr_val
Done
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 5
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
May 29, 2013, 8:50:17 PM5/29/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 6: Looks good to me, approved; Ready; Verified
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 6
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>

Chris Sosa (Code Review)

unread,
Jun 3, 2013, 2:00:29 PM6/3/13
to ChromeBot, Gilad Arnold
Chris Sosa has posted comments on this change.

Change subject: Add better logging to AUTest.
......................................................................


Patch Set 6: Ready
Gerrit-MessageType: comment
Gerrit-Change-Id: I69c60b6e09d784cb7e866a81e475f5e2ecb05cb2
Gerrit-PatchSet: 6
Gerrit-Project: chromiumos/third_party/autotest
Gerrit-Branch: master
Gerrit-Owner: Chris Sosa <so...@chromium.org>
Reply all
Reply to author
Forward
0 new messages