Datalogging unreliable when MakeCode is connected via webUSB on V2.00 DAPLink 0255

[jaustin]

Describe the bug

(this is likely a CODAL/DAPLink bug that's affected by MakeCode, but filing here as the top level user-visible location)

Using current /beta and 0255 on a V2.00 micro:bit (Git SHA: 1436bdcc67029fdfc0ff03b73e12045bb6a9f272 ) I don't see reliable logging with the following progamme

To Reproduce Load the following into /beta

datalogger.onLogFull(function () {
    basic.showIcon(IconNames.No)
    while (true) {
        basic.pause(100)
    }
})
input.onGesture(Gesture.Shake, function () {
    if (input.buttonIsPressed(Button.AB)) {
        basic.showIcon(IconNames.Skull)
        datalogger.deleteLog()
        basic.clearScreen()
    }
})
basic.forever(function () {
    datalogger.log(datalogger.createCV("x", input.acceleration(Dimension.X)), datalogger.createCV("y", input.acceleration(Dimension.Y)), datalogger.createCV("z", input.acceleration(Dimension.Z)))
    led.toggle(2, 3)
})

Expected behavior I would get continuous logging until the log fills up. If I disconnect web USB and flash the program via mass storage, it works reliably.

If I flash via web USB and then check the log, sometimes it's empty. If I re-flash, the log might log some small number of values (typically up to 4 seconds) and then stop.

4 seconds is about the time it takes for the device to re-enumerate on my PC. I think this looks like the log getting clobbered during re-enumeration/mounting.

Screenshots Here's an example when mass storage flashing

Here's an example using web USB

(I got the following assert Assert.txt

File: .\source\rtos\RTX_Config.c Line: 191 Source: Application ) (notice the much shorter length of time)

MY_DATA_web_USB_HTM.zip

micro:bit version (please complete the following information): V2.00 running 0255 does not reproduce on V2.20 running 0257

Desktop (please complete the following information):

• OS: [e.g. iOS]
• Browser [e.g. chrome, safari]
• Version [e.g. 22]

Smartphone (please complete the following information):

• Device: [e.g. iPhone6]
• OS: [e.g. iOS8.1]
• Browser [e.g. stock browser, safari]
• Version [e.g. 22]

Additional context Add any other context about the problem here.

[jaustin]

Here's another example of a dodgy/corrupted file (I did a manual erase on this, but had the battery plugged in the whole time, so I think it really should have kept time MY_DATA.HTM.zip )

[jaustin]

@finneyj @johnvidler @carlosperate I think we need to take a look at this

[martinwork]

This may be a red herring, but... When the program below is WebUSB flashed, V2.0 and V2.2 play the tone more than once. There seems to be one extra reset with live, and two with beta. I was surprised that when a similar "on start" is added to the datalogging program, the tone plays just once. Removing the onLogFull block brings back the extra tones. The only significant difference seems to be whether init() is called early on. I don't know what causes the extra resets, so wonder if they are still doing something in the interface... maybe causing early I2C commands to be ignored?

music.playTone(262, music.beat(BeatFraction.Sixteenth))
basic.showNumber(2)
basic.forever(function () {
    basic.showNumber(1)
})

[jaustin]

I can't reproduce this using a beta build of 0257 on a micro:bit V2.00, so I'd say this is definitely related to the 0255 version. Additionally, it seems that the data corruption actually occurs when I plug the micro:bit in not when I flash... I'll keep looking into that to try and confirm, but here are two logs. The code was flashed from MakeCode and then logging happened during web usb connection. Then I closed the MakeCode tab and un/replugged the micro:bit. That resulted in a viable log. I then reconnected MakeCode and dis/reconnected the micro:bit and when opening the HTML again I got clobbered HTML. datalog before and after makecode webusb.zip

I can reproduce this, so it would appear the problem is happening on MakeCode connection not when the code is originally flashed.

For example: this file was correct, then after connecting with webUSB (and MakeCode rebooted the micro:bit) I got corrupted data:

[martinwork]

The resets also occur when you load up a project, if you plug in micro:bit with a project loaded, and if you switch makecode tabs.

[jaustin]

I cannot reproduce right now if I am only loading MakeCode live, rather than MakeCode beta. With 'live' the rate at which the status LED blinks is massively slower than beta. MY_DATA_no_unplug_makecode_running.HTM.zip

@pelikhan could recent web USB changes have affected this? Note that you don't have to plug/unplug the micro:bit to see this issue. Attached is an HTML file where I just pushed the code via web USB and did nothing else, and the log stops after 7 seconds.

[pelikhan]

The change is that we always scan for the jacdac exchange address. If it is not present, we end up scanning the whole flash twice.

---

From: Jonathan Austin @.> Sent: Monday, May 23, 2022 6:06:59 AM To: microsoft/pxt-microbit @.> Cc: Peli de Halleux @.>; Mention @.> Subject: Re: [microsoft/pxt-microbit] Datalogging unreliable when MakeCode is connected via webUSB on V2.00 DAPLink 0255 (Issue #4676)

I cannot reproduce right now if I am only loading MakeCode live, rather than MakeCode beta. With 'live' the rate at which the status LED blinks is massively slower than beta. MY_DATA_no_unplug_makecode_running.HTM.ziphttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fmicrosoft%2Fpxt-microbit%2Ffiles%2F8754723%2FMY_DATA_no_unplug_makecode_running.HTM.zip&data=05%7C01%7Cjhalleux%40microsoft.com%7C963868ca6aea4bf8706a08da3cbd1eff%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637889082010390743%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=DDCrlYgW99kLjFcwYdMOP34uDWRYVK%2ByGvFPeLg9s58%3D&reserved=0

@pelikhanhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fpelikhan&data=05%7C01%7Cjhalleux%40microsoft.com%7C963868ca6aea4bf8706a08da3cbd1eff%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637889082010390743%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=8QXoYazAECCkiTgTIR1Yp59P5DbzVuNcqPdLLvkbMJw%3D&reserved=0 could recent web USB changes have affected this? Note that you don't have to plug/unplug the micro:bit to see this issue. Attached is an HTML file where I just pushed the code via web USB and did nothing else, and the log stops after 7 seconds.

— Reply to this email directly, view it on GitHubhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fmicrosoft%2Fpxt-microbit%2Fissues%2F4676%23issuecomment-1134654860&data=05%7C01%7Cjhalleux%40microsoft.com%7C963868ca6aea4bf8706a08da3cbd1eff%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637889082010546985%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=MjUTSdMll5VtcolspcHJLOzsAnM65P3MTsZATN1qn2w%3D&reserved=0, or unsubscribehttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAA73QKK57CRF2IDWJFB35TTVLN7HHANCNFSM5WQEMBIQ&data=05%7C01%7Cjhalleux%40microsoft.com%7C963868ca6aea4bf8706a08da3cbd1eff%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637889082010546985%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=erzM5EX3wCuuskHAcav6Mb5SGYEySzFJMhGbTzlXhgI%3D&reserved=0. You are receiving this because you were mentioned.Message ID: @.***>

[pelikhan]

This is rather DAP command heavy, it might impact the data logging.

[pelikhan]

what does createCV mean?

[jaustin]

I think it's what @jwunderl did to make the data logging blocks no longer need arrays - I guessed it was "create column value"

[jaustin]

@pelikhan could we just halt the target while we do the heavy stuff?

[pelikhan]

Good idea, I will try that.

[pelikhan]

@mmoskal is changing the way we discover the jacdac exchange address. However, since Jacdac also uses Daplink when connected to webusb, it will stress it out while data logging is also enabled.

[jaustin]

Is it possible to prompt users that want JACDAC and data logging and have 0255 to update? 0256 and above have a BUSY flag that strongly mitigates the issues here and allows CODAL to know when DAPLink's overloaded. The issue here is the V2s already with 0255. For datalogging we have done loads of work in CODAL to avoid users needing to update for the main usage scenario.

[mmoskal]

the jacdac test is in https://github.com/microsoft/pxt-microbit/pull/4683

[pelikhan]

The UI is still advertising 0249, and the foundation docs are not mentionning 0256. Is 0256 redy for prime time?

Isn't this issue related to the serial+datalog issue as well?

[jaustin]

So, for different micro:bit versions there are different valid firmware versions right now V1.x: 0249 latest V2.00: 0255 latest V2.2x: 0257 latest

We're about to do a beta for 0257 for V2.00 and @carlosperate it would be ideal if we could do a build for V1.x with that too so we could bring all DAPLink to the same 'latest' version perhaps - is that feasible?

[microbit-carlos]

Yeah, we need to do a beta of DAPLink 0258-beta1 for micro:bit V2.00 soon, we could also do the same beta release for V1 at the same time. There shouldn't be any difference for V2.2 between 0257 and 0258-beta1, so no need to do a release for that.

[microbit-carlos]

I've raised https://github.com/microsoft/pxt-microbit/pull/4689 to see if it can mitigate this issue, which is still present in the latest beta with the jacdac scanning update (MakeCode beta as of last night, haven't tested the latest release this morning).

Would it be possible to get that deployed to beta? I was hoping raising the PR could create a test deployment, so that I could test it, but it looks like the “pxt-buildpush” workflow only triggers with commits on this repository, not PRs from forks (which in the security point of view it makes sense).

Btw, the latest CODAL tag basically increases the I2C wait timeout from 5ms to 20ms. When MakeCode is running with a micro:bit connected I've seen DAPLink I2C responses take 17-18ms to be ready, when without MakeCode they always did it within the original 5ms (and this was in January, so likely before the Jacdac feature inclusion). What is MakeCode doing via WebUSB to tax DAPLink so much?

[jaustin]

I've raised #4689 to see if it can mitigate this issue, which is still present in the latest beta with the jacdac scanning updating (MakeCode beta as of last night, haven't tested the latest release this morning).

Would it be possible to get that deployed to beta? I was hoping raising the PR could create a test deployment, so that I could test it, but it looks like the “pxt-buildpush” workflow only triggers with commits on this repository, not PRs from forks (which in the security point of view it makes sense).

@abchatra I think we need someone from MakeCode team to make the PR?

[microbit-carlos]

Just to clarify, the latest CODAL tag from https://github.com/microsoft/pxt-microbit/pull/4689 is good to be merged into beta as it is, the increase in the timeout is necessary independently of this issue (unless we think we can decrease the MakeCode WebUSB activity instead, which I would also welcome).

However, in the future, if we wanted to test any CODAL tags before merging them it looks like somebody with write access to this repo would need to raise a PR for us.

[pelikhan]

We poll daplink in a tight loop for serial data; if no data is available we stall daplink for 5000us... which probably upsets the data logger.

https://github.com/microsoft/pxt-microbit/blob/a822191245fe39271c6fa3882db7b3b081e99dd0/editor/flash.ts#L773

Now the question is how fast can a program fill the serial buffer if we rely on unreliable browser setTimeout and say have to wait 5+ms before trying to read the serial buffer.

@mmoskal

[jaustin]

Since Carlos's changes were merged into CODAL 0.2.38 I haven't seen this issue - the 5ms-->20ms wait Carlos talks about seems to tally with what @pelikhan mentioned about spinning DAPLink in a tight loop for 5ms, but does show we've probably just moved the problem away rather than hard fixed it.

[jaustin]

If anyone else that was previously able to reproduce can verify it doesn't happen for them with latest beta, I think we can close this.

[abchatra]

Closing as no action on makecode.