leonardo: touching serial port after upload interferes with 'while(!Serial);' loop

[PeterVH]

Versions: Leonardo, windows7, arduino 1.0.2 or 1.0.3

On windows, if you upload the ASCIITable sample and subsequently open the serial monitor, nothing gets printed.

Analysis: after uploading the sketch the serial port is touched (briefly opened) to take away the magic baud rate. (This was introduced to fix defect #995). However the sketch is already running and the 'while(!Serial);' loop sees the DTR becoming high and exits. As a consequence the sketch wants to send out its ascii table but the serial port will close soon after this and the data gets lost.

I investigated several options to solve this seemingly trivial problem but I found no good one.

The baudrate could be restored in the first (and then only) call to touchPort() routine (with baud rate 1200):

          ...
          port = (SerialPort) portId.open("tap", 2000);
          port.setSerialPortParams(irate, 8, SerialPort.STOPBITS_1, SerialPort.PARITY_NONE);
          port.setDTR(false);  // will trigger the reset but device will still be around a while
          port.setSerialPortParams(oldRate, 8, SerialPort.STOPBITS_1, SerialPort.PARITY_NONE);
          port.close();
          ...

.
This would probably work most of the time (I did not try it though) but it is no good idea to send requests to a device after you instructed it to reset.

Restoring the baud rate when the booter is running makes no sense: on windows the bootloader comes back on a different port.

So the only good place to restore the baud rate is where it is done now. But to avoid the problem described here, it the port should be opened without DTR/RTS becoming set. I did not found a way to do that with rxtx.

Solution: Therefore I think it is best to just roll back touching the port after upload (unless somebody comes with a new idea). After all, the original problem described in issue 995 is easy to work around manually.

Also note that the issue 995 causes problems on mac, see #1186.

[ffissore]

Please, give a spin to this nightly 1.5.5 version
http://downloads.arduino.cc/arduino-jssc-nightly-linux32.tgz
http://downloads.arduino.cc/arduino-jssc-nightly-linux64.tgz
http://downloads.arduino.cc/arduino-jssc-nightly-windows.zip
http://downloads.arduino.cc/arduino-jssc-nightly-macosx.zip

We have replaces RXTX with JSSC

[cmaglie]

@PeterVH
is this problem still present in 1.5.6? May you try?

[PeterVH]

I tried 1.5.6 r2 on windows7 64bit SP1. It still does not work correctly. it is easy to verify: upload the AsciiTable example, wait ~2sec and open the Serial monitor => nothing gets printed.

It looks like Serial's boolean operator returns true before the serial monitor is opened.

[PeterVH]

This modified version of AsciiTable's setup() might help investigate it:

void setup() { 

  //Initialize serial and wait for port to open:
  Serial.begin(9600);

  unsigned int i = 0;
  unsigned int rising_edges = 0, first_edge=0;
  boolean s0 = false;
  boolean s1;
  for (i=0; i<500; i++) {
    s1 = Serial;
    if (s1!=s0) {
      if (s1) {
        rising_edges++;
        if(first_edge==0)
          first_edge = i;
      }
      s0 = s1;
    }
  }
   while (!Serial) {
      ; // wait for serial port to connect. Needed for Leonardo only
  }

  Serial.print("rising_edges="); Serial.println(rising_edges, DEC);
  Serial.print("edge="); Serial.println(first_edge, DEC);
  Serial.println(s1 ? "open": "still NOT open");

  // prints title with ending line break 
  Serial.println("ASCII Table ~ Character Map"); 
} 

It takes the leo 5 seconds to execute the loop (the boolean operator delays 10 msec). So if you open the serial monitor within 5 seconds, the output will appear in it.
for 1.0.3 it counted 2 rising edges, first one at about i=50.
for 1.5.6 it counts 1 rising edge but always for i about 75, independent from the moment you open the serial monitor. If you open the serial monitor after say 10 seconds, the loop is done and nothing appears in the serial monitor.

[PeterVH]

Outside the ide, it works as documented:

-close the ide
-reset the Leonardo (the modified sketch already uploaded)
-wait say 10 seconds (the loop takes 5 seconds)
-open putty
-it reports "0 raising edges", "still NOT open", meaning that at the end of the loop the port is still not open (because putty not yet started). This is correct.

It is just with the ide + serial monitor that the boolean operator returns true too soon.

[matthijskooijman]

Yesterday, I noticed something with one of my Pinoccio boards. It's not a real Arduino, but with similar USB hardware as the Uno, i.e. a separate 16u2 or something like that to trigger reset on serial port open. In noticed that when starting up the IDE, the board would reset. This makes me believe that perhaps the IDE opens up serial ports now, presumably since the serial library switch. Then, when opening up a serial port using an external program, it resets again, making me believe the IDE does not keep the serial port open.

For my board, this behaviour caused two resets. However, for a Leonardo, opening up the serial port does not cause a reset, so perhaps this could explain the behaviour I'm seeing? I haven't investigated completely, nor have I read your sketch in detail, but perhaps this helps you figuring out what happens?

[cmaglie]

Hi @PeterVH
thanks for the detailed answer (especially for the test sketches, very helpful for understanding what's happening). Following your path I've made this test:

https://gist.github.com/cmaglie/9227782

this patch to CDC.cpp stores all the USB events in SRAM, so we can print them out on the UART of the leonardo and see them with an external USB2Serial converter.

I'll post in a minute what I've got so far.

[cmaglie]

Here we go, on linux32 with IDE 1.5.6-r2:

First upload of the test on the Leonardo:

-----------------------
USB trace:
SET_CONTROL - line state 0
SET_CODING - 9600baud - char format 0 - parity 0 - databits 8 - line state 0
SET_CONTROL - line state 3
SET_CONTROL - line state 0
------10 sec line------

We can notice that the port is opened and closed apparently without reason (state 3 and state 0)
If i try to open the serial monitor on the IDE (speed at 115200, previously set):

SET_CONTROL - line state 3
SET_CODING - 49664baud - char format 0 - parity 0 - databits 8 - line state 3

(49664 is 115200 with the highest bit truncated)
if I try to change speed from the serial monitor:

SET_CONTROL - line state 0
SET_CONTROL - line state 3
SET_CODING - 57600baud - char format 0 - parity 0 - databits 8 - line state 3

so, when changing speed the port is closed and reopened.
After closing the serial monitor:

SET_CONTROL - line state 0

as expected.

Now let's try another upload, so we can see the 1200bps touch:

SET_CONTROL - line state 3
SET_CODING  - 1200baud - char format 0 - parity 0 - databits 8 - line state 3
SET_CONTROL - line state 0



-----------------------
USB trace:
SET_CONTROL - line state 0
SET_CODING - 9600baud - char format 0 - parity 0 - databits 8 - line state 0
SET_CONTROL - line state 3
SET_CONTROL - line state 0
------10 sec line------

Now the SET_CODING is not a problem because it keeps the line state to 0, the real problem I guess is the third SET_CONTROL that sets line state to 3. After some digging I found that the cause of it is the touch at 9600 after the upload: I'm not sure, but I've the suspect that with JSSC we can get rid of it. In fact if I remove it from the IDE, after uploading I get:

SET_CONTROL - line state 3
SET_CODING - 1200baud - char format 0 - parity 0 - databits 8 - line state 3
SET_CONTROL - line state 0



-----------------------
USB trace:
SET_CONTROL - line state 0
SET_CODING - 9600baud - char format 0 - parity 0 - databits 8 - line state 0

that should keep the Leonardo before the while(!Serial); state, but I don't know if this doesn't reintroduce #995, I should make the same test with RXTX.

[PeterVH]

...but I don't know if this doesn't reintroduce #995

Well no, if you manage to remove the magic baud rate, you are ok.
I can test it with ArduinoISP on Leo if you want.

So with JSSC you can set the line coding without setting DTR/RTS? Well that looks the ideal solution to this problem. Note this needs to be tested on windows too (just uploading the AsciiTable sample and see if it apears in serial monitor), this stuff is very os dependent (the JSSC implementation might be too).

I should make the same test with RXTX.

Why?

[PeterVH]

(Nice piece of printf debugging btw.)

[cmaglie]

Well, really its the OS that sets the port back to 9600, I guess that is the USB-CDC driver of linux that do this automatically, this is the reason why I would like to test RXTX to see if the "spurious" touch at 1200 is an issue related to RXTX or not. BTW if you could test the #995 issue with the 1.5.6 and the following patch, it would be a great confirm that the path we are trying is correct:

--- a/app/src/cc/arduino/packages/uploaders/SerialUploader.java
+++ b/app/src/cc/arduino/packages/uploaders/SerialUploader.java
@@ -136,25 +136,13 @@ public class SerialUploader extends Uploader {
           // sketch port never comes back). Doing this saves users from accidentally
           // opening Serial Monitor on the soon-to-be-orphaned bootloader port.
           Thread.sleep(1000);
-          long timeout = System.currentTimeMillis() + 2000;
-          while (timeout > System.currentTimeMillis()) {
+          long started = System.currentTimeMillis();
+          while (System.currentTimeMillis() - started < 2000) {
             List<String> portList = Serial.list();
-            if (portList.contains(uploadPort)) {
-              try {
-                Serial.touchPort(uploadPort, 9600);
-                break;
-              } catch (SerialException e) {
-                // Port already in use
-              }
-            }
+            if (portList.contains(uploadPort))
+              break;
             Thread.sleep(250);
           }
-        } else {
-          try {
-            Serial.touchPort(uploadPort, 9600);
-          } catch (SerialException e) {
-            throw new RunnerException(e);
-          }
         }
       }
     } catch (InterruptedException ex) {

[PeterVH]

Well, really its the OS that sets the port back to 9600, I guess that is the USB-CDC driver of linux that do this automatically,

That makes sense, but why did the os restore the 9600 baud and not the last known baud rate of 1200?

I tested the patch with ArduinoISP/Leonardo/Kubuntu 12.04:
I did not observe #995.
Note that on kubuntu, issue #1203 did not occur (that is with or without patch)

I ll make some time this week to test on win7.

[PeterVH]

Just tested on win7 64 bit sp1. #1203 is fixed without reintroducing #995.

It troubles me a bit I don't understand completely what is going on (see question above) but the problem seems fixed.

[cmaglie]

Fix merged f50ec33

@PeterVH
yeah that's weird, my guess is that RXTX was caching the baudrate (and also making a "spurious" port opening with that speed!) . Notice that even if the OS sets the speed at 9600 bps, it still doesn't open the port (if you look at my trace the port status is always 0) as it should be.