OTALog() issue/questions



  • I'm trying to use the OTA logging feature of MySensors and have been having some issues. They are illustrated in the code samples below. In the first example (CASE_1 in the code), I simply tried to send 3 log messages sequentially from the node to the gateway. When I do this, I only get Message1 and message3 at the gateway:

    The relevant code from the node:

        OTALog(0, true,PSTR("Message1: %d"),t);
        OTALog(0, true,PSTR("Message2: %d"),t);
        OTALog(0, true,PSTR("Message3: %d"),t);
    

    Gateway log:

    1540406467496 Case 1
    1540406470239 45;255;0;0;17;2.3.0-alpha
    1540406470240 45;255;3;0;6;0
    1540406472239 45;255;3;0;11;Temperature
    1540406472240 45;255;3;0;12;1.1
    1540406472240 45;0;0;0;6;
    1540406472272 45;255;3;0;9;9785 Message1: 0
    1540406472301 45;255;3;0;9;9815 Message3: 0
    1540406487989 45;255;3;0;9;25500 Message1: 1
    1540406488018 45;255;3;0;9;25530 Message3: 1
    

    in the second example (CASE_2 in the code) I added a call to wait(10); after each call to OTALog and this is the outcome:
    node log:

    1540407116393 Case 2
    1540407116393 Loop: 0
    1540407132103 Loop: 1
    

    Gateway log:

    1540407110239 Case 2
    1540407114366 45;255;0;0;17;2.3.0-alpha
    1540407114368 45;255;3;0;6;0
    1540407116366 45;255;3;0;11;Temperature
    1540407116368 45;255;3;0;12;1.1
    1540407116369 45;0;0;0;6;
    1540407116373 45;255;3;0;9;11142 Message1: 0
    1540407116385 45;255;3;0;9;11153 Message2: 0
    1540407116423 45;255;3;0;9;11192 Message3: 0
    1540407132083 45;255;3;0;9;26851 Message1: 1
    1540407132094 45;255;3;0;9;26860 Message2: 1
    1540407132132 45;255;3;0;9;26899 Message3: 1
    

    Now I get all the messages, but I shouldn't have had to add the wait() call, right?

    Next I tried sending a message larger than the payload size of 25 bytes (CASE_3).

    GW Log:

    1540407262935 Case 3
    1540407264796 45;255;0;0;17;2.3.0-alpha
    1540407264796 45;255;3;0;6;0
    1540407266796 45;255;3;0;11;Temperature
    1540407266796 45;255;3;0;12;1.1
    1540407266797 45;0;0;0;6;
    1540407266841 45;255;3;0;9;8912 Sending more than 25 charMessage1: 0
    1540407266878 45;255;3;0;9;8950 Message2: 0
    1540407282587 45;255;3;0;9;24657 Sending more than 25 charMessage1: 1
    1540407282626 45;255;3;0;9;24696 Message2: 1
    

    Only the first 25 characters are part of the resulting message and they are combined with the text from the second message.

    I then added #define MY_DEBUG_VERBOSE_TRANSPORT on the gateway (basically to cause some delays in the receiving code). After doing that, the long messages came through OK.

    Gateway log:

    1540407367325 Case 4
    ... (many TSF log messages)
    1540407369674 45;255;0;0;17;2.3.0-alpha
    1540407369675 0;255;3;0;9;7359 TSF:MSG:READ,45-45-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
    1540407369675 45;255;3;0;6;0
    1540407371672 0;255;3;0;9;9356 TSF:MSG:READ,45-45-0,s=255,c=3,t=11,pt=0,l=11,sg=0:Temperature
    1540407371674 45;255;3;0;11;Temperature
    1540407371674 0;255;3;0;9;9358 TSF:MSG:READ,45-45-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.1
    1540407371676 45;255;3;0;12;1.1
    1540407371676 0;255;3;0;9;9359 TSF:MSG:READ,45-45-0,s=0,c=0,t=6,pt=0,l=0,sg=0:
    1540407371676 45;0;0;0;6;
    ...
    1540407371680 0;255;3;0;9;9364 TSF:MSG:READ,45-45-0,s=255,c=3,t=9,pt=0,l=25,sg=0:Sending more than 25 char
    ...
    1540407371688 45;255;3;0;9;9371 Sending more than 25 characters: 0
    ...
    1540407371695 45;255;3;0;9;9378 Message1: 0
    ...
    1540407371733 45;255;3;0;9;9417 Message2: 0
    ...
    1540407387404 45;255;3;0;9;25085 Sending more than 25 characters: 1
    ...
    1540407387411 45;255;3;0;9;25093 Message1: 1
    ...
    1540407387451 45;255;3;0;9;25132 Message2: 1
    

    There are a few other test cases in the included code, but they serve to illustrate the point that there are some timing issues when using the OTALogging code.

    Or am I just missing something obvious to make this work correctly? There doesn't seem to be a whole lot of documentation about this newer feature. I have looked at the code in MyOTALogging.cpp and understand what it is doing, but the part I am unsure of is the actual transport mechanism. It seems like packets are getting dropped. My guess is that all the string manipulation and printing to the serial port are causing this.

    I am basically trying to get occasional log messages from my nodes to my controller (OpenHAB) and for now I will be sending only short ( < 25 character) log messages and ensuring there is a slight wait after the call.

    Case_5 enabled MY_DEBUG_VERBOSE_TRANSPORT in the node and also needed some changes to MyConfig.h so all the messages wouldn't be sent OTA.
    Case 6 disabled MY_DEBUG_VERBOSE_TRANSPORT in the gateway.

    The gateway in both cases 5 & 6 also received all the messages.

    Changes to MyConfig for case 5 & 6:

    #define DEBUG_OUTPUT_ENABLED	//!< DEBUG_OUTPUT_ENABLED
    #ifndef MY_DEBUG_OTA
    #if defined(MY_GATEWAY_SERIAL) || (!defined(CASE_5) && !defined(CASE_6))
    #define DEBUG_OUTPUT(x,...)		hwDebugPrint(x, ##__VA_ARGS__)	//!< debug
    #endif
    #else
    #define DEBUG_OUTPUT(x,...)		hwDebugPrint(x, ##__VA_ARGS__)	//!< debug
    #ifndef MY_OTA_LOG_SENDER_FEATURE
    #define MY_OTA_LOG_SENDER_FEATURE
    #endif
    #if !defined(CASE_5) && !defined(CASE_6)
    #ifndef MY_DEBUG_OTA_DISABLE_ACK
    #define DEBUG_OUTPUT(x,...)		OTALog((MY_DEBUG_OTA), true, x, ##__VA_ARGS__)	//!< debug
    #else
    #define DEBUG_OUTPUT(x,...)		OTALog((MY_DEBUG_OTA), false, x, ##__VA_ARGS__)	//!< debug
    #endif
    #endif
    // disable radio related debugging messages
    #undef MY_DEBUG_VERBOSE_RF24
    #undef MY_DEBUG_VERBOSE_NRF5_ESB
    #undef MY_DEBUG_VERBOSE_RFM69
    #undef MY_DEBUG_VERBOSE_RFM69_REGISTERS
    #undef MY_DEBUG_VERBOSE_RFM95
    #endif
    

    Node code

    #include "Arduino.h"
    
    //#define CASE_1
    //#define CASE_2
    //#define CASE_3
    //#define CASE_4
    //#define CASE_5
    //#define CASE_6
    #define CASE_7
    
    // Enable debug prints
    #if defined(CASE_6) || defined(CASE_7)
    #define MY_DEBUG_VERBOSE_TRANSPORT
    #endif
    
    #define MY_NODE_ID 45
    
    // Enable and select radio type attached
    #define MY_RADIO_NRF24
    #define MY_RF24_DATARATE RF24_2MBPS
    
    // Enable OTA debugging to Node 0
    #define MY_DEBUG_OTA (0)
    #define MY_OTA_LOG_SENDER_FEATURE
    
    #include <SPI.h>
    #include <MySensors.h>
    
    // Sleep time between sensor updates (in milliseconds)
    static const uint64_t UPDATE_INTERVAL = 15000;
    
    #define CHILD_ID_TEMP 0
    
    MyMessage msgTemp(CHILD_ID_TEMP, V_TEMP);
    
    
    void presentation()
    {
      // Send the sketch version information to the gateway
      sendSketchInfo("Temperature", "1.1");
    
      // Register all sensors to gw (they will be created as child devices)
      present(CHILD_ID_TEMP, S_TEMP);
    
    }
    
    unsigned int t=0;
    void setup()
    {
    #ifdef CASE_1
    	const char *case_id="Case 1";
    #endif
    #ifdef CASE_2
    	const char *case_id="Case 2";
    #endif
    #ifdef CASE_3
    	const char *case_id="Case 3";
    #endif
    #ifdef CASE_4
    	const char *case_id="Case 4";
    #endif
    #ifdef CASE_5
    	const char *case_id="Case 5";
    #endif
    #ifdef CASE_6
    	const char *case_id="Case 6";
    #endif
    #ifdef CASE_7
    	const char *case_id="Case 7";
    #endif
    	Serial.println(case_id);
    }
    
    #ifdef CASE_1
    void case1() {
    	OTALog(0, true,PSTR("Message1: %d"),t);
        OTALog(0, true,PSTR("Message2: %d"),t);
        OTALog(0, true,PSTR("Message3: %d"),t);
    }
    #endif
    
    #ifdef CASE_2
    void case2() {
    	OTALog(0, true,PSTR("Message1: %d"),t);
    	wait(10);
        OTALog(0, true,PSTR("Message2: %d"),t);
    	wait(10);
        OTALog(0, true,PSTR("Message3: %d"),t);
    }
    #endif
    
    #if defined(CASE_3) || defined(CASE_4)
    void case3_4() {
        OTALog(0, true,PSTR("Sending more than 25 characters: %d"),t);
        wait(10);
    	OTALog(0, true,PSTR("Message1: %d"),t);
    	wait(10);
        OTALog(0, true,PSTR("Message2: %d"),t);
    }
    #endif
    #if defined(CASE_5) || defined(CASE_6) || defined(CASE_7)
    void case567() {
        OTALog(0, true,PSTR("Sending more than 25 characters: %d"),t);
    	OTALog(0, true,PSTR("Message1: %d"),t);
        OTALog(0, true,PSTR("Message2: %d"),t);
    }
    #endif
    void loop()
    {
    	Serial.print("Loop: "); Serial.println(t);
    
    #ifdef CASE_1
    	case1();
    #endif
    #ifdef CASE_2
    	case2();
    #endif
    #ifdef CASE_3
    	case3_4();
    #endif
    #ifdef CASE_4
    	case3_4();
    #endif
    #if defined(CASE_5) || defined(CASE_6) || defined(CASE_7)
    	case567();
    #endif
        sleep(UPDATE_INTERVAL);
        t++;
    }
    

    Gateway:

    #include "Arduino.h"
    
    //#define CASE_1
    //#define CASE_2
    //#define CASE_3
    //#define CASE_4
    //#define CASE_5
    //#define CASE_6
    #define CASE_7
    
    #if defined(CASE_4) || defined(CASE_5) || defined(CASE_6)
    #define MY_DEBUG_VERBOSE_TRANSPORT
    #endif
    
    #define MY_RF24_DATARATE RF24_2MBPS
    
    // Enable and select radio type attached
    #define MY_RADIO_NRF24
    
    #define MY_OTA_LOG_RECEIVER_FEATURE
    
    #define MY_RF24_PA_LEVEL RF24_PA_MAX
    
    // Enable serial gateway
    #define MY_GATEWAY_SERIAL
    
    #include <MySensors.h>
    
    void setup()
    {
    	delay(5000);
    #ifdef CASE_1
    	const char *case_id="Case 1";
    #endif
    #ifdef CASE_2
    	const char *case_id="Case 2";
    #endif
    #ifdef CASE_3
    	const char *case_id="Case 3";
    #endif
    #ifdef CASE_4
    	const char *case_id="Case 4";
    #endif
    #ifdef CASE_5
    	const char *case_id="Case 5";
    #endif
    #ifdef CASE_6
    	const char *case_id="Case 6";
    #endif
    #ifdef CASE_7
    	const char *case_id="Case 7";
    #endif
    	Serial.println(case_id);
    }
    
    void presentation()
    {
    	// Present locally attached sensors
    }
    
    void loop()
    {
    	// Send locally attached sensor data here
    }
    

  • Mod

    Hi and welcome to the forum @oddthomas

    If you haven't read them already, these discussions might be useful:
    https://github.com/mysensors/MySensors/issues/892
    https://forum.mysensors.org/topic/7912/rfm69-new-driver-delay



  • Thanks for the links.

    Adding the delay in my code will not work in the case where a log message is being sent that is longer than 25 characters (MAX_PAYLOAD). The library code for that method splits the message and sends them in a loop where I have no control in my program via the wait() method.

    I think in my case, I will add some code similar to what was suggested in the github discussion, but I will add it to MyTransportRF24.cpp rather than at the top level send() method.

    Something similar to this:

    #ifdef MY_TRANSPORT_RF24_MESSAGE_DELAY
    unsigned int lastSendMS;
    #endif
    
    bool transportSend(const uint8_t to, const void *data, const uint8_t len, const bool noACK)
    {
    #ifdef MY_TRANSPORT_RF24_MESSAGE_DELAY
    	unsigned int waitTime=lastSendMS+MY_TRANSPORT_RF24_MESSAGE_DELAY-millis();
    	if(waitTime > 0) {
    		wait(waitTime);
    	}
    #endif
    ...
    

    Haven't tried this yet, but it should address my issue for now.



  • I was unable to insert a wait() call anywhere where it would work reliably.

    I am going to abandon this path and create a log node that simply exists to receive "normal" messages and post them to an MQTT topic so a client on my ethernet network can listen and log them to a file/syslog/etc.


 

429
Online

7.9k
Users

8.8k
Topics

93.8k
Posts