Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sanitycheck fixes, enhancements #21684

Merged
merged 9 commits into from
Jan 6, 2020
3 changes: 3 additions & 0 deletions scripts/sanity_chk/hwmap-schema.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,9 @@ sequence:
"post_script":
type: str
required: false
"post_flash_script":
type: str
required: false
"pre_script":
type: str
required: false
72 changes: 41 additions & 31 deletions scripts/sanitycheck
Original file line number Diff line number Diff line change
Expand Up @@ -564,6 +564,7 @@ class BinaryHandler(Handler):
env.get("ASAN_OPTIONS", "")
if not self.lsan:
env["ASAN_OPTIONS"] += "detect_leaks=0"

with subprocess.Popen(command, stdout=subprocess.PIPE,
stderr=subprocess.PIPE, cwd=self.build_dir, env=env) as proc:
logger.debug("Spawning BinaryHandler Thread for %s" % self.name)
Expand All @@ -575,6 +576,9 @@ class BinaryHandler(Handler):
t.join()
proc.wait()
self.returncode = proc.returncode
_, stderr = proc.communicate(timeout=30)
if stderr:
logger.error(stderr.decode())

handler_time = time.time() - start_time

Expand Down Expand Up @@ -681,6 +685,18 @@ class DeviceHandler(Handler):
if i['serial'] == serial:
i['available'] = True

@staticmethod
def run_custom_script(script, timeout):
with subprocess.Popen(script, stderr=subprocess.PIPE, stdout=subprocess.PIPE) as proc:
try:
stdout, _ = proc.communicate(timeout=timeout)
logger.debug(stdout.decode())

except subprocess.TimeoutExpired:
proc.kill()
proc.communicate()
logger.error("{} timed out".format(script))

def handle(self):
out_state = "failed"

Expand All @@ -703,6 +719,7 @@ class DeviceHandler(Handler):
command = [get_generator()[0], "-C", self.build_dir, "flash"]

while not self.device_is_available(self.instance.platform.name):
logger.debug("Waiting for device {} to become available".format(self.instance.platform.name))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That print is going all the time when device is being programming. Like:

DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available
DEBUG - Waiting for device mec15xxevb_assy6853 to become available

For me that print caused misunderstanding if a device has a problem. Only when I commented it out, I realized that device is programming in the background and everything is ok. I think necessary to remove that print or change text. "Device programming. Soon it will be available" for example

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is just a debug log message, it does not impact functionality. It means the device is locked and being used to run a test, so the next test can't execute yet. Useful for debugging possible lockups and races.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"Device programming. Soon it will be available" for example

the message is not related to flashing at all, the device is just not available and anything might be going on, for example a test might be running.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, understand. But in my case that message is printing during the first flashing process. And then test start to execute. It means that message is printing while the flashing process is running, but after second flashing process that message is not visible.

time.sleep(1)

hardware = self.get_available_device(self.instance.platform.name)
Expand Down Expand Up @@ -759,20 +776,12 @@ class DeviceHandler(Handler):
read_pipe, write_pipe = os.pipe()
start_time = time.time()


pre_script = hardware.get('pre_script')
post_flash_script = hardware.get('post_flash_script')
post_script = hardware.get('post_script')

if pre_script:
with subprocess.Popen(pre_script, stderr=subprocess.PIPE, stdout=subprocess.PIPE) as proc:
try:
(stdout, stderr) = proc.communicate(timeout=30)
logger.debug(stdout.decode())

except subprocess.TimeoutExpired:
proc.kill()
(stdout, stderr) = proc.communicate()
logger.error("{} timed out".format(post_script))
self.run_custom_script(pre_script, 30)

t = threading.Thread(target=self.monitor_serial, daemon=True,
args=(ser, read_pipe, harness))
Expand Down Expand Up @@ -802,13 +811,21 @@ class DeviceHandler(Handler):
except subprocess.CalledProcessError:
os.write(write_pipe, b'x') # halt the thread

if post_flash_script:
self.run_custom_script(post_flash_script, 30)


t.join(self.timeout)
if t.is_alive():
logger.debug("Timed out while monitoring serial output on {}".format(self.instance.platform.name))
out_state = "timeout"

if ser.isOpen():
ser.close()

os.close(write_pipe)
os.close(read_pipe)

handler_time = time.time() - start_time

if out_state == "timeout":
Expand All @@ -828,15 +845,7 @@ class DeviceHandler(Handler):
self.set_state(out_state, handler_time)

if post_script:
with subprocess.Popen(post_script, stderr=subprocess.PIPE, stdout=subprocess.PIPE) as proc:
try:
(stdout, stderr) = proc.communicate(timeout=30)
logger.debug(stdout.decode())

except subprocess.TimeoutExpired:
proc.kill()
(stdout, stderr) = proc.communicate()
logger.error("{} timed out".format(post_script))
self.run_custom_script(post_script, 30)

self.make_device_available(serial_device)

Expand Down Expand Up @@ -1645,7 +1654,7 @@ class TestInstance:
self.platform = platform

self.status = None
self.reason = "N/A"
self.reason = "Unknown"
self.metrics = dict()
self.handler = None
self.outdir = outdir
Expand Down Expand Up @@ -1830,14 +1839,12 @@ class CMake():
with open(os.path.join(self.build_dir, self.log), "a") as log:
log.write(log_msg)

overflow_flash = "region `FLASH' overflowed by"
overflow_ram = "region `RAM' overflowed by"

if log_msg:
if log_msg.find(overflow_flash) > 0 or log_msg.find(overflow_ram) > 0:
logger.debug("RAM/ROM Overflow")
res = re.findall("region `(FLASH|RAM|SRAM)' overflowed by", log_msg)
if res:
logger.debug("Test skipped due to {} Overflow".format(res[0]))
self.instance.status = "skipped"
self.instance.reason = "overflow"
self.instance.reason = "{} overflow".format(res[0])
else:
self.instance.status = "failed"
self.instance.reason = "Build failure"
Expand Down Expand Up @@ -1891,12 +1898,13 @@ class CMake():
if p.returncode == 0:
filter_results = self.parse_generated()
msg = "Finished building %s for %s" % (self.source_dir, self.platform.name)

logger.debug(msg)
results = {'msg': msg, 'filter': filter_results}

else:
self.instance.status = "failed"
self.instance.reason = "Cmake build failure"
logger.error("Cmake build failure: %s for %s" % (self.source_dir, self.platform.name))
results = {"returncode": p.returncode}

if out:
Expand Down Expand Up @@ -2021,10 +2029,10 @@ class ProjectBuilder(FilterBuilder):

if os.path.exists(v_log) and "Valgrind" in self.instance.reason:
self.log_info("{}".format(v_log), inline_logs)
elif os.path.exists(d_log) and os.path.getsize(d_log) > 0:
self.log_info("{}".format(d_log), inline_logs)
elif os.path.exists(h_log) and os.path.getsize(h_log) > 0:
self.log_info("{}".format(h_log), inline_logs)
elif os.path.exists(d_log) and os.path.getsize(d_log) > 0:
self.log_info("{}".format(d_log), inline_logs)
else:
self.log_info("{}".format(b_log), inline_logs)

Expand Down Expand Up @@ -2464,7 +2472,7 @@ class TestSuite:
board_root)

for file in glob.glob(os.path.join(board_root, "*", "*", "*.yaml")):
logger.debug("Found plaform configuration " + file)
logger.debug("Found platform configuration " + file)
try:
platform = Platform()
platform.load(file)
Expand Down Expand Up @@ -2890,6 +2898,7 @@ class TestSuite:
try:
data = future.result()
except Exception as exc:
logger.error('%r generated an exception: %s' % (test, exc))
sys.exit('%r generated an exception: %s' % (test, exc))

else:
Expand Down Expand Up @@ -3785,7 +3794,8 @@ class HardwareMap:
'Silicon Labs',
'NXP Semiconductors',
'Microchip Technology Inc.',
'FTDI'
'FTDI',
'Digilent'
]

runner_mapping = {
Expand Down