Timer.Alarm fires too frequently.

[gandm]

Please include the following information when submitting a bug report:

• LoPy + PyCom expansion board

• (sysname='LoPy', nodename='LoPy', release='1.7.3.b1', version='1e46e72-dirty on 2017-06-18', machine='LoPy with ESP32', lorawan='1.0.0') plus some small printf mods below

• Exact steps to cause this issue

importing this class and running the classes start() method runs a timer every 5 seconds that invokes _sendData()

from network import LoRa
import socket
import binascii
import time
from machine import Timer

class PNode:
    def start(self):
        lora = LoRa(mode=LoRa.LORA,
                    frequency=868100000,
                    bandwidth=LoRa.BW_125KHZ,
                    sf=12,
                    coding_rate=LoRa.CODING_4_8,
                    power_mode=LoRa.ALWAYS_ON, tx_iq=True)

        print("LoRa Initialised")

        self.__s = socket.socket(socket.AF_LORA, socket.SOCK_RAW)
        self.__s.setblocking(False)

        self.ping_counter = 1
        self.start_time = time.ticks_ms()
        self.__alarm = Timer.Alarm(self._sendData, 5, periodic=True)

    def _sendData(self, alarm):
        try:
            self.__s.send('Ping {0!s}'.format(self.ping_counter))
        except OSError as err:
            print("OSError {0}, time={1}".format(err,time.ticks_diff(self.start_time, time.ticks_ms())))
        else:
            print('Sent Ping {0!s} at time={1}ms'.format(self.ping_counter,time.ticks_diff(self.start_time, time.ticks_ms())))
            self.ping_counter += 1

Also using a modified version of the sigfox repo modlora.c code below to give some additional information via printf's. No other changes made.

static int32_t lora_send (const byte *buf, uint32_t len, uint32_t timeout_ms) {
    lora_cmd_data_t cmd_data;

    cmd_data.cmd = E_LORA_CMD_TX;
    memcpy (cmd_data.info.tx.data, buf, len);
    cmd_data.info.tx.len = len;

    printf("lora_send timeout is %dms\n",timeout_ms);
    printf("lora_send sending data len=%d\n",cmd_data.info.tx.len);
    printf("lora_send sending data=\"");
    for(int i=0; i<cmd_data.info.tx.len; i++) {
      printf("%c",cmd_data.info.tx.data[i]);
    }
    printf("\"\n");

    if (timeout_ms < 0) {
        // blocking mode
        timeout_ms = portMAX_DELAY;
    }

    xEventGroupClearBits(LoRaEvents, LORA_STATUS_COMPLETED | LORA_STATUS_ERROR | LORA_STATUS_MSG_SIZE);

    // just pass to the LoRa queue
    if (!xQueueSend(xCmdQueue, (void *)&cmd_data, (TickType_t)(timeout_ms / portTICK_PERIOD_MS))) {
        printf("xQueueSend Full\n");
        return 0;
    }

    lora_obj.sftx = lora_obj.sf;

    if (timeout_ms != 0) {
        xEventGroupWaitBits(LoRaEvents,
                            LORA_STATUS_COMPLETED | LORA_STATUS_ERROR | LORA_STATUS_MSG_SIZE,
                            pdTRUE,   // clear on exit
                            pdFALSE,  // do not wait for all bits
                            (TickType_t)portMAX_DELAY);
    }
    // return the number of bytes sent
    printf("lora_send sent %d bytes\n", len);
    return len;
}

Should send an incrementing Ping number every 5 seconds. It works mostly by occasionally gets a number of EAGAIN errors which fire repeatedly and very rapidly until the system becomes stable and starts ping again.

lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 17"
lora_send sent 7 bytes
Sent Ping 17 at time=85003ms
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 18"
lora_send sent 7 bytes
Sent Ping 18 at time=93031ms

The timer alarm now seems to fire far more often than my 5 seconds requested.

lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 19"
lora_send sent 7 bytes
Sent Ping 19 at time=93042ms
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 20"
lora_send sent 7 bytes
Sent Ping 20 at time=93054ms
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full                                                      

NOTE:*********************************
Queue seems full? and then the sytem
keeps retrying ~ 20ms without my consent
until fixed - see last entries below
every 

OSError [Errno 11] EAGAIN, time=93066                 
lora_send timeout is 0ms                                         
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93079
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93092
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93104
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93117
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93130
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93142
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93155
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93168
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93180
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93193
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93206
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93218
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93231
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93244
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93256
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93269
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93282
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93294
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93307
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93320
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93332
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93345
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93358
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93370
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93383
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93396
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93408
lora_send timeout is 0ms
lora_send sending data len=7
lora_send sending data="Ping 21"
xQueueSend Full
OSError [Errno 11] EAGAIN, time=93421

************ Now it is recovered OK
lora_send timeout is 0ms                                                              
lora_send sending data len=7
lora_send sending data="Ping 21"
lora_send sent 7 bytes
Sent Ping 21 at time=95936ms

Questions:

Why does my timer fire more rapidly than 5 seconds that causes Queue full?
Why is the queue full?
I only issue a single send but the modlora code keeps firing.
Also, why does my try: except: clause keep firing? OSError [Errno 11] EAGAIN, time= messages are emitted by my python except clause.

The issue seems to be worse if I run a wlan.scan() on another timer every 30 seconds.

[gandm]

This is a zip file that contains a small app that recreates the issue (well it does for me!) as well as my modified firmware image. You'll need to modify the ssid and password to join a wlan in the appropriate file.

The root cause seems to be that the alarm timer fires at the anticipated interval and then slightly delayed (probably due to the wlan.scan()) followed by a burst of LoRa sends many times in a second, which causes the EAGAIN error over and over until it settles.

pnode_v1.zip
MyImage.tar.gz