arduino/arduino-create-agentPublic

NotificationsYou must be signed in to change notification settings
Fork158
Star453

fix: Serial Monitor corrupted output in some rare cases#1032

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 ourterms of service andprivacy statement. We’ll occasionally send you account related emails.

Already on GitHub?Sign in to your account

Jump to bottom

Merged

cmaglie merged 4 commits intomainfrommultiple_opens

Apr 24, 2025

Merged

fix: Serial Monitor corrupted output in some rare cases#1032

cmaglie merged 4 commits intomainfrommultiple_opens

Apr 24, 2025

Conversation

Copy link

Member

cmaglie commentedApr 23, 2025•
edited
Loading

Please check if the PR fulfills these requirements

The PR has no duplicates (please search among thePull Requests before creating one)
Tests for the changes have been added (for bug fixes / features)

What kind of change does this PR introduce?

This is a tentative fix for#1031

What is the current behavior?

The Serial Monitor may give corrupted output.

What is the new behavior?

The Serial Monitor should not show corrupted output anymore.

Does this PR introduce a breaking change?

Other information:

Fix#1031

Copy link

codecov-commenter commentedApr 23, 2025•
edited
Loading

Codecov Report

Attention: Patch coverage is0% with20 lines in your changes missing coverage. Please review.

Project coverage is 20.24%. Comparing base(87f097b) to head(fb2220f).
Report is 1 commits behind head on main.

Files with missing lines	Patch %	Lines
serialport.go	0.00%	16 Missing⚠️
serial.go	0.00%	4 Missing⚠️

Additional details and impacted files

@@           Coverage Diff           @@##             main    #1032   +/-   ##=======================================  Coverage   20.23%   20.24%           =======================================  Files          42       42             Lines        3242     3241    -1     =======================================  Hits          656      656+ Misses       2499     2498    -1  Partials       87       87

Flag	Coverage Δ
unit	`20.24% <0.00%> (+<0.01%)`	⬆️

Flags with carried forward coverage won't be shown.Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report?Share it here.

🚀 New features to boost your workflow:

❄️Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

per1234 reviewed

Apr 23, 2025

View reviewed changes

Copy link

Contributor

per1234 left a comment

Choose a reason for hiding this comment

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

I verified that the fault of the corrupted serial data (which I can reliably reproduce when using version 1.7.0 of Cloud Agent) no longer occurs when using the test build from this pull request.

However, I encounter a different fault when using the test build: sometimes when I change the baud rate, it does not take effect.

For example, this is the Cloud Agent Debug Console output that was produced when I changed the baud rate from 115200 to 9600:

[...]{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}close /dev/cu.usbserial-0001Closing serial port /dev/cu.usbserial-0001Shutting down reader on /dev/cu.usbserial-0001{  "Cmd": "Close",  "Desc": "Got unregister/close on port.",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200}writerBuffered just got closed. make sure you make a new one. port:/dev/cu.usbserial-0001Shutting down writer on /dev/cu.usbserial-0001open /dev/cu.usbserial-0001 9600 timedopen /dev/cu.usbserial-0001 9600 timed{  "Cmd": "Open",  "Desc": "Got register/open on port.",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200,  "BufferType": "timed"}{  "P": "/dev/cu.usbserial-0001",  "D": "Hets #�\u001d@��\u0004�:��\"%=� clock div:1\r\nload:0x3fff0030,len:4888\r\nload:0x40078000,len:16516\r\nload:0x40080400,len:4\r\nload:0x40080404,len:3476\r\nentry 0x400805b4\r\n"}open /dev/cu.usbserial-0001 9600 timed{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}[...]

Note that the expected command was sent (though multiple times as also occurs when using 1.7.0), but the response from the Agent is:

{  "Cmd": "Open",  "Desc": "Got register/open on port.",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200,  "BufferType": "timed"}

(with theBaud key set to115200 instead of9600 as expected)

I checked 1.7.0 by changing the baud rate back and forth between 9600 and 115200 many times and this problem of the incorrect baud rate did not occur once. So it does appear to be a regression introduced by the changes proposed by this PR.

cmaglie force-pushed themultiple_opens branch fromeae0887 toc2bee84Compare

April 23, 2025 13:28

Synchronize multiple open commands coming together.

5bd8910

cmaglie force-pushed themultiple_opens branch fromc2bee84 to5bd8910Compare

April 23, 2025 13:33

Copy link

MemberAuthor

cmaglie commentedApr 23, 2025

I've made another change@per1234, could you try the commit5bd8910 as soon as the build is ready?

per1234 reviewed

Apr 23, 2025

View reviewed changes

Copy link

Contributor

per1234 left a comment

Choose a reason for hiding this comment

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

When using the build from5bd8910, the Arduino Cloud Editor Serial Monitor fails to reconnect to the port when I change the baud rate:

Here is the debug console output from changing the baud rate from 9600 to 115200:

[...]{  "P": "/dev/cu.usbserial-0001",  "D": "�"}{  "P": "/dev/cu.usbserial-0001",  "D": "�"}close /dev/cu.usbserial-0001Closing serial port /dev/cu.usbserial-0001Shutting down reader on /dev/cu.usbserial-0001{  "Cmd": "Close",  "Desc": "Got unregister/close on port.",  "Port": "/dev/cu.usbserial-0001",  "Baud": 9600}Shutting down writer on /dev/cu.usbserial-0001writerBuffered just got closed. make sure you make a new one. port:/dev/cu.usbserial-0001open /dev/cu.usbserial-0001 115200 timedopen /dev/cu.usbserial-0001 115200 timed{  "Cmd": "Open",  "Desc": "Got register/open on port.",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200,  "BufferType": "timed"}{  "Cmd": "OpenFail",  "Desc": "Error opening port. Serial port busy",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200}{  "P": "/dev/cu.usbserial-0001",  "D": "�@1\u0012$T�tp�L&��fff0030,len:4888\r\nload:0x40078000,len:16516\r\nload:0x40080400,len:4\r\nload:0x40080404,len:3476\r\nentry 0x400805b4\r\n"}open /dev/cu.usbserial-0001 115200 timed{  "Cmd": "OpenFail",  "Desc": "Error opening port. Serial port busy",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200}{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}open /dev/cu.usbserial-0001 115200 timed{  "Cmd": "OpenFail",  "Desc": "Error opening port. Serial port busy",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200}{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}open /dev/cu.usbserial-0001 115200 timed{  "Cmd": "OpenFail",  "Desc": "Error opening port. Serial port busy",  "Port": "/dev/cu.usbserial-0001",  "Baud": 115200}{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}{  "P": "/dev/cu.usbserial-0001",  "D": "Hello, world!\r\n"}[...]

We can see from the output that the baud rate change was actually successful, but maybe the failures of the redundant commands cause Arduino Cloud Serial Monitor to think that the agent was not able to perform the operation?

Allow re-opening of already opened ports

ac3d1f9

Copy link

MemberAuthor

cmaglie commentedApr 23, 2025

We can see from the output that the baud rate change was actually successful, but maybe the failures of the redundant commands cause Arduino Cloud Serial Monitor to think that the agent was not able to perform the operation?

I think so, I changed the code again, now if a port is already opened, it will not return an error, but a success message with a "Port already opened" in the description. Let me know if this one works...

per1234 approved these changes

Apr 23, 2025

View reviewed changes

Copy link

Contributor

per1234 left a comment

Choose a reason for hiding this comment

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

Everything is now working perfectly for me.

#1031 no longer occurs.

The two regressions that I reported in my previous reviews no longer occur.

Thanks Cristian!

cmaglie requested a review froma team

April 24, 2025 08:08

cmaglie self-assigned this

Apr 24, 2025

cmaglie added topic: code

Related to content of the project itself

type: imperfection

Perceived defect in any part of project

criticality: highOf high impact labels

Apr 24, 2025

alessio-perugini approved these changes

Apr 24, 2025

View reviewed changes

lucarin91 reviewed

Apr 24, 2025

View reviewed changes

Copy link

Contributor

lucarin91 left a comment

Choose a reason for hiding this comment

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

I am wondering if it make sense to port this change also on the global client PR#1014

serialport.go OutdatedShow resolvedHide resolved

Renamed mutex var and added comment

59e8c0b

Copy link

MemberAuthor

cmaglie commentedApr 24, 2025

I am wondering if it make sense to port this change also on the global client PR#1014

We must port this change to#1014. AFAIU, even if#1014 removes the globals, it does not prevent simultaneous access to the same resource if multiple requests are coming from the websocket.

cmaglie requested a review fromlucarin91

April 24, 2025 10:50

cmaglie changed the title~~Synchronize multiple open commands coming together.~~fix: Serial Monitor corrupted output in some rare cases

Apr 24, 2025

Copy link

Contributor

Xayton commentedApr 24, 2025

I tried to open the same port multiple times, in a given websocket connection, and it works!

open /dev/cu.usbmodemC04E301217F82 9600{  "Cmd": "Open",  "Desc": "Got register/open on port.",  "Port": "/dev/cu.usbmodemC04E301217F82",  "Baud": 9600,  "BufferType": "default"}open /dev/cu.usbmodemC04E301217F82 9600{  "Cmd": "Open",  "Desc": "Port already opened.",  "Port": "/dev/cu.usbmodemC04E301217F82",  "Baud": 9600,  "BufferType": "default"}

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate). I think this is fine, but it would be nice to document this new behaviour.

Copy link

MemberAuthor

cmaglie commentedApr 24, 2025

but it would be nice to document this new behaviour

where?

Copy link

MemberAuthor

cmaglie commentedApr 24, 2025

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate).

Maybe it should return an error in this case (when the baudrate do not match)?

Copy link

Contributor

Xayton commentedApr 24, 2025

but it would be nice to document this new behaviour
where?

We could use the current documentation location (the Wiki), even if this means it's not part of the repo (and is not tracked together with other changes).

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate).
Maybe it should return an error in this case (when the baudrate do not match)?

Yes, we should probably return an error if the other parameters do not match (baudrate, but also the buffer algorithm).
Otherwise we have the open return a good state, but then the serial data received will be wrong/corrupted.

Xayton reviewed

Apr 24, 2025

View reviewed changes

serialport.go OutdatedShow resolvedHide resolved

Error out if baudrate and buftype of already opened port do not match

fb2220f

Copy link

MemberAuthor

cmaglie commentedApr 24, 2025

Yes, we should probably return an error if the other parameters do not match (baudrate, but also the buffer algorithm).
Otherwise we have the open return a good state, but then the serial data received will be wrong/corrupted

I've added a patch for this case.

Xayton approved these changes

Apr 24, 2025

View reviewed changes

Copy link

Contributor

Xayton left a comment

Choose a reason for hiding this comment

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

I tested the latest change and everything works:

open a port: OK (and get the list)
open again with the same baudrate: OK (no more list)
open with different parameters: fail to open

open /dev/cu.usbmodemC04E301217F82 9600{  "Cmd": "Open",  "Desc": "Got register/open on port.",  "Port": "/dev/cu.usbmodemC04E301217F82",  "Baud": 9600,  "BufferType": "default"}Serial Ports:[  {    "Name": "/dev/cu.usbmodemC04E301217F82",    "SerialNumber": "C04E301217F8",    "IsOpen": true,    "VendorID": "0x2341",    "ProductID": "0x1002"  }]open /dev/cu.usbmodemC04E301217F82 9600{  "Cmd": "Open",  "Desc": "Port already opened.",  "Port": "/dev/cu.usbmodemC04E301217F82",  "Baud": 9600,  "BufferType": "default"}open /dev/cu.usbmodemC04E301217F82 115200{  "Cmd": "OpenFail",  "Desc": "Error opening port. Serial port busy",  "Port": "/dev/cu.usbmodemC04E301217F82",  "Baud": 115200}

Copy link

Contributor

lucarin91 commentedApr 24, 2025

I am wondering if it make sense to port this change also on the global client PR#1014
We must port this change to#1014. AFAIU, even if#1014 removes the globals, it does not prevent simultaneous access to the same resource if multiple requests are coming from the websocket.

yeah, but I was suggesting to do this change directly in that PR, therespHandlerOpen became a method of hub struct so we can move the mutex on that struct directly

Copy link

MemberAuthor

cmaglie commentedApr 24, 2025

yeah, but I was suggesting to do this change directly in that PR, there spHandlerOpen became a method of hub struct so we can move the mutex on that struct directly

Let's merge this PR separately, so we can do a quick release with the fix.

I'll take care to port the mutex to the proper place in the other PR (we should handle the merge conflict in any case).