Cellular: AT requests are to be processed within time period

features/cellular/framework/AT/ATHandler.cpp

@@ -15,10 +15,11 @@
  * limitations under the License.
  */
 
+#include <ctype.h>
+#include <stdio.h>
 #include "ATHandler.h"
 #include "mbed_poll.h"
 #include "FileHandle.h"
-#include "Timer.h"
 #include "mbed_wait_api.h"
 #include "mbed_debug.h"
 #ifdef MBED_CONF_RTOS_PRESENT
@@ -31,7 +32,6 @@ using namespace mbed;
 using namespace events;
 using namespace mbed_cellular_util;
 
-//#define MBED_TRACE_MAX_LEVEL TRACE_LEVEL_DEBUG
 #include "CellularLog.h"
 
 #if MBED_CONF_MBED_TRACE_ENABLE
@@ -40,6 +40,9 @@ using namespace mbed_cellular_util;
 #define at_debug(...)
 #endif
 
+// URCs should be handled fast, if you add debug traces within URC processing then you also need to increase this time
+#define PROCESS_URC_TIME 20
+
 const char *mbed::OK = "OK\r\n";
 const uint8_t OK_LENGTH = 4;
 const char *mbed::CRLF = "\r\n";
@@ -63,6 +66,7 @@ static const uint8_t map_3gpp_errors[][2] =  {
 
 ATHandler::ATHandler(FileHandle *fh, EventQueue &queue, int timeout, const char *output_delimiter, uint16_t send_delay) :
     _nextATHandler(0),
+    _fileHandle(fh),
     _queue(queue),
     _last_err(NSAPI_ERROR_OK),
     _last_3gpp_error(0),
@@ -82,7 +86,8 @@ ATHandler::ATHandler(FileHandle *fh, EventQueue &queue, int timeout, const char
     _error_found(false),
     _max_resp_length(MAX_RESP_LENGTH),
     _debug_on(false),
-    _cmd_start(false)
+    _cmd_start(false),
+    _start_time(0)
 {
     //enable_debug(true);
 
@@ -108,7 +113,9 @@ ATHandler::ATHandler(FileHandle *fh, EventQueue &queue, int timeout, const char
     set_tag(&_info_stop, CRLF);
     set_tag(&_elem_stop, ")");
 
-    set_file_handle(fh);
+    _fileHandle->set_blocking(false);
+
+    set_filehandle_sigio();
 }
 
 void ATHandler::enable_debug(bool enable)
@@ -150,20 +157,7 @@ FileHandle *ATHandler::get_file_handle()
 
 void ATHandler::set_file_handle(FileHandle *fh)
 {
-    _fh_sigio_set = false;
     _fileHandle = fh;
-    _fileHandle->set_blocking(false);
-    set_filehandle_sigio();
-}
-
-void ATHandler::set_filehandle_sigio()
-{
-    if (_fh_sigio_set) {
-        return;
-    }
-
-    _fileHandle->sigio(mbed::Callback<void()>(this, &ATHandler::event));
-    _fh_sigio_set = true;
 }
 
 nsapi_error_t ATHandler::set_urc_handler(const char *prefix, mbed::Callback<void()> callback)
@@ -243,6 +237,7 @@ void ATHandler::lock()
 #endif
     _processing = true;
     clear_error();
+    _start_time = rtos::Kernel::get_ms_count();
 }
 
 void ATHandler::unlock()
@@ -287,31 +282,24 @@ void ATHandler::process_oob()
     tr_debug("process_oob %d", (_fileHandle->readable() || (_recv_pos < _recv_len)));
     if (_fileHandle->readable() || (_recv_pos < _recv_len)) {
         _current_scope = NotSet;
-        Timer timer;
+        uint32_t timeout = _at_timeout;
-        timer.start();
+        _at_timeout = PROCESS_URC_TIME;
-        do {
+        while (true) {
             if (match_urc()) {
-                timer.reset();
+                if (!(_fileHandle->readable() || (_recv_pos < _recv_len))) {
-                if (_fileHandle->readable() || (_recv_pos < _recv_len)) {
+                    break; // we have nothing to read anymore
-                    continue;
                 }
+                _start_time = rtos::Kernel::get_ms_count(); // time to process next (potential) URC
+            } else if (mem_str(_recv_buff, _recv_len, CRLF, CRLF_LENGTH)) {
+                // If no match found, look for CRLF and consume everything up to CRLF
+                consume_to_tag(CRLF, true);
+            } else {
+                if (!fill_buffer()) {
                     break;
                 }
-            // If no match found, look for CRLF and consume everything up to CRLF
-            if (mem_str(_recv_buff, _recv_len, CRLF, CRLF_LENGTH)) {
-                consume_to_tag(CRLF, true);
-                timer.reset();
-            } else {
-                if (_fileHandle->readable()) {
-                    timer.reset();
-                    fill_buffer();
-                } else {
-#ifdef MBED_CONF_RTOS_PRESENT
-                    wait_ms(1);
-#endif
             }
         }
-        } while (timer.read_ms() < 100); // URC's are very short
+        _at_timeout = timeout;
     }
     tr_debug("process_oob exit");
 
@@ -320,6 +308,15 @@ void ATHandler::process_oob()
     unlock();
 }
 
+void ATHandler::set_filehandle_sigio()
+{
+    if (_fh_sigio_set) {
+        return;
+    }
+    _fileHandle->sigio(mbed::Callback<void()>(this, &ATHandler::event));
+    _fh_sigio_set = true;
+}
+
 void ATHandler::reset_buffer()
 {
     tr_debug("%s", __func__);
@@ -338,8 +335,7 @@ void ATHandler::rewind_buffer()
     }
 }
 
-// we are always expecting to receive something so there is wait timeout
+bool ATHandler::fill_buffer()
-void ATHandler::fill_buffer()
 {
     tr_debug("%s", __func__);
     // Reset buffer when full
@@ -347,29 +343,24 @@ void ATHandler::fill_buffer()
         reset_buffer();
     }
 
-    Timer timer;
+    int timeout = (_start_time + _at_timeout) - rtos::Kernel::get_ms_count();
-    timer.start();
+    if (timeout >= 0) {
-    do {
+        pollfh fhs;
+        fhs.fh = _fileHandle;
+        fhs.events = POLLIN;
+        int count = poll(&fhs, 1, timeout);
+        if (count > 0 && (fhs.revents & POLLIN)) {
             ssize_t len = _fileHandle->read(_recv_buff + _recv_len, sizeof(_recv_buff) - _recv_len);
             if (len > 0) {
                 _recv_len += len;
-           at_debug("\n----------readable----------: %d\n", _recv_len);
+                return true;
-           for (size_t i = _recv_pos; i < _recv_len; i++) {
+            }
-               at_debug("%c", _recv_buff[i]);
         }
-           at_debug("\n----------readable----------\n");
-           return;
-        } else if (len != -EAGAIN && len != 0) {
-           tr_warn("%s error: %d while reading", __func__, len);
-           break;
     }
-#ifdef MBED_CONF_RTOS_PRESENT
-        wait_ms(1);
-#endif
-    } while ((uint32_t)timer.read_ms() < _at_timeout);
 
     set_error(NSAPI_ERROR_DEVICE_ERROR);
-    tr_debug("AT TIMEOUT, scope: %d timeout: %lu", _current_scope, _at_timeout);
+
+    return false;
 }
 
 int ATHandler::get_char()
@@ -377,9 +368,8 @@ int ATHandler::get_char()
     if (_recv_pos == _recv_len) {
         tr_debug("%s", __func__);
         reset_buffer(); // try to read as much as possible
-        fill_buffer();
+        if (!fill_buffer()) {
-        if (get_last_error()) {
+            tr_warn("AT TIMEOUT");
-            tr_debug("%s: -1", __func__);
             return -1; // timeout to read
         }
     }
@@ -792,7 +782,7 @@ void ATHandler::resp(const char *prefix, bool check_urc)
             if (!prefix && ((_recv_len-_recv_pos) >= _max_resp_length)) {
                 return;
             }
-            fill_buffer();
+            (void)fill_buffer();
         }
     }
 
@@ -810,7 +800,10 @@ void ATHandler::resp_start(const char *prefix, bool stop)
 
     // Try get as much data as possible
     rewind_buffer();
-    fill_buffer();
+    if (!fill_buffer()) {
+        tr_error("fill failed %s", prefix);
+        return;
+    }
 
     if (prefix) {
         if ((strlen(prefix) < sizeof(_info_resp_prefix))) {
@@ -891,8 +884,11 @@ bool ATHandler::consume_char(char ch)
 {
     tr_debug("%s: %c", __func__, ch);
     int read_char = get_char();
+    if (read_char == -1) {
+        return false;
+    }
     // If we read something else than ch, recover it
-    if (read_char != ch && read_char != -1) {
+    if (read_char != ch) {
         _recv_pos--;
         return false;
     }
@@ -1014,13 +1010,7 @@ void ATHandler::cmd_start(const char* cmd)
 {
 
     if (_at_send_delay) {
-        uint64_t current_time = rtos::Kernel::get_ms_count();
+        rtos::Thread::wait_until(_last_response_stop + _at_send_delay);
-        uint64_t time_difference = current_time - _last_response_stop;
-
-        if (time_difference < (uint64_t)_at_send_delay) {
-            wait_ms((uint64_t)_at_send_delay - time_difference);
-            tr_debug("AT wait %llu %llu", current_time, _last_response_stop);
-        }
     } 
 
     at_debug("AT cmd %s (err %d)\n", cmd, _last_err);
@@ -1100,7 +1090,12 @@ size_t ATHandler::write(const void *data, size_t len)
     fhs.events = POLLOUT;
     size_t write_len = 0;
     for (; write_len < len; ) {
-        int count = poll(&fhs, 1, _at_timeout);
+        int timeout = (_start_time + _at_timeout) - rtos::Kernel::get_ms_count();
+        if (timeout < 0) {
+            set_error(NSAPI_ERROR_DEVICE_ERROR);
+            return 0;
+        }
+        int count = poll(&fhs, 1, timeout);
         if (count <= 0 || !(fhs.revents & POLLOUT)) {
             set_error(NSAPI_ERROR_DEVICE_ERROR);
             return 0;
@@ -1140,7 +1135,7 @@ void ATHandler::flush()
 {
     while (_fileHandle->readable()) {
         reset_buffer();
-        fill_buffer();
+        (void) fill_buffer();
     }
     reset_buffer();
 }

features/cellular/framework/AT/ATHandler.h

@@ -19,7 +19,6 @@
 #define AT_HANDLER_H_
 
 #include "platform/mbed_retarget.h"
-#include "stdio.h"
 
 #include "EventQueue.h"
 #include "PlatformMutex.h"
@@ -421,6 +420,9 @@ private:
     bool _debug_on;
     bool _cmd_start;
 
+    // time when a command or an URC processing was started
+    uint64_t _start_time;
+
     // Gets char from receiving buffer.
     // Resets and fills the buffer if all are already read (receiving position equals receiving length).
     int get_char();
@@ -429,8 +431,8 @@ private:
     // Reading position set to 0 and buffer's unread content moved to beginning
     void rewind_buffer();
     // Reads from serial to receiving buffer.
-    // Returns on first successful read OR on timeout.
+    // Returns true on successful read OR false on timeout.
-    void fill_buffer();
+    bool fill_buffer();
 
     void set_tag(tag_t* tag_dest, const char *tag_seq);