Speech output constantly reads wrong warning / status messages

[chriselsen]

In version: v2.7.3 RC1 I'm suddenly getting really bad behavior by the speech output.
During a flight I constantly get speech outputs on items that are not applicable.
E.g.

• DP2 reads "Disarmed" followed by "Armed" while vehicle is happily flying in the air.
• DP2 reads "No GPS lock" even though the display shows 10 sats, HDOP of 1.7 and a lock.
• DP2 reads "Weak signal" even though RSSI is over 90%.

These messages don't just happen once during a flight, but repeat over and over again, making a pilot believe there is something wrong with the quad. But it's not. Imho it makes DP2 in the current version unusable.
Going back to a previous version, fixes these issues.

Looking through the changes, I wonder if #1038 broke something here. Maybe you need a filter against MAVLINK glitches.

[squilter]

I'm getting some similar problems. Here's what I've been getting:

• "Lost -- GPS 3D Lock"
• "Bat -- Battery at 100 percent"

In both of these situations, it begins by saying one thing (i.e. "lost GPS lock") but then talks over itself with a correction.

[keyoss]

yes same here..
esp. bat-battery at... (if you have the old fashioned tts style enabled)

same for gps and signal ( even if rssi is disabled...)

[PaulHam211]

Yup, Same here! Lost GPS lock, dissarmed, ect...

[m4gr3d]

thanks for reporting! I'm going testing this afternoon. I'll try to pinpoint the source of the issue.

[m4gr3d]

@squilter @PaulHam211 @keyoss @chriselsen do you have Periodic status enabled?

[squilter]

No

[keyoss]

@ne0fhyk
at the very first test after the update i enabled periodics except rssi.
there i had all outputs with the described bat-battery effect.

after disabling periodics just gps lost' gps lock and bat-battery...

after reenable of periodics i never heard Voltage infos anymore...

[PaulHam211]

Periodic status was disabled when i tried it today.

[chriselsen]

No. It's disabled. I even disabled all warnings, except 400ft flight level. Still happening.
It's also often warning about flight mode changing to Unknown.

-------- Original message --------
From: Fredia Huya-Kouadio
Date:2014/09/07 10:33 (GMT-08:00)
To: DroidPlanner/droidplanner
Cc: Christian Elsen
Subject: Re: [droidplanner] Speech output constantly reads wrong warning / status messages (#1050)

@squilterhttps://github.com/squilter @PaulHam211https://github.com/PaulHam211 @keyosshttps://github.com/keyoss @chriselsenhttps://github.com/chriselsen do you have Periodic status enabled?

Reply to this email directly or view it on GitHubhttps://github.com//issues/1050#issuecomment-54753853.

[arthurbenemann]

I have tracked the bug down to the merge of #1009.

[m4gr3d]

@arthurbenemann #1009 was included in the 2.7.2_RC1 beta release. So we should have seen bug reports in that release as well.
The issue might be in the recent update to the tts logic (aka PR #1046).

[arthurbenemann]

@ne0fhyk Maybe people just didn't reported (it doesn't create an exception). I dissected the git history, and the problem appears from Droidplanner_v2.7.1-54-ge383a88 and forward from that.

I'm on to this bug now, so don't worry about it.

[arthurbenemann]

Interesting findings, take a look at this code:

        private void handleData(Parser parser, int bufferSize, byte[] buffer) {
            if (bufferSize < 1) {
                return;
            }

            for (int i = 0; i < bufferSize; i++) {
                MAVLinkPacket receivedPacket = parser.mavlink_parse_char(buffer[i] & 0x00ff);
                if (receivedPacket != null) {
                    if (receivedPacket.msgid==msg_gps_raw_int.MAVLINK_MSG_ID_GPS_RAW_INT) {
                        Log.d("msgReceived", receivedPacket.unpack().toString());
                    }
                    queueToLog(receivedPacket);
                    MAVLinkMessage msg = receivedPacket.unpack();
                    if (msg.msgid==msg_gps_raw_int.MAVLINK_MSG_ID_GPS_RAW_INT) {
                        Log.d("msgHandle", msg.toString());                 }

                    reportReceivedMessage(msg);
                }
            }
        }

And the corresponding logcat:

09-08 13:06:20.422: D/msgHandle(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:7002598000 lat:-353628751 lon:1491649699 alt:26355400 eph:0 epv:-1 vel:18 cog:13047 fix_type:3 satellites_visible:10
09-08 13:06:20.422: D/msgReport(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:7002598000 lat:-353628751 lon:1491649699 alt:26355400 eph:0 epv:-1 vel:18 cog:13047 fix_type:3 satellites_visible:10
09-08 13:06:20.733: D/msgReceived(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:7003004000 lat:-353628756 lon:1491649705 alt:26356890 eph:0 epv:-1 vel:18 cog:13011 fix_type:3 satellites_visible:10
09-08 13:06:20.733: D/msgHandle(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:0 lat:0 lon:0 alt:0 eph:0 epv:0 vel:0 cog:0 fix_type:0 satellites_visible:0
09-08 13:06:20.733: D/msgReport(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:0 lat:0 lon:0 alt:0 eph:0 epv:0 vel:0 cog:0 fix_type:0 satellites_visible:0
09-08 13:06:21.023: D/msgReceived(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:7003206000 lat:-353628758 lon:1491649709 alt:26357630 eph:0 epv:-1 vel:18 cog:12996 fix_type:3 satellites_visible:10
09-08 13:06:21.023: D/msgHandle(23236): MAVLINK_MSG_ID_GPS_RAW_INT - time_usec:7003206000 lat:-353628758 lon:1491649709 alt:26357630 eph:0 epv:-1 vel:18 cog:12996 fix_type:3 satellites_visible:10

[m4gr3d]

@arthurbenemann how often is the data being consumed. Is that easily repeatable?

The MAVLinkPacket#unpack() creates MAVLinkMessage that keep references to the MAVLinkPacket.
So somewhere, one of the consumer is most likely using that reference to modify the packet.

To fully fix the bug, we'd need to find which consumer is at fault, and fix that behavior.

[arthurbenemann]

@ne0fhyk Yes, I think queueToLog() was changing the fields of the message. On #1056 I made the app receive the message before the log writer, so at least the app works correctly.

[arthurbenemann]

how often is the data being consumed. Is that easily repeatable?

@ne0fhyk Once every 20 packets probably.

[m4gr3d]

@arthurbenemann your update will fix the issue but for different reasons :D

queueToLog(...) just queues the received packet for another thread to consume.

What was most likely happening, the receiving thread was calling unpack() to decode the MAVLinkMessage, while the queuing thread was calling encodePacket() to encode the packet as bytes. Both calls make use of the MAVLinkPayload#resetIndex(), so the payload's index was most likely 'corrupted' through unprotected concurrent access from both threads.

With your change, the receiving thread will complete its work before the packet is dispatched to the queuing thread, so that eliminates the risk of concurrent access to the mavlink packet's internal fields.