MultiWii 2.4 Nav 7 initial connection is ok, but how to slow down MSP communications.

[fbezruchko]

I have old multiwii 2.41 nav version 7. MWPtools successfully connects to it, but it has a lot msp timeouts and freezes:

2019-05-06T00:12:35+1000 mwp startup version: mwp local / 2019-04-13 2.095.731
2019-05-06T00:12:35+1000 on Linux Mint 19.1 user-Aspire-V3 Linux 4.15.0-48-generic x86_64
2019-05-06T00:12:35+1000 Failed to find "blackbox_decode" on PATH
2019-05-06T00:12:35+1000 Using speech api 1 [espeak]
2019-05-06T00:12:35+1000 libchamplain 0.12.16
2019-05-06T00:12:37+1000 Starting Bing proxy 
2019-05-06T00:12:37+1000 BB load async map zoom : true
2019-05-06T00:12:37+1000 Delta speed 0,000000
2019-05-06T00:13:00+1000 Try connect /dev/ttyUSB0
2019-05-06T00:13:00+1000 Connected /dev/ttyUSB0
2019-05-06T00:13:00+1000 Serial ready
2019-05-06T00:13:01+1000 set mrtype=14 cap =10
2019-05-06T00:13:01+1000 Error on cmd MSP_CMDS_API_VERSION 1
2019-05-06T00:13:01+1000 Generate navconf 7
2019-05-06T00:13:01+1000 Masks arm 1 angle 2 horz 4 ph 20 rth 10 wp 80
2019-05-06T00:13:01+1000 Sensors: Acc Mag GPS  (000d)
2019-05-06T00:13:01+1000 switch val == 00000000 (00000006)
2019-05-06T00:13:01+1000 init icon 14
2019-05-06T00:13:01+1000 Timer cycle for 7 items, 42 => 102 bytes
2019-05-06T00:13:01+1000 Start poller
2019-05-06T00:13:03+1000 MSP Timeout (MSP_CMDS_ALTITUDE)
2019-05-06T00:13:06+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:09+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:10+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:11+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:12+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:13+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:14+1000 message => No data for 5s
2019-05-06T00:13:14+1000 Alert: beep-sound.ogg
2019-05-06T00:13:14+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:15+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:17+1000 MSP Timeout (MSP_CMDS_NAV_STATUS)
2019-05-06T00:13:18+1000 MSP Timeout (MSP_CMDS_STATUS)
2019-05-06T00:13:19+1000 MSP Timeout (MSP_CMDS_STATUS)
2019-05-06T00:13:20+1000 MSP Timeout (MSP_CMDS_STATUS)
2019-05-06T00:13:21+1000 MSP Timeout (MSP_CMDS_STATUS)
2019-05-06T00:13:22+1000 MSP Timeout (MSP_CMDS_STATUS)
2019-05-06T00:13:22+1000 message => No data for 5s

... and so on.

I use usb to serial converter. In EOSBandi's WinGUI for MW works better, but i need change nav version 7 to 5 and firmware version to 2.30. And it does not upload missions.

I hope on mwptools.

[stronnag]

Are you using a virtual machine (VirtualBox for example)?

Although I no longer use mwp with multiwii, I do test with a MW board, and there are no comms errors in (my) native environment.

Anyway, nice that someone is trying to use it with MW, I suspect we will find some real bugs due to 'inav assumptions'.

[stronnag]

You can always invoke mwp with mwp --raw-log to log the complete serial data, but it will just show that mwp is not receiving data ...

[stronnag]

And it really helps if you build mwp from a cloned git repository, then we get the commit version in the log.

[fbezruchko]

Ok, hi, @stronnag. 1. I dont use virtualbox, i use "true" pc with linux mint 19. Also i have build mwptools from source from github. I have some raw logs (link bellow). Now i have only one idea. In the beginning of raw file i see "v2". As i can understand it means that mwp uses MSP v2 protocol to communicate with FC. But, i have old MultiWii 2.4 based on AVR, and it has MSP v1. In protocol.cpp (here: https://github.com/multiwii/multiwii-firmware/blob/upstream_shared/Protocol.cpp) i can see ever:
// Multiwii Serial Protocol 0 #define MSP_VERSION 0
Maybe this is a problem?

Link to raw: https://yadi.sk/d/evDdqiuWzhkIeQ

[stronnag]

Thanks. mwp talks MSP v1 to MSP v1 clients (like MW, old iNav) and MSP v2 to modern iNav. It is auto-detected. The v2 in the raw log refers to the log file format (as I add a version string it when we introduced MSPv2), as it was necessary to modify the record header to accommodate that MSPv2 can be longer than 256 bytes.

So to your log, there is a tool mwptools/samples/parseraw.rb that analyses the log. When I run it on your log, initially I see the expected sequence of 'o' (request outbound packets) and 'i' (response inbound packets) until the near the end, where you flight controller stops responding:
(comments preceded by '#')

$ ./parseraw.rb /tmp//mwp_2019-05-09_173210.raw 
#  ...
# cut earlier stuff
#  ... 
# records start offset time (s), message length (bytes) and direction 'o' or 'i'
# then we show the MSP message ID and the raw data 
offset 67.667663 len 6 o
MSP 107 :"$M<\x00kk"
24 4d 3c 00 6b 6b 
offset 67.671444 len 11 i
MSP 107 :"$M>\x05k\x00\x00\x00\x00\x00n"
24 4d 3e 05 6b 00 00 00 00 00 6e 
offset 67.671493 len 6 o
MSP 108 :"$M<\x00ll"
24 4d 3c 00 6c 6c 
offset 67.67731 len 12 i
MSP 108 :"$M>\x06l\xF3\xFF\n\x00\xE7\xFFt"
24 4d 3e 06 6c f3 ff 0a 00 e7 ff 74 
offset 67.677441 len 6 o
MSP 109 :"$M<\x00mm"
24 4d 3c 00 6d 6d 
offset 67.682718 len 12 i
MSP 109 :"$M>\x06m\x00\x00\x00\x00\x00\x00k"
24 4d 3e 06 6d 00 00 00 00 00 00 6b 
offset 67.682792 len 6 o
MSP 101 :"$M<\x00ee"
24 4d 3c 00 65 65 
offset 67.68882 len 17 i
MSP 101 :"$M>\ve\xF0\n\x00\x00\r\x00\x00\x00\x00\x00\x00\x99"
24 4d 3e 0b 65 f0 0a 00 00 0d 00 00 00 00 00 00 99 
offset 67.68891 len 6 o
MSP 121 :"$M<\x00yy"
24 4d 3c 00 79 79 
offset 67.693943 len 13 i
MSP 121 :"$M>\ay\x00\x00\x00\x00\n\x00\x00t"
24 4d 3e 07 79 00 00 00 00 0a 00 00 74 
#
# after this successful MSP 121 'NAV_STATUS', your board stops responding. mwp repeats the request c. every seconds
# 
offset 67.693981 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 68.649051 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 69.654513 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 70.658455 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 71.66388 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 72.66842 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 73.67197 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 
offset 74.675977 len 6 o
MSP 106 :"$M<\x00jj"
24 4d 3c 00 6a 6a 

So, at offset 67.693981 (seconds), your board stops responding.

For reference, my old, 2014-era Multiwii board works perfectly with mwp; so far it's been running for just over 15 minutes and processed almost 60000 MSP messages.

2019-05-09T17:12:45+0100 963s, rx 866928b, tx 358992b, (900b/s, 373b/s) to 6 wait 0, avg poll loop 96 ms messages 59830

Maybe this is a problem?

No, the problem is that your board stops responding to MSP.

[fbezruchko]

Thanks a lot! I will try to analyze communication. One question: How i can reduce frequency of communication? I mean add little delay between any two MSP commands from mwp to FC:

1. MSP > FC

2. Answer from FC to mwp

3. delay

4. next MSP > FC
   and so on.

[fbezruchko]

I guess, I find my problem. MWP works perfect, problem in my hardware. I use custom GPS through additional SoftwareSerial. I check around interrupts for it, but not for UART ISR. When FC receive NMEA messages from GPS it cant answer to mwp. I think MSP packets may to be brocken this period. In EOSBandi's WinGUI and MultiWiiConf its work, because those apps have another communication logic. WinGUI has default RX/TX frequency 5Hz, MultiWiiConf - about 50Hz (I think). And both apps try to restore communication on its frequency - when there is no answer from FC, MultiWiiConf and WinGUI dont wait 1 sec before retry. And I see like everything is OK. And more, GPS NMEA comes every 1 sec. And MSP retrys comes from mwp every 1 sec too. And I think, this conflict repeats several periods, until time moments do not shift due to the difference in the generators. I dont have osciloscope yet to check my hypothesis.

Can You give me a link to the code region, where i can reduce retry interval (just for my version of mwp) and check my hypothesis. I hope my idea is clear - sorry for my English.

[stronnag]

I'm pleased you've found the issue.

mwp does not work in the same way as WinGui or MWConf; it is (strictly) event driven and sends the next MSP request as soon as it has received /processed the previous response. This was to avoid issues (overflows, lost messages in the FC) caused by having a fixed timer.

There is a 'house-keeping' timer that checks for lost messages. This runs every 100ms. You can change how frequently the 'no response' check occurs by configuration.

$ gsettings get org.mwptools.planner poll-timeout 
uint32 900
# 900 + 100 gives the actual check interval (don't ask, historical).
# so for a more frequent check:
$ gsettings set org.mwptools.planner poll-timeout 100
# there is now 200ms lost message check. 

However, my guess is that this probably doesn't help; it may be that rather than sending each request in a single write(), for your use case, it might help to write each byte individually, possibly with an inter-character delay.

+++ common/serial-device.vala	2019-05-10 07:46:12.397235040 +0100
@@ -1202,7 +1202,14 @@
         if((commode & ComMode.BT) == ComMode.BT)
             size = Posix.send(fd, buf, count, 0);
         else if((commode & ComMode.STREAM) == ComMode.STREAM)
-            size = Posix.write(fd, buf, count);
+        {
+            for(var i = 0; i < count; i++)
+            {
+                Posix.write(fd, &((uint8[])buf)[i], 1);
+                Thread.usleep(2*1000); // 2ms intercharacter delay
+            }
+            size = (ssize_t)count; // sort of ...
+        }
         else
         {
             unowned uint8[] sbuf = (uint8[]) buf;

I changed the title to more closely reflect the problem we're trying to solve.

[fbezruchko]

OK, thanks! I change poll-timeout to 130ms and it reduce freezes very well. Not 100%, but its usable now. Its enough for me, i think. GPS data has more priority and i cant do nothing - just drop some MSP messages. Close the issue.

I have another problem yet, may be it is not issue, but i need some help. Where i can ask you about upload mission procedure of mwp (I dont think "issues tab" is a right place for it - i think it is a not mwp issue)? What means notices: "Validation WPx fails for P1" and "Validation WPx fails for FLAG"?

[stronnag]

When you upload a mission, mwp downloads each point and verifies that it is what was uploaded (a safety check). Let me get out my MW board again ...

No problem here.

If you run mwp --debug-flags=1 , mwp should display what it sent and what it received (for WP validation).

This may be another symptom of the soft serial implementation affecting UART processing.

[fbezruchko]

I find problem. It was my mistake. I dont use a baro and incorrectly commented out on altitude parameter in packet. Now it works perfectly. Thank you, man!

About my project. I create a very very simple (shortest and clearness program) version of old MultiWii for fixed hardware and just for rovers/boats for K-12 pupils (12-16 years old). And education program based on it. They must understand how work IMU, navigation, RX and servo output. They build electronics from modules like arduino mini, GY-521, and ESP8266, write some code, and take part in the competition.

[stronnag]

Cool school programme, good luck with it. Wish I had things like that when I was at school (some time ago, we sent off handwritten programs (for punched cards / paper tape) via the mail steamer to the nearest university timeshare computer on the mainland). Three weeks later, the mail steamer returned a print out ("syntax error at line 2").