[Bug] Technichub garbles print output at CI-build 2063 and primehub does not #736

BertLindeman · 2022-10-15T16:16:06Z

Describe the bug
A print command like:

print("Waiting for remote connection to hub:", end=" ")
print('"' + str(hub.system.name()) + '" as a ' + version[0], "\n")

should produce

Waiting for remote connection to hub: "HubB_2063" as a technichub

but on a Technichub, it produces:

Waiting for reub: "HubB_2063" as a technichub

A Spike Prime hub at the same firmware level shows no problem.

('primehub', '3.2.0b3', 'v3.2.0b3-71-g8c8f70dc on 2022-10-10')
Waiting for remote connection to hub: "Spike_2063" as a primehub

To reproduce
Steps to reproduce the behavior:

Go to beta.pybricks.com
Connect bluetooth to a hub at CI-build level 2063
Load the program (see below)
run tun program (no devices need on the hub)
See the print output.

Expected behavior
Correct print output on both hubs

python program used

# from micropython import mem_info
# mem_info()

# import urandom
from pybricks.pupdevices import Remote

from pybricks.hubs import ThisHub
# from pybricks.robotics import DriveBase
from pybricks import version
print(version)

hub = ThisHub()
print("Waiting for remote connection to hub:", end=" ")
print('"' + str(hub.system.name()) + '" as a ' + version[0], "\n")

try:
    remote = Remote()
except Exception as e:
    print("=======\t\tNo remote connected\t=======\n", e)
    raise(SystemExit())

print("Connected to remote:", remote.name(), "\n")

Note to me: saved as /home/bert/py/pybricks/MOC-120171 - motorized defender\print_anomaly_issue.py

Extra info
The original program is larger, but the program above is the shortest I could find having this problem.
Ran on win11 (Edge) and on linux Mint (Google chrome)

In some cases adding

mem_info()

helps to get correct print output.
Does mem_info do garbage collect or something alike?

Screenshots
Not now

The text was updated successfully, but these errors were encountered:

dlech · 2022-10-15T21:08:58Z

I think I saw the same behavior recently as well. I didn't take the time to try to reproduce it yet though. This could be due to recent changes in the Bluetooth code that are using more RAM on the Bluetooth chip now.

BertLindeman · 2022-10-16T15:15:50Z

Looks like it one data frame from the hub to localhost is missing. But I see no refusal or fail in the trace.
In the bluetooth trace (NOT attached - refused by github) frame 66:

after this a frame is missing (with 20 bytes data)
The text should be Waiting for remote connection to hub:
But 20 bytes are missing: mote connection to h

Then frame 67:

The print output:

('technichub', '3.2.0b3', 'v3.2.0b3-71-g8c8f70dc on 2022-10-10')
Waiting for reub: "HubB_2063" as a technichub

=======         No remote connected     =======
 [Errno 116] ETIMEDOUT
Traceback (most recent call last):
  File "main.py", line 29, in <module>
SystemExit:

The program:

# from micropython import mem_info
# mem_info()

# import urandom
from pybricks.pupdevices import Remote

from pybricks.hubs import ThisHub
# from pybricks.robotics import DriveBase
from pybricks import version
print(version)

hub = ThisHub()

str1 = "Waiting for remote connection to hub: "
str2 = '"' + str(hub.system.name()) + '" as a ' + version[0] + "\n"
str_all = str1 + str2

#print("Waiting for remote connection to hub:", end=" ")
#print('"' + str(hub.system.name()) + '" as a ' + version[0], "\n")

print(str_all)
#print(len("mote connection to h"))

try:
    remote = Remote(timeout=100)
except Exception as e:
    print("=======\t\tNo remote connected\t=======\n", e)
    raise(SystemExit())

print("Connected to remote:", remote.name(), "\n")

The trace is refused as file . . . .
Retry to upload the trace, but now also zipped - failed with:
Something went really wrong, and we can't process that file
I give up on that . . .

BertLindeman · 2022-10-16T15:23:14Z

Trace file uploaded by MSEDGE. Previous attempts failed on FireFox 👎

captured_BT_issue#736_with_error.ntar.GZ

dlech · 2022-10-17T17:34:27Z

I was able to reproduce the bug, so should be fixed now. You can try the latest CI builds to test.

BertLindeman · 2022-10-17T17:35:32Z

Thank you David.

Already busy on it 👍

dlech · 2022-10-17T17:36:35Z

of course you are 😆

BertLindeman · 2022-10-17T17:52:46Z

Can you point me to "how to use pybricksdev beta" on windows or Linux.
The later CI builds do not (yet) work well with beta.pybricks.com

dlech · 2022-10-17T17:57:22Z

The easiest way ensure you are using the "latest" pybricksdev is to use pipx. The easiest way to get pipx is to install it with your package manager on Linux (e.g. sudo apt install pipx).

Then run pybricksdev like this:

pipx run pybricksdev run ble test.py

BertLindeman · 2022-10-17T20:16:24Z

Used build 2096 and later build 2113.
Maybe this is another problem, but the result is not always correct.

The program is the same as above.
A few sets of output with build 2113
Removed the progress bar, too confusing here.
Also removed this from all, as that is always the same:

=======         No remote connected     =======
 [Errno 116] ETIMEDOUT
Traceback (most recent call last):
  File "print_anomaly_issue.py", line 21, in <module>
SystemExit:

A few attempts:

Z:\home\bert\py\pybricks\MOC-120171 - motorized defender>py -3 -m pipx run pybricksdev run ble print_anomaly_issue.py
Searching for any hub with Pybricks service...

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for rhub: "Hub_A_2113" as a technichub

Z:\home\bert\py\pybricks\MOC-120171 - motorized defender>py -3 -m pipx run pybricksdev run ble print_anomaly_issue.py
Searching for any hub with Pybricks service...

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for remote connection to hub: "Hub_A_2113" as a technichub

Z:\home\bert\py\pybricks\MOC-120171 - motorized defender>py -3 -m pipx run pybricksdev run ble print_anomaly_issue.py
Searching for any hub with Pybricks service...

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for rhub: "Hub_A_2113" as a technichub

Z:\home\bert\py\pybricks\MOC-120171 - motorized defender>py -3 -m pipx run pybricksdev run ble print_anomaly_issue.py
Searching for any hub with Pybricks service...

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for rhub: "Hub_A_2113" as a technichub

The printed string is sometimes:
Waiting for rhub: "Hub_A_2113" as a technichub
and sometimes correct:
Waiting for remote connection to hub: "Hub_A_2113" as a technichub

dlech · 2022-10-17T20:22:07Z

Hmm... maybe there is yet another error code we need to check for.

dlech · 2022-10-17T20:59:13Z

In order to reproduce the problem again, I had to print literally the same thing you are printing instead of using runtime values:

# from micropython import mem_info
# mem_info()

# import urandom
from pybricks.pupdevices import Remote

from pybricks.hubs import ThisHub

# from pybricks.robotics import DriveBase
from pybricks import version

# print(version)
print("('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')")

hub = ThisHub()
# print("Waiting for remote connection to hub:", end=" ")
# print('"' + str(hub.system.name()) + '" as a ' + version[0], "\n")
print('Waiting for remote connection to hub: "Hub_A_2113" as a technichub")')

try:
    remote = Remote()
except Exception as e:
    print("=======\t\tNo remote connected\t=======\n", e)
    raise (SystemExit())

print("Connected to remote:", remote.name(), "\n")

BertLindeman · 2022-10-17T21:29:34Z

Not sure if this helps.
Without any background in bluetooth trace, I noticed this:

Frames 135 and 138 send parts of the program to the hub.
The string we want to see back is complete there.

Frames 155 through 160 is the data send by the hub. again missing 20 bytes.

The next frame:

The trace:
captured_BT_issue#736_with_error.ntar(2).gz.pcapng.gz

This partially reverts 38d8d2b. The change did not actually fix the bug. The testing method was faulty. Issue: pybricks/support#736

dlech · 2022-10-17T21:33:09Z

I think the problem is related to starting scanning for the remote at the same time as printing. This seems to cause us to drop one bluetooth packet.

BertLindeman · 2022-10-17T21:46:06Z

I think the problem is related to starting scanning for the remote at the same time as printing. This seems to cause us to drop one bluetooth packet.

Seems the case indeed.
I took your program and added a wait(20) after
hub = ThisHub()
Did not see any problems yet. (Only tested 5 times....)

EDIT:
This wait is after the hub definition, not before the scan for remote.
Not exactly what you ment I think.

dlech · 2022-10-17T22:07:44Z

The prints are buffered, so it is basically the same as long as it didn't print too much.

This adds an additional retry in the case where we don't get the correct command status after sending a notification. This seems to happen occasionally when we are printing and trying to connect to the remote at the same time. Fixes: pybricks/support#736

dlech · 2022-10-17T22:38:48Z

I think I might have fixed it for real this time.

laurensvalk · 2022-10-18T07:05:24Z

Is this related to #417?

BertLindeman · 2022-10-18T07:23:30Z

Affraid there is good and bad news....

Took firmware from drv/bluetooth_stm32_cc2640: retry notification when no status Build #2118

The good:
Did not see missing print output on your original print_anomaly_issue_DAVID.py

The bad:

Just a feeling that raise SystemExit() takes longer to really quit.
The test with an extra wait before the print now produces 20 bytes extra output.
Now with a wait:
Waiting for remote connection to hub: "Honnection to hub: "Hub_X_nnnn" as a technichub")
But expected:
Waiting for remote connection to hub: "Hub_X_nnnn" as a technichub")

DR;TL 4 times the same test now produces the same result:

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for remote connection to hub: "Honnection to hub: "Hub_X_nnnn" as a technichub")
=======         No remote connected     =======
[Errno 116] ETIMEDOUT
Traceback (most recent call last):
File "print_anomaly_issue_DAVID_plus_wait.py", line 30, in <module>
SystemExit:

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for remote connection to hub: "Honnection to hub: "Hub_X_nnnn" as a technichub")
=======         No remote connected     =======
[Errno 116] ETIMEDOUT
Traceback (most recent call last):
File "print_anomaly_issue_DAVID_plus_wait.py", line 30, in <module>
SystemExit:

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for remote connection to hub: "Honnection to hub: "Hub_X_nnnn" as a technichub")
=======         No remote connected     =======
[Errno 116] ETIMEDOUT
Traceback (most recent call last):
File "print_anomaly_issue_DAVID_plus_wait.py", line 30, in <module>
SystemExit:

('technichub', '3.2.0b3', 'v3.2.0b3-118-gb193756e on 2022-10-17')
Waiting for remote connection to hub: "Honnection to hub: "Hub_X_nnnn" as a technichub")
=======         No remote connected     =======
[Errno 116] ETIMEDOUT
Traceback (most recent call last):
File "print_anomaly_issue_DAVID_plus_wait.py", line 30, in <module>
SystemExit:

BertLindeman · 2022-10-18T07:58:19Z

To add to the confusion (sorry)

The Cityhub on build 2118 acts the same as the TechnicHub
The MoveHub on build 2118 huh?
WITH wait output is OK:
Waiting for remote connection to hub: "Hub_X_nnnn" as a technichub")

WITHOUT Wait there is output missing:
Waiting for remote connection to hub: "Hnichub")

[EDIT]:

Spike Primehub on build 2118 shows no problems

dlech · 2022-10-18T14:54:05Z

Is this related to #417?

Similar, but probably not the same since that issue only appears to affect the move hub and this one only affects the technic/city hubs.

This reverts commit 7755b28. This caused duplicate output in some cases, so isn't the correct fix. Issue: pybricks/support#736

dlech · 2022-10-18T14:58:27Z

I'm going to revert the previous "fix" that is causing the extra output for now and try again later.

dlech · 2022-10-18T17:57:04Z

3rd attempt seems less hacky, so 🤞 maybe it is fixed for real this time?

laurensvalk · 2022-10-18T18:02:44Z

Not to nitpick, but can we avoid merging to master right away if unsure?

BertLindeman · 2022-10-18T19:30:41Z

OK on the TechnicHub.
OK on the CityHub.
Not OK on the MoveHub. Even on a simple print does not get correct output.
Example:

print("          1         2         3         4         5         6         7         8")
print("0123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 ")

produces:

          1         2         3         4         5         6         7         8
0123456789 123456789 123456789 123456789 123456789 123456789
789

With a wait(20) after each print, the output is correct:

          1         2         3         4         5         6         7         8
0123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789

dlech · 2022-10-18T20:16:49Z

OK on the TechnicHub.
OK on the CityHub.

Great!

Not OK on the MoveHub. Even on a simple print does not get correct output.

Let's continue that discussion on #417 since the issues with the move hub are already described there.

Similar to efda5d0, this avoids bugs by only allowing the Bluetooth chip to do one thing at a time and blocks other requested tasks until the previous ones have completed. This helps prevent the Bluetooth chip from getting in a bad state and fixes some existing known bugs. We can also now drop the workaround for [1] from 7d7434f (which in addition to the changes in this commit is also now avoided by a01772b). [1]: pybricks/support#736 Fixes: pybricks/support#567

BertLindeman added the triage Issues that have not been triaged yet label Oct 15, 2022

dlech closed this as completed in pybricks/pybricks-micropython@38d8d2b Oct 17, 2022

dlech self-assigned this Oct 17, 2022

dlech reopened this Oct 17, 2022

dlech added a commit to pybricks/pybricks-micropython that referenced this issue Oct 17, 2022

drv/bluetooth_stm32_cc2640: revert bleMemAllocError check

0228791

This partially reverts 38d8d2b. The change did not actually fix the bug. The testing method was faulty. Issue: pybricks/support#736

dlech closed this as completed in pybricks/pybricks-micropython@7755b28 Oct 17, 2022

dlech reopened this Oct 18, 2022

dlech closed this as completed in pybricks/pybricks-micropython@7d7434f Oct 18, 2022

BertLindeman mentioned this issue Oct 18, 2022

[Bug] Connecting to remote suppresses standard output #417

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Bug] Technichub garbles print output at CI-build 2063 and primehub does not #736

[Bug] Technichub garbles print output at CI-build 2063 and primehub does not #736

BertLindeman commented Oct 15, 2022

dlech commented Oct 15, 2022

BertLindeman commented Oct 16, 2022

BertLindeman commented Oct 16, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022 •

edited

Loading

dlech commented Oct 17, 2022

dlech commented Oct 17, 2022

laurensvalk commented Oct 18, 2022

BertLindeman commented Oct 18, 2022

BertLindeman commented Oct 18, 2022 •

edited

Loading

dlech commented Oct 18, 2022 •

edited

Loading

dlech commented Oct 18, 2022

dlech commented Oct 18, 2022 •

edited

Loading

laurensvalk commented Oct 18, 2022

BertLindeman commented Oct 18, 2022

dlech commented Oct 18, 2022

[Bug] Technichub garbles print output at CI-build 2063 and primehub does not #736

[Bug] Technichub garbles print output at CI-build 2063 and primehub does not #736

Comments

BertLindeman commented Oct 15, 2022

dlech commented Oct 15, 2022

BertLindeman commented Oct 16, 2022

BertLindeman commented Oct 16, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022

dlech commented Oct 17, 2022

BertLindeman commented Oct 17, 2022 • edited Loading

dlech commented Oct 17, 2022

dlech commented Oct 17, 2022

laurensvalk commented Oct 18, 2022

BertLindeman commented Oct 18, 2022

BertLindeman commented Oct 18, 2022 • edited Loading

dlech commented Oct 18, 2022 • edited Loading

dlech commented Oct 18, 2022

dlech commented Oct 18, 2022 • edited Loading

laurensvalk commented Oct 18, 2022

BertLindeman commented Oct 18, 2022

dlech commented Oct 18, 2022

BertLindeman commented Oct 17, 2022 •

edited

Loading

BertLindeman commented Oct 18, 2022 •

edited

Loading

dlech commented Oct 18, 2022 •

edited

Loading

dlech commented Oct 18, 2022 •

edited

Loading