Ant.GenericChannel callback double-up

Hi, I'm not sure if this is a bug or not, but my GenericChannel callback seems to get called twice for every single message. This is causing me problems in particular because I'm receiving Ant.MSG_CODE_EVENT_TRANSFER_TX_COMPLETED twice every time I call Ant.GenericChannel.sendAcknowledge(), which is disrupting my state machine.

I only have one Connect app on my Edge 520. I only have one profile using one Connect data field. I've looked everywhere to find the cause.

I have distilled the code into a single-file app, which exhibits the problem, attached below. The suspicious debug output from this app includes lines like this, where you can see the msg.timestamp value is repeated.

*** id=78, timestamp=29667, Obj: 144
*** id=78, timestamp=29667, Obj: 144
*** id=78, timestamp=46051, Obj: 144
*** id=78, timestamp=46051, Obj: 144
*** id=78, timestamp=62435, Obj: 144
*** id=78, timestamp=62435, Obj: 144
*** id=78, timestamp=13282, Obj: 144
*** id=78, timestamp=13282, Obj: 144
*** id=78, timestamp=29666, Obj: 144
*** id=78, timestamp=29666, Obj: 144
*** id=78, timestamp=46050, Obj: 144
*** id=78, timestamp=46050, Obj: 144


Any tips would be greatly appreciated...I'm out of ideas.
Thanks.


using Toybox.Application;
using Toybox.System;
using Toybox.Communications;
using Toybox.Background;
using Toybox.Ant;

using Toybox.WatchUi as Ui;
using Toybox.Graphics as Gfx;
using Toybox.Time;

class DataFieldView extends Ui.SimpleDataField {

function initialize() {
SimpleDataField.initialize();
label = "test";
}

function compute(info) {
return Time.now().value();
}
}


class DataFieldApp extends Application.AppBase {
const DEVICE_ID = 22;
const DEVICE_TYPE = 0x08;
const MESSAGE_PERIOD = 32768 / 2;

var channel;

function initialize() {
AppBase.initialize();
}

function onStart(state) {
channel = new Ant.GenericChannel(method(:onMessage), new Ant.ChannelAssignment(Ant.CHANNEL_TYPE_RX_NOT_TX, Ant.NETWORK_PUBLIC));

var device = new Ant.DeviceConfig({
:deviceNumber => DEVICE_ID,
:deviceType => DEVICE_TYPE,
:transmissionType => 0,
:messagePeriod => MESSAGE_PERIOD,
:radioFrequency => 66, // 66 is the default frequency band
:searchTimeoutLowPriority => 12, //30s timeout
:searchThreshold => 0}); //pair to all transmitting devices

channel.setDeviceConfig(device);

channel.open();
}

function onStop(state) {
channel.release();
channel = null;
}

function getInitialView() {
return [ new DataFieldView() ];
}

function onMessage(msg) {
System.println("*** id=" + msg.messageId + ", " + msg.timestamp + ", " + msg);

var payload = msg.getPayload();

if(Ant.MSG_ID_BROADCAST_DATA == msg.messageId) {
}

else if(Ant.MSG_ID_CHANNEL_RESPONSE_EVENT == msg.messageId) {
if(payload[0] == Ant.MSG_ID_RF_EVENT) {
var messageCode = payload[1];
System.println("messageCode=" + messageCode.format("%X"));

switch(messageCode) {
case Ant.MSG_CODE_EVENT_CHANNEL_CLOSED:
System.println("channel closed; trying to re-open");
channel.open();
break;
}

} else {
//message is a "channel response"
var initiatingMsgId = payload[0];
var responseCode = payload[1];
if(responseCode != Ant.MSG_CODE_RESPONSE_NO_ERROR) {
System.println("******** channel response, msgId=" + initiatingMsgId.format("%X") + ", responseCode=" + responseCode.format("%X"));
}
}
}

else {
System.println("******** unknown= " + msg.messageId.format("%X"));
}
}
}

  • I should note that my real code is based of the sample code, with e.g.
    class Sensor extends Ant.GenericChannel {
    ...
    }


    but the simplified code above exhibits the same problem
  • I'm not sure what the msg.timestamp is. The documentation says it rolls over every 2 seconds and that it's based on the 32768 kHz clock When I insert the following println into the same spot in my code where you had yours, I get the following output.

    Sys.println("*** id=" + msg.messageId + ", " + msg.timestamp + ", " + msg + ", getTimer " + Sys.getTimer());

    Apparently, I'm seeing 2 calls of onMessage as well based on the getTimer value I'm seeing.

    *** id=78, 37632, Obj: 35, getTimer 486779312
    *** id=78, 37632, Obj: 35, getTimer 486779312
    *** id=78, 37632, Obj: 35, getTimer 486779562
    *** id=78, 37632, Obj: 35, getTimer 486779562
    *** id=78, 37632, Obj: 35, getTimer 486779812
    *** id=78, 37632, Obj: 35, getTimer 486779812
    *** id=78, 37632, Obj: 35, getTimer 486780062
    *** id=78, 37632, Obj: 35, getTimer 486780062
    *** id=78, 37632, Obj: 35, getTimer 486780312
    *** id=78, 37632, Obj: 35, getTimer 486780312
    *** id=78, 37632, Obj: 35, getTimer 486780562
    *** id=78, 37632, Obj: 35, getTimer 486780562
    *** id=78, 37376, Obj: 35, getTimer 486780812
    *** id=78, 37376, Obj: 35, getTimer 486780812
    *** id=78, 37376, Obj: 35, getTimer 486781062
    *** id=78, 37376, Obj: 35, getTimer 486781062
    *** id=78, 37376, Obj: 35, getTimer 486781406
    *** id=78, 37376, Obj: 35, getTimer 486781406
    *** id=78, 37376, Obj: 35, getTimer 486781562
    *** id=78, 37376, Obj: 35, getTimer 486781562
    *** id=78, 37376, Obj: 35, getTimer 486781812
    *** id=78, 37376, Obj: 35, getTimer 486781812
    *** id=78, 37376, Obj: 35, getTimer 486782062
    *** id=78, 37376, Obj: 35, getTimer 486782062
    *** id=78, 37376, Obj: 35, getTimer 486782312
    *** id=78, 37376, Obj: 35, getTimer 486782312
    *** id=78, 37376, Obj: 35, getTimer 486782593
    *** id=78, 37376, Obj: 35, getTimer 486782593
    *** id=78, 37376, Obj: 35, getTimer 486782812
    *** id=78, 37376, Obj: 35, getTimer 486782812
    *** id=78, 37376, Obj: 35, getTimer 486783062
    *** id=78, 37376, Obj: 35, getTimer 486783062
    *** id=78, 37376, Obj: 35, getTimer 486783312
    *** id=78, 37376, Obj: 35, getTimer 486783312
    *** id=78, 37376, Obj: 35, getTimer 486783562
    *** id=78, 37376, Obj: 35, getTimer 486783562
    *** id=78, 37376, Obj: 35, getTimer 486783812
    *** id=78, 37376, Obj: 35, getTimer 486783812
    *** id=78, 37376, Obj: 35, getTimer 486784062
    *** id=78, 37376, Obj: 35, getTimer 486784062
    *** id=78, 37376, Obj: 35, getTimer 486784312
    *** id=78, 37376, Obj: 35, getTimer 486784312
    *** id=78, 37376, Obj: 35, getTimer 486784562
    *** id=78, 37376, Obj: 35, getTimer 486784562
    *** id=78, 37376, Obj: 35, getTimer 486784812
    *** id=78, 37376, Obj: 35, getTimer 486784812
    *** id=78, 37376, Obj: 35, getTimer 486785062
    *** id=78, 37376, Obj: 35, getTimer 486785062
    *** id=78, 37376, Obj: 35, getTimer 486785312
    *** id=78, 37376, Obj: 35, getTimer 486785312
    *** id=78, 37376, Obj: 35, getTimer 486785562
    *** id=78, 37376, Obj: 35, getTimer 486785562
    *** id=78, 37376, Obj: 35, getTimer 486785812
    *** id=78, 37376, Obj: 35, getTimer 486785812
    *** id=78, 37376, Obj: 35, getTimer 486786171
    *** id=78, 37376, Obj: 35, getTimer 486786171
    *** id=78, 37376, Obj: 35, getTimer 486786312
    *** id=78, 37376, Obj: 35, getTimer 486786312
  • It might be helpful to determine that they are in fact the same. Your log messages don't show anything else indicating they are broadcast traffic or channel responses without error but not what they are. Maybe adding a statement there to determine they are in fact the same message and being called twice or two unique messages. Did you already put logging there to determine that, from your post I can't tell.

    EDIT: You might have in fact already determined this with your real code but the sample code above doesn't indicate that.
  • I'm not sure what the msg.timestamp is. The documentation says it rolls over every 2 seconds and that it's based on the 32768 kHz
    clock


    Yes, I saw that. I'm not sure why your timestamp isn't changing. Mine is null for some messages, and as posted above for others. But it does change.


    Apparently, I'm seeing 2 calls of onMessage as well based on the getTimer value I'm seeing.


    Ok, at least it's not something wacky in my environment. Depending on one's use case, this may or may not be a problem. In my case I'm trying to send multiple packets from a queue, and am relying on the Ant.MSG_CODE_EVENT_TRANSFER_TX_COMPLETED message (which is documented in D00000652_ANT_Message_Protocol_and_Usage_Rev_5.1.pdf) to pop the queue. Therefore, getting it twice is a problem.

    Thanks for checking the issue in your codebase; that was helpful.
  • Maybe adding a statement there to determine they are in fact the same message and being called twice or two unique messages. Did you already put logging there to determine that, from your post I can't tell.


    Yes, it's a good point. I do have more code, posted below, to check on various flags. The message object itself is the same object id always, which is probably an optimisation reusing the same memory. I haven't checked every byte of the payload for duplicates - I will do that. A more extensive channel session shows messages such as channel response messages always sent in twos as well.

    Here is almost verbatim my actual message handler:

    function onMessage(msg) {
    System.println("*** " + msg.timestamp + " " + msg);

    var payload = msg.getPayload();

    //see 9.5.5.1 of ANT_Message_Protocol_and_Usage for information on the following...

    if(Ant.MSG_ID_BROADCAST_DATA == msg.messageId) { //this is true every 'period' when the channel is open
    //System.println("*** rssi=" + msg.rssi);

    if(state.broadcastQueue.size() > 0 && !transmitting) {
    var page = state.broadcastQueue[0];
    var message = new Ant.Message();
    message.setPayload(page.serialize());
    transmitting = true;
    Ant.GenericChannel.sendAcknowledge(message);
    System.println("sendAck request, bq.size=" + state.broadcastQueue.size());
    }

    if(state.searching) {
    state.searching = false;
    device = GenericChannel.getDeviceConfig();
    System.println("deviceNumber=" + device.deviceNumber);
    }

    //state.lastPing = Time.now();

    switch(payload[0]) {
    //handle payload!
    }

    return;
    }

    if(Ant.MSG_ID_ACKNOWLEDGED_DATA == msg.messageId) {
    return;
    }

    if(Ant.MSG_ID_CHANNEL_RESPONSE_EVENT == msg.messageId) {
    if(payload[0] == Ant.MSG_ID_RF_EVENT) {
    //message is a "channel event"
    var messageCode = payload[1];

    System.println("messageCode=" + messageCode.format("%X"));

    switch(messageCode) {
    case Ant.MSG_CODE_EVENT_CHANNEL_CLOSED:
    System.println("channel closed; trying to re-open");
    open();
    break;
    case Ant.MSG_CODE_EVENT_RX_FAIL_GO_TO_SEARCH:
    state.searching = true;
    break;
    case Ant.MSG_CODE_EVENT_CRYPTO_NEGOTIATION_FAIL:
    //encrypted = false;
    break;
    case Ant.MSG_CODE_EVENT_CRYPTO_NEGOTIATION_SUCCESS:
    //encrypted = true;
    break;
    case Ant.MSG_CODE_EVENT_TX:
    // message was successfully sent (although not necessarily received)
    transmitting = false;
    break;
    case Ant.MSG_CODE_EVENT_TRANSFER_TX_COMPLETED: //WTF receiving two of these every time we call Ant.GenericChannel.sendAcknowledge(message) ???????!!!!!!!!!!1
    // message was sent and received
    state.broadcastQueue = state.broadcastQueue.slice(1, null); // pop the page
    System.println("sendAck complete, bq.size=" + state.broadcastQueue.size());
    transmitting = false;
    break;
    case Ant.MSG_CODE_EVENT_TRANSFER_TX_FAILED:
    // message was sent and not necessarily received
    transmitting = false;
    System.println("sendAck failed");
    break;
    case Ant.MSG_CODE_EVENT_RX_FAIL:
    // no message was received in the timeslot...oh well
    break;
    }
    } else {
    //message is a "channel response"
    var initiatingMsgId = payload[0];
    var responseCode = payload[1];
    if(responseCode != Ant.MSG_CODE_RESPONSE_NO_ERROR) {
    System.println("******** channel response, msgId=" + initiatingMsgId.format("%X") + ", responseCode=" + responseCode.format("%X"));
    }

    //case Ant.MSG_ID_PROXIMITY_SEARCH:
    //case Ant.MSG_ID_LOW_PRIORITY_SEARCH_TIMEOUT:
    //case 0x44: //Ant.MSG_ID_SEARCH_TIMEOUT symbol not found! WTF #234234
    }
    } else {
    System.println("******** unknown= " + msg.messageId.format("%X"));
    }
    }

  • FYI, adding some code at the top of onMessage to simply "return" on every second invocation, has my code working as expected, with bi-directional data transfer, channel closing, searching, and reopening, all working fine. I'll report this as a bug.
  • Thanks for the report, I'm reaching out to a couple of sources to see what might be happening.

    - Coleman
  • 40ft what version of CIQ SDK are you using? What software is your Edge? We are trying to pinpoint what version of the VM you are using.

    Thanks,
    - Coleman
  • Was using 2.4.3, now using 2.4.5. Edge 520 is 12.50