{"action":"created","issue":{"url":"https://api.github.com/repos/arduino/Arduino/issues/3745","labels_url":"https://api.github.com/repos/arduino/Arduino/issues/3745/labels{/name}","comments_url":"https://api.github.com/repos/arduino/Arduino/issues/3745/comments","events_url":"https://api.github.com/repos/arduino/Arduino/issues/3745/events","html_url":"https://github.com/arduino/Arduino/issues/3745","id":103936650,"number":3745,"title":"HardwareSerial library sometimes sends the same data twice","user":{"login":"johnholman","id":14043088,"avatar_url":"https://avatars.githubusercontent.com/u/14043088?v=3","gravatar_id":"","url":"https://api.github.com/users/johnholman","html_url":"https://github.com/johnholman","followers_url":"https://api.github.com/users/johnholman/followers","following_url":"https://api.github.com/users/johnholman/following{/other_user}","gists_url":"https://api.github.com/users/johnholman/gists{/gist_id}","starred_url":"https://api.github.com/users/johnholman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/johnholman/subscriptions","organizations_url":"https://api.github.com/users/johnholman/orgs","repos_url":"https://api.github.com/users/johnholman/repos","events_url":"https://api.github.com/users/johnholman/events{/privacy}","received_events_url":"https://api.github.com/users/johnholman/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/arduino/Arduino/labels/Component:%20HardwareSerial","name":"Component: HardwareSerial","color":"009800"},{"url":"https://api.github.com/repos/arduino/Arduino/labels/Type:%20Bug","name":"Type: Bug","color":"0052cc"},{"url":"https://api.github.com/repos/arduino/Arduino/labels/Type:%20Regression","name":"Type: Regression","color":"0052cc"}],"state":"open","locked":false,"assignee":{"login":"cmaglie","id":423515,"avatar_url":"https://avatars.githubusercontent.com/u/423515?v=3","gravatar_id":"","url":"https://api.github.com/users/cmaglie","html_url":"https://github.com/cmaglie","followers_url":"https://api.github.com/users/cmaglie/followers","following_url":"https://api.github.com/users/cmaglie/following{/other_user}","gists_url":"https://api.github.com/users/cmaglie/gists{/gist_id}","starred_url":"https://api.github.com/users/cmaglie/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cmaglie/subscriptions","organizations_url":"https://api.github.com/users/cmaglie/orgs","repos_url":"https://api.github.com/users/cmaglie/repos","events_url":"https://api.github.com/users/cmaglie/events{/privacy}","received_events_url":"https://api.github.com/users/cmaglie/received_events","type":"User","site_admin":false},"milestone":null,"comments":18,"created_at":"2015-08-30T17:56:27Z","updated_at":"2015-09-18T14:52:29Z","closed_at":null,"body":"Running a Arduino Mega 2560 program that makes heavy use of interrupts and that reports by sending lines of text (about 150 characters) in the main loop via the serial port at 115200 baud, I noiticed that additional spurious characters were sent on average every 2000 lines or so. Looking at the problem in more detail, what was transmitted was a line of exactly 66 characters consisting of the first few characters of the new line followed by last part of the line that had already been sent. The next line missed the first two characters, and then following ones were normal until the next occurrence.\r\n\r\nThese symptoms seemed consistent with void HardwareSerial::_tx_udr_empty_irq(void) occasionally being invoked at a time when the transmit buffer is in fact empty (i.e. _tx_buffer_head == _tx_buffer_tail), even though this should never happen. So I added some instrumentation:\r\n```\r\nvoid HardwareSerial::_tx_udr_empty_irq(void)\r\n{\r\n  // the buffer shouldn't be empty if we get here, but ...\r\n  if (_tx_buffer_head == _tx_buffer_tail) {\r\n    serial_errors++;\r\n```\r\nwhere serial_errors is defined in HardwareSerial.h as a private member\r\n\r\n\tvolatile uint8_t serial_errors;\r\n\r\nand added a method to read and print the error count as part of the main loop.\r\n\r\nThis confirmed that the problem is indeed associated with the ISR being entered at a time when the buffer is empty, as the error count increments by one each time the problem occurs.\r\n\r\nMy original code is quite complicated, but I've been able to replicate the problem with a simple testcase in which the loop prints as before while a timer interrupt runs every 0.5ms with an associated ISR running for 0.3ms. The error seems to occur more often at higher baud rates - at 500,000 baud it occurs every few seconds. I can provide the testcase if required.\r\n\r\nAs a workaround, I've added this section to the start of _tx_udr_empty_irq:\r\n```\r\nvoid HardwareSerial::_tx_udr_empty_irq(void)\r\n{\r\n  // the buffer shouldn't be empty if we get here, but ...\r\n  if (_tx_buffer_head == _tx_buffer_tail) {\r\n    serial_errors++;\r\n    // empty buffer so the interrupt should be disabled. Make it so and return.\r\n    cbi(*_ucsrb, UDRIE0);\r\n\treturn;\r\n  }\r\n...\r\n```\r\nThis fix seems to work for me, but I'm certainly not convinced that it is correct in all circumstances.\r\n\r\nI've not been able to figure out why the ISR is ever entered in this situation. Most but not all of the errors disappear if you comment out the part in the busy wait loop in write() that calls the ISR directly when interrupts are disabled globally. (No, I'm not printing to the serial port from an ISR!) Almost all disappear if in addition you comment out the optimisation that writes directly into the output register when the buffer is empty. However I've seen the problem very occasionally (but not with the test case) even when both optimisations are taken out.\r\n\r\n\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/arduino/Arduino/issues/comments/141474605","html_url":"https://github.com/arduino/Arduino/issues/3745#issuecomment-141474605","issue_url":"https://api.github.com/repos/arduino/Arduino/issues/3745","id":141474605,"user":{"login":"NicoHood","id":6888294,"avatar_url":"https://avatars.githubusercontent.com/u/6888294?v=3","gravatar_id":"","url":"https://api.github.com/users/NicoHood","html_url":"https://github.com/NicoHood","followers_url":"https://api.github.com/users/NicoHood/followers","following_url":"https://api.github.com/users/NicoHood/following{/other_user}","gists_url":"https://api.github.com/users/NicoHood/gists{/gist_id}","starred_url":"https://api.github.com/users/NicoHood/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/NicoHood/subscriptions","organizations_url":"https://api.github.com/users/NicoHood/orgs","repos_url":"https://api.github.com/users/NicoHood/repos","events_url":"https://api.github.com/users/NicoHood/events{/privacy}","received_events_url":"https://api.github.com/users/NicoHood/received_events","type":"User","site_admin":false},"created_at":"2015-09-18T14:52:29Z","updated_at":"2015-09-18T14:52:29Z","body":"It must be a race condition or ISR problem. I still search for the reason, but if you take this example sketch, it works if you put cli() and sei() around write():\r\n\r\n```cpp\r\n// arduino uno, 64 byte serial tx rx buffers, default\r\n\r\nconst int dledPin =  12;\r\nconst int ledPin =  13;\r\nbool ledState = LOW;\r\nunsigned long previousMillis = 0;\r\n\r\nvoid setup() {\r\n  pinMode(ledPin, OUTPUT);\r\n  pinMode(dledPin, OUTPUT);\r\n  pinMode(11, OUTPUT);\r\n  pinMode(10, OUTPUT);\r\n  pinMode(9, OUTPUT);\r\n  digitalWrite(dledPin, 0);\r\n  Serial.begin(2000000);\r\n}\r\n\r\nvoid loop() {\r\n  unsigned long currentMillis = millis();\r\n\r\n  if ((currentMillis - previousMillis) >= 1000) {\r\n\r\n    ledState = !ledState;\r\n\r\n    digitalWrite(dledPin, 1);\r\n    for (int i = 0; i < 500; i++) {\r\n      cli();\r\n      Serial.write('a');\r\n      sei();\r\n      //digitalWrite(dledPin, 0);\r\n      Serial.flush();\r\n      //digitalWrite(dledPin, 1);\r\n      delay(6);\r\n    }\r\n    digitalWrite(dledPin, 1);\r\n\r\n    previousMillis = millis();\r\n\r\n    digitalWrite(ledPin, ledState);\r\n\r\n  }\r\n}\r\n```"}}