CWHUSKY: Lab 2_1B: WARNING:root:SAM3U Serial buffers OVERRUN - data loss has occurred and XADC errors

zaphod · May 10, 2023, 2:38am

A few issues:

I am getting “WARNING:root:SAM3U Serial buffers OVERRUN - data loss has occurred.” warning when capturing traces with trace_test = cap_pass_trace("h\n"). However, I am getting 3000 samples as requested. Should just ignore?
After above warning the error status shows the following (XADC error):

sam_errors      = False
sam_led_setting = Default
XADC errors     = VCCaux alarm, 
ADC errors      = False
extclk error    = False
trace errors    = False

Is that error something that needs to be rectified?

The plot (see attached) does not look like reference plot (in the Exploration section of the tutorial) but can I assume that is because the reference plot was taken on a different target?

lab2_1B_plot872×654 28.9 KB

jpthibault · May 10, 2023, 1:02pm

Regarding point 2, what’s the output of:
print(' vccaux=%1.3f/%1.3f/%1.3f' % (scope.XADC.vccaux, scope.XADC.get_vcc('vccaux', 'min'), scope.XADC.get_vcc('vccaux', 'max')))

zaphod · May 11, 2023, 2:04am

vccaux=1.804/1.685/1.862

If I disconnect, power cycle, reconnect and try again I get:

vccaux=1.805/1.707/1.847

If I do the same again but don’t re-program the target board I get something like this without an alarm:

vccaux=1.801/1.796/1.810

jpthibault · May 11, 2023, 2:58am

Hmm, this suggests some hardware problem – either with Husky, the target, or your host USB port.

Are you able to try with a different USB port and/or cable?

If that doesn’t change anything, it would also be helpful if you can run this, from our “tests” directory:

pytest test_husky.py

(you may have to pip install pytest)

First run it without any target attached (i.e. only Husky is connected, nothing else). This should run in about two minutes – most tests will be marked “SKIPPED”, which is normal.
Assuming that ran cleanly, re-run with the --fulltest argument, which will take about 20 minutes.

If those pass without any failures, add your SAM4S target, program it as follows:

import chipwhisperer as cw
scope = cw.scope()
prog = cw.programmers.SAM4SProgrammer
cw.program_target(scope, prog, 'hardware/victims/firmware/simpleserial-trace/simpleserial-trace-CW308_SAM4S.hex')

(adjust the path to your local simpleserial-trace-CW308_SAM4S.hex file location)

and then run:
HUSKY_TARGET_PLATFORM=sam4s pytest ./test_husky.py --fulltest

zaphod · May 12, 2023, 3:23am

Hi @jpthibault
I tried several USB ports. Did not make a difference.
First ran pytest ./test_husky.py with nothing connected. Only failures were with the fw version:

=================================== FAILURES=================================
___________________________________ test_fw_version ----------__________________________
test_husky.py:483: in test_fw_version
    assert scope.sam_build_date == '13:17:41 Feb  9 2023'
E   AssertionError: assert '21:32:05 Jan 31 2023' == '13:17:41 Feb  9 2023'
E     - 13:17:41 Feb  9 2023
E     + 21:32:05 Jan 31 2023
========================== short test summary info ==================================
FAILED test_husky.py::test_fw_version - AssertionError: assert '21:32:05 Jan 31 2023' == '13:17:41 Feb  9 2023'
================== 1 failed, 34 passed, 111 skipped in 17.92s =============================

Then ran pytest ./test_husky.py --fulltest with nothing connected. Only failures where with the fw version as before (took ~4 minutes only. I guess 20 minutes is when the target is attached?)

Then I hooked the target up and tried to program it but I kept on getting the following error:

File chipwhisperer/software/chipwhisperer/hardware/naeusb/bootloader_sam3u.py:330, in Samba.read_word(self, addr)
    328 if len(resp) < 4:
    329     target_logger.debug("Timeout on read from {:04X}".format(addr))
--> 330     raise IOError("timeout")
    332 value = (resp[3] << 24 | resp[2] << 16 | resp[1] << 8 | resp[0] << 0)
    333 target_logger.debug("Read {:04X} from {:02X}".format(value, addr))

OSError: timeout

So I run what worked for me before when running LAB 2_1B:

SCOPETYPE = 'OPENADC'
PLATFORM = 'CW308_SAM4S'
SS_VER = 'SS_VER_2_1'

%run "../../Setup_Scripts/Setup_Generic.ipynb"

prog = cw.programmers.SAM4SProgrammer
cw.program_target(scope, prog, "../../../hardware/victims/firmware/simpleserial-trace/simpleserial-trace-CW308_SAM4S.hex")

Not sure what that does that fixes the issue but this did not give an error.

So started the full test again:

HUSKY_TARGET_PLATFORM=sam4s pytest ./test_husky.py --fulltest

Final results:

============================= FAILURES ====================================
____________________________ test_fw_version ___________________________
test_husky.py:483: in test_fw_version
    assert scope.sam_build_date == '13:17:41 Feb  9 2023'
E   AssertionError: assert '21:32:05 Jan 31 2023' == '13:17:41 Feb  9 2023'
E     - 13:17:41 Feb  9 2023
E     + 21:32:05 Jan 31 2023
______ test_segments[0-0-90-False-7370000.0-4-False-20-0-segments_trigger_no_offset] _________
test_husky.py:1136: in test_segments
    assert errors == 0, "Ratios = %s; errors: %s, params = %s" % (ratios, scope.adc.errors, funcparams)
E   AssertionError: Ratios = [1.0407061733948049, 1.0112685270828163, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0]; errors: slow FIFO underflow, , params = {'fulltest': True, 'offset': 0, 'presamples': 0, 'samples': 90, 'stream': False, 'clock': 7370000.0, 'adcmul': 4, 'seg_count': False, 'segs': 20, 'segcycs': 0, 'desc': 'segments_trigger_no_offset'}
E   assert 38 == 0
============================ short test summary info ================================
FAILED test_husky.py::test_fw_version - AssertionError: assert '21:32:05 Jan 31 2023' == '13:17:41 Feb  9 2023'
FAILED test_husky.py::test_segments[0-0-90-False-7370000.0-4-False-20-0-segments_trigger_no_offset] - AssertionError: Ratios = [1.0407061733948049, 1.0112685270828163, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0]; errors: slow FIFO underflow, , params = {'fulltest': True, 'offset': 0, 'presample...
========================= 2 failed, 138 passed, 6 skipped in 782.07s (0:13:02)

I also got some warnings and some skipped tests:

test_husky.py::test_segments[0-0-90-False-7370000.0-4-False-20-0-segments_trigger_no_offset] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
FAILED
test_husky.py::test_segments[0-10-90-False-7370000.0-4-False-20-0-segments_trigger_no_offset_presamp] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[10-0-90-False-7370000.0-4-False-20-0-segments_trigger_offset10_SLOW] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[50-0-90-False-7370000.0-4-False-20-0-segments_trigger_offset50_SLOW] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[50-20-90-False-7370000.0-4-False-20-0-segments_trigger_offset50_presamp] PASSED
test_husky.py::test_segments[0-0-100-True-7370000.0-4-False-2000-0-segments_trigger_stream_SLOW] PASSED
test_husky.py::test_segments[0-0-90-False-7370000.0-4-True-20-32500-segments_counter_no_offset] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[0-30-90-False-7370000.0-4-True-20-32500-segments_counter_no_offset_presamp_SLOW] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[10-0-90-False-7370000.0-4-True-20-32500-segments_counter_offset10_SLOW] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[50-0-90-False-7370000.0-4-True-20-32500-segments_counter_offset50_SLOW] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_segments[50-40-90-False-7370000.0-4-True-20-32500-segments_counter_offset50_presamp] (ChipWhisperer Target WARNING|File SimpleSerial.py:410) Unexpected start to command: z
PASSED
test_husky.py::test_trace[False-swo-firmware trigger-pattern-matched SWO trace, target-triggered] SKIPPED (No target detected or incorrect FW.)
test_husky.py::test_trace[True-swo-firmware trigger-raw SWO trace, target-triggered] SKIPPED (No target detected or incorrect FW.)
test_husky.py::test_trace[False-swo-0-pattern-matched SWO trace, trace-triggered] SKIPPED (No target detected or incorrect FW.)
test_husky.py::test_segment_trace[swo-1-1triggers] SKIPPED (No target detected or incorrect FW.)
test_husky.py::test_segment_trace[swo-10-10triggers] SKIPPED (No target detected or incorrect FW.)
test_husky.py::test_segment_trace[swo-21-21triggers] SKIPPED (No target detected or incorrect FW.)

jpthibault · May 12, 2023, 2:26pm

That all looks good actually - the remaining warnings / skipped tests are TraceWhisperer tests which required additional jumper wires.
And the programming failure is my bad, there was a missing scope.default_setup() in the code snippet I gave you.

But the mystery about the VCC alarm remains. Can you try a different computer, or connect through a good powered USB hub? Are you using a USB-C adapter?

zaphod · May 13, 2023, 3:03am

I think I figured out the issue. I was toggling scope.io.target_pwr in my reset_target() (I had some other issues earlier and I read a suggestion in one of the labs to add target_pwr toggling).

I removed toggling of the target_pwr and now I don’t seem to get the VCCaux alarm.

Do you know the answers to my other 2 issues in my original post?

Thanks!

zaphod · May 14, 2023, 11:05pm

Correction: I am still getting “VCCaux alarm”. But seems like it occurs only when I program the target with

prog = cw.programmers.SAM4SProgrammer
cw.program_target(scope, prog, "../../../hardware/victims/firmware/basic-passwdcheck/basic-passwdcheck-{}.hex".format(PLATFORM))

If I check the status of the errors I see the following (I cleared the error just before programming):

sam_errors      = serial rx overflow
sam_led_setting = Default
XADC errors     = VCCaux alarm, 
ADC errors      = False
extclk error    = False
trace errors    = False

 vccaux=1.805/1.686/1.874

If I clear the error after programming I don’t see it during capturing (so far at least).

jpthibault · May 16, 2023, 12:53pm

I should have done this sooner but I can confirm that I see the same – it looks like toggling the target power (which is done by Setup_Generic.ipynb and by program_target()) causes a current draw which spikes the FPGA’s VCCaux and triggers the alarm. This doesn’t seem to happen with other targets.

We’ll have to figure out the best way to address this; for now you can simply manually clear the error. There isn’t really anything to worry about because the VCC alarm limits are very conservative (the absolute maximum rating for VCCaux is 2.0V).

Now regarding your other original questions - yes, that plot looks good; it’s different from our example because it’s a different target. But you can clearly see the difference between the two traces, which is what the attack will leverage.

The serial buffer overrun message is caused by all the extraneous my_puts() messages that are output at the start of the while loop in main(); if you comment them out the error will go away. I’m not sure why these are popping up now; regardless, you should be able to successfully complete the lab.

jpthibault · May 18, 2023, 1:20pm

FYI this commit should address the issue. We now use a “soft power-on” sequence to try to limit the inrush current that’s causing the voltage spikes. The parameters may need some tweaking but hopefully this will address the issue. Thanks for flagging the problem!

zaphod · May 21, 2023, 7:52pm

Verified! Thanks.

Btw, %run "../../Setup_Scripts/Setup_Generic.ipynb" sets the scope.errors.sam_errors flag to serial rx overflow

Perhaps the Setup_Generic.ipynb script should clear any errors?

jpthibault · May 22, 2023, 12:34am

Again this is due to all the my_puts() that get run after reset in main(). We’re still investigating while the overflow message is popping up now, but you can safely ignore it. (or comment out the extraneous my_puts() to avoid it altogether)