{"action":"created","issue":{"url":"https://api.github.com/repos/foosel/OctoPrint/issues/2454","repository_url":"https://api.github.com/repos/foosel/OctoPrint","labels_url":"https://api.github.com/repos/foosel/OctoPrint/issues/2454/labels{/name}","comments_url":"https://api.github.com/repos/foosel/OctoPrint/issues/2454/comments","events_url":"https://api.github.com/repos/foosel/OctoPrint/issues/2454/events","html_url":"https://github.com/foosel/OctoPrint/issues/2454","id":301492331,"number":2454,"title":"Missing ok's causing printer to hang - serial buffer issue?","user":{"login":"cesarvandevelde","id":4973479,"avatar_url":"https://avatars3.githubusercontent.com/u/4973479?v=4","gravatar_id":"","url":"https://api.github.com/users/cesarvandevelde","html_url":"https://github.com/cesarvandevelde","followers_url":"https://api.github.com/users/cesarvandevelde/followers","following_url":"https://api.github.com/users/cesarvandevelde/following{/other_user}","gists_url":"https://api.github.com/users/cesarvandevelde/gists{/gist_id}","starred_url":"https://api.github.com/users/cesarvandevelde/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cesarvandevelde/subscriptions","organizations_url":"https://api.github.com/users/cesarvandevelde/orgs","repos_url":"https://api.github.com/users/cesarvandevelde/repos","events_url":"https://api.github.com/users/cesarvandevelde/events{/privacy}","received_events_url":"https://api.github.com/users/cesarvandevelde/received_events","type":"User","site_admin":false},"labels":[{"id":326275175,"url":"https://api.github.com/repos/foosel/OctoPrint/labels/type:potential%20bug","name":"type:potential bug","color":"f7c6c7","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2018-03-01T17:29:42Z","updated_at":"2018-03-02T20:24:32Z","closed_at":null,"author_association":"NONE","body":"#### What were you doing?\r\n\r\nOctoPrint occasionally stalls the GCode stream during prints. The issue is\r\nrelatively rare, and occurs roughly every 8-10 hours of printing. I have reason\r\nto believe this may be caused by a serial buffer overrun on the host side,\r\nplease refer to the sections below for my preliminary analysis.\r\n\r\nHere are the relevant settings on the OctoPrint side:\r\n- Port: `/dev/ttyAMA0` (RPi's built-in serial port). The RPi's serial pins are\r\n  connected via an active level-shifter to the RAMPS UART port.\r\n- Baud rate: `250000`\r\n- Temperature interval (autoreport): `2s`\r\n\r\nAnd the relevant Marlin settings:\r\n- Configuration.h:\r\n  - `#define SERIAL_PORT 0`\r\n  - `#define BAUDRATE 250000`\r\n  - `#define HOST_KEEPALIVE_FEATURE`\r\n  - `#define DEFAULT_KEEPALIVE_INTERVAL 2`\r\n  - `#define BUSY_WHILE_HEATING`\r\n- Configuration_adv.h:\r\n  - `#define MAX_CMD_SIZE 96`\r\n  - `#define BUFSIZE 4`\r\n  - `#define TX_BUFFER_SIZE 4`\r\n  - `//#define RX_BUFFER_SIZE 1024`\r\n  - `//#define NO_TIMEOUTS 1000`\r\n  - `//#define ADVANCED_OK`\r\n\r\n\r\n#### What did you expect to happen?\r\n\r\nI expected OctoPrint to reliably stream GCode files to the printer.\r\n\r\n#### What happened instead?\r\n\r\nOccasionally, OctoPrint gets stuck while midway through a print. The issue\r\noccurs roughy every 8-10 hours of print time, making the issue very hard to\r\ndiagnose.\r\n\r\nMy analysis shows that this issue caused by a garbled \"ok\" message from the\r\nprinter, causing OctoPrint to pause sending new commands until a fake\r\nacknowledgment is issued. Communication still works in this state, and OctoPrint\r\ncontinues to receive temperature status messages.\r\n\r\nI kept my eye on the situation and logged a bunch of corrupted messages, shown\r\nbelow. Note that each line is from a separate print job:\r\n```\r\nRecv:  T:210.26 /210.00 B:60.03 /60.00o\\x00k\r\nRecv:  T:209.87 /210.00 B:60.01 /60.00 @:100 Bo\\x00k\r\nRecv:  T:210.00 /210.0o\\x00k\r\nRecv:  T:210.05 /210.0o\\x00k\r\nRecv:  T:210.10 /210.0o\\x00k\r\nRecv:  T:209.82 /210.0o\\x00k\r\nRecv:  T:210.26 /210.00 B:60.03 /60.00o\\x00k\r\nRecv:  T:209.87 /210.00 B:60.01 /60.00 @:100 Bo\\x00k\r\nRecv:  T:210.00 /210.0o\\x00k\r\nRecv:  T:210.05 /210.0o\\x00k\r\nRecv:  T:210.10 /210.0o\\x00k\r\nRecv:  T:209.82 /210.0o\\x00k\r\nRecv:  T:209.96 /210.0o\\x00k\r\n```\r\n\r\nAll these lines show the same pattern: an `ok` message is interjected into an\r\nauto temp report message. The pattern is predictable, and it seems to me that\r\nthese errors cannot be caused by noise on the serial communication line\r\n(e.g. a bit-flip on the RX line). For good measure, I also probed TX/RX data\r\nlines, described below in section \"Printer model & used firmware incl. version\".\r\nMy measurements show a clean, crisp signal with minimal noise.\r\n\r\nSome further digging led me to the following issue on the Marlin GitHub\r\nrepository: MarlinFirmware/Marlin#9111. My takeaway from that discussion is that\r\nit is impossible for marlin to send an `ok` during a auto temperature report\r\nmessage, leading me to believe that the host side is at fault. My initial guess\r\nis that the RX serial buffer gets overrun, causing the two lines to be put\r\ntogether and introducing null characters (`\\x00`) into the stream. However, I am\r\nnot familiar with the OctoPrint serial port API.\r\n\r\nTo alleviate the issue, I hacked together a small plugin that looks for the\r\nstring `o\\x00k` in incoming lines of data, and returns `ok` if detected. Since\r\nusing this plugin, i've the print stream freeze only once. I suspect this is\r\nbecause the garble was in a different spot.\r\n\r\nhttps://gist.github.com/cesarvandevelde/6e4b54ce1977cb89ffa875d095c550af\r\n\r\nThe plugin also logs instances of garbled messages, though null characters are\r\ncuriously dropped from the log. Below are two log files from the plugin:\r\n\r\n```\r\n2018-02-02 18:13:45,907 Garbled OK detected:\r\n2018-02-02 18:13:45,909 --------------------------------------------------------------------------------\r\n2018-02-02 18:13:45,910 Send: M110 N0\r\n2018-02-02 18:13:45,910 Recv: o\u0000k\r\n\r\n2018-02-02 18:13:45,911 --------------------------------------------------------------------------------\r\n2018-02-02 20:19:59,496 Garbled OK detected:\r\n2018-02-02 20:19:59,497 --------------------------------------------------------------------------------\r\n2018-02-02 20:19:59,498 Send: G1 X101.15 Y51.325 E1069.44284\r\n2018-02-02 20:19:59,499 Recv: ok\r\n\r\n2018-02-02 20:19:59,499 Send: G1 X100.387 Y51.183 E1069.46865\r\n2018-02-02 20:19:59,500 Recv: ok\r\n\r\n2018-02-02 20:19:59,500 Send: G1 X99.613 Y51.183 E1069.4944\r\n2018-02-02 20:19:59,501 Recv: ok\r\n\r\n2018-02-02 20:19:59,502 Send: G0 F7200 X99.417 Y51.219\r\n2018-02-02 20:19:59,502 Recv: ok\r\n\r\n2018-02-02 20:19:59,503 Send: G1 F3000 E1068.9944\r\n2018-02-02 20:19:59,503 Recv:  T:209.82 /210.00 B:59.96 /60.00 @:102 Bo\u0000k\r\n\r\n2018-02-02 20:19:59,504 --------------------------------------------------------------------------------\r\n```\r\n\r\n```\r\n2018-02-10 16:18:37,453 Potential garble detected:\r\n2018-02-10 16:18:37,456 --------------------------------------------------------------------------------\r\n2018-02-10 16:18:37,456 Send: G1 X88.289 Y53.384 E241.48638\r\n2018-02-10 16:18:37,457 Recv: ok\r\n\r\n2018-02-10 16:18:37,458 Send: G1 X87.536 Y53.156 E241.51254\r\n2018-02-10 16:18:37,458 Recv: ok\r\n\r\n2018-02-10 16:18:37,459 Send: G1 X86.854 Y52.79 E241.53829\r\n2018-02-10 16:18:37,459 Recv: ok\r\n\r\n2018-02-10 16:18:37,460 Send: G1 X86.182 Y52.238 E241.56721\r\n2018-02-10 16:18:37,461 Recv: ok\r\n\r\n2018-02-10 16:18:37,461 Send: G1 X74.726 Y40.779 E242.10614\r\n2018-02-10 16:18:37,462 Recv:  T:210.10 /210.09\u00007 B@:41\r\n\r\n2018-02-10 16:18:37,463 --------------------------------------------------------------------------------\r\n2018-02-10 19:20:29,004 Potential garble detected:\r\n2018-02-10 19:20:29,005 --------------------------------------------------------------------------------\r\n2018-02-10 19:20:29,006 Send: G1 X111.867 Y145.848 E4089.55515\r\n2018-02-10 19:20:29,007 Recv: ok\r\n\r\n2018-02-10 19:20:29,007 Send: G1 X112.766 Y146.12 E4089.58639\r\n2018-02-10 19:20:29,008 Recv: ok\r\n\r\n2018-02-10 19:20:29,008 Send: G1 X113.592 Y146.562 E4089.61755\r\n2018-02-10 19:20:29,009 Recv: ok\r\n\r\n2018-02-10 19:20:29,009 Send: G1 X114.337 Y147.174 E4089.64962\r\n2018-02-10 19:20:29,010 Recv: ok\r\n\r\n2018-02-10 19:20:29,011 Send: G1 X125.799 Y158.636 E4090.18876\r\n2018-02-10 19:20:29,011 Recv:  T:209.33 /210.0/\u000060.00 @:110 B@:49\r\n\r\n2018-02-10 19:20:29,012 --------------------------------------------------------------------------------\r\n2018-02-10 20:48:43,800 Potential garble detected:\r\n2018-02-10 20:48:43,804 --------------------------------------------------------------------------------\r\n2018-02-10 20:48:43,805 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,806 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,807 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,808 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,808 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,809 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,809 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,810 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,811 Recv:  T:19.33 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,811 Recv:  T:19.29 /0.00 B:19.37 /0.00 @:0 \u0000T:19.29 /0.00 B:19.37 /0.00 @:0 B@:0\r\n\r\n2018-02-10 20:48:43,812 --------------------------------------------------------------------------------\r\n```\r\n\r\n#### Did the same happen when running OctoPrint in safe mode?\r\n\r\nI have not tried to reproduce this issue in safe mode.\r\n\r\n#### Version of OctoPrint\r\n\r\nOctoPrint 1.3.6\r\n\r\n#### Operating System running OctoPrint\r\n\r\nOctoPi 0.14.0 running on a Raspberry Pi 2\r\n\r\n#### Printer model & used firmware incl. version\r\n\r\nSelf-sourced Prusa i3 running Marlin 1.1.8 on RAMPS1.4/Mega2560. Serial port is\r\nconnected via GPIO pins, not over USB. The Pi's TXD/RXD pins are connected via\r\nan active level shifter to the RXD/TXD pins of the RAMPS board. A quick probing\r\nwith my Logic analyzer shows a clean signal with crisp edges, negligible noise\r\nand minimal cross-talk.\r\n\r\n<img width=\"965\" alt=\"pi_serial_tx\" src=\"https://user-images.githubusercontent.com/4973479/36859371-63790b9c-1d7e-11e8-982e-5e4057770018.png\">\r\n\r\n<img width=\"1176\" alt=\"pi_serial_rx\" src=\"https://user-images.githubusercontent.com/4973479/36859380-6c6eeece-1d7e-11e8-87f2-d126be1f764f.png\">\r\n\r\n\r\n\r\n#### Browser and Version of Browser, Operating System running Browser\r\n\r\nNot applicable.\r\n\r\n#### Link to octoprint.log\r\n\r\nhttps://gist.github.com/cesarvandevelde/d51439ece12b35bb9faa4e87ec229eb9\r\n\r\n#### Link to contents of terminal tab or serial.log\r\n\r\nPlease see above.\r\n\r\n#### Link to contents of Javascript console in the browser\r\n\r\nNot applicable\r\n\r\n#### Screenshot(s)/video(s) showing the problem:\r\n\r\nNot applicable.\r\n\r\nI have read the FAQ.\r\n"},"comment":{"url":"https://api.github.com/repos/foosel/OctoPrint/issues/comments/370042253","html_url":"https://github.com/foosel/OctoPrint/issues/2454#issuecomment-370042253","issue_url":"https://api.github.com/repos/foosel/OctoPrint/issues/2454","id":370042253,"user":{"login":"cesarvandevelde","id":4973479,"avatar_url":"https://avatars3.githubusercontent.com/u/4973479?v=4","gravatar_id":"","url":"https://api.github.com/users/cesarvandevelde","html_url":"https://github.com/cesarvandevelde","followers_url":"https://api.github.com/users/cesarvandevelde/followers","following_url":"https://api.github.com/users/cesarvandevelde/following{/other_user}","gists_url":"https://api.github.com/users/cesarvandevelde/gists{/gist_id}","starred_url":"https://api.github.com/users/cesarvandevelde/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cesarvandevelde/subscriptions","organizations_url":"https://api.github.com/users/cesarvandevelde/orgs","repos_url":"https://api.github.com/users/cesarvandevelde/repos","events_url":"https://api.github.com/users/cesarvandevelde/events{/privacy}","received_events_url":"https://api.github.com/users/cesarvandevelde/received_events","type":"User","site_admin":false},"created_at":"2018-03-02T20:24:32Z","updated_at":"2018-03-02T20:24:32Z","author_association":"NONE","body":"I've been looking around for info on serial ports in linux, and came to the same conclusion: the buffer size cannot be adjusted. Seems that this is driver-dependent or even hardware-dependent...\r\n\r\nTo me, this feels like a \"perfect storm\" type of deal, where a number of different factors work together to create a situation where a buffer overrun can occur:\r\n- High baud rate\r\n- Small buffer due to hardware serial (16 bytes vs 64 bytes on USB)\r\n- Large RTL resulting in only 2 bytes of safety margin\r\n- Slower processor (I'm using a RPi 2)\r\n- Slow single-byte transfers inside PySerial\r\n- Auto temp enabled, meaning that temperature reports can arrive at any given time\r\n- GCode with lots of short line segments, increasing the probability of an `ok` collision. \r\n\r\nI can see a number of different solutions:\r\n1. As you mentioned, perhaps using bulk reads will solve the problem.\r\n2. Disable auto temp reports. This does not feel like a good solution to me as it as it doesn't address the underlying issue.\r\n3. Incorporate a more advanced version of my hacky plugin into the OctoPrint comm layer. It should be doable to detect incoming \\x00 characters and use that to information to trigger a fake ack when the stream gets stalled.\r\n4. Find a way to either increase the buffer or decrease the RTL. This solution would be hardware-specific, though I imagine a substantial segment of users run OctoPrint on a Raspberry Pi.\r\n\r\nRight now, I'm exploring option 4. I think I've found a way to decrease the RTL by manually modifying one of the control registers of the Pi's serial port. [This PDF](https://www.raspberrypi.org/app/uploads/2012/02/BCM2835-ARM-Peripherals.pdf) lists all the UART registers of the Pi's Broadcom SoC. Of particular interest is `TXIFLSEL`, listed on p188. \r\n\r\nI think it should be possible to modify this register using the [raspi-direct](https://github.com/offis/raspi-directhw) library, though I'll need to write a custom executable for that. Furthermore, there is a difference between the different RPi models. RPi models with wifi/bt use the high-performance /dev/ttyAMA0 port to communicate with the bluetooth module. As a substitute, the less performant mini-UART port is routed to the GPIO pins instead...\r\n"}}
{"actor":{"display_login":"cesarvandevelde"}}