Cellular: AT debugging improved

features/cellular/README.md

@@ -72,7 +72,7 @@ You can define the debug tracing level in the `mbed_app.json` configuration file
 
 The `TESTS` folder contains Greentea tests for cellular specific classes. You need to give relevant configuration file with `--app-config` parameter, e.g.:
 
-    mbed test -n features-cellular-tests-* --app-config features\cellular\TESTS\socket\udp\template_mbed_app.json -vv
+    mbed test -n features-cellular-tests-* --app-config features\cellular\TESTS\socket\udp\template_mbed_app.json.txt -v
 
     Note that Greentea tests use SIM PIN so you need to change that or your SIM card may get locked.
 

features/cellular/TESTS/socket/udp/main.cpp

@@ -55,11 +55,56 @@ static UARTSerial cellular_serial(MDMTXD, MDMRXD, MBED_CONF_PLATFORM_DEFAULT_SER
 static rtos::Semaphore network_semaphore(0);
 static CellularConnectionFSM cellular;
 
+#if MBED_CONF_MBED_TRACE_ENABLE
+
+static rtos::Mutex trace_mutex;
+
+void trace_wait()
+{
+    trace_mutex.lock();
+}
+
+void trace_release()
+{
+    trace_mutex.unlock();
+}
+
+static char time_st[sizeof("[12345678]") + 1];
+
+static char* trace_time(size_t ss)
+{
+    snprintf(time_st, sizeof("[12345678]"), "[%08llu]", rtos::Kernel::get_ms_count());
+    return time_st;
+}
+
+static void trace_open()
+{
+    mbed_trace_init();
+    mbed_trace_prefix_function_set( &trace_time );
+    mbed_trace_mutex_wait_function_set(trace_wait);
+    mbed_trace_mutex_release_function_set(trace_release);
+
+    mbed_cellular_trace::mutex_wait_function_set(trace_wait);
+    mbed_cellular_trace::mutex_release_function_set(trace_release);
+}
+
+static void trace_close()
+{
+    mbed_cellular_trace::mutex_wait_function_set(NULL);
+    mbed_cellular_trace::mutex_release_function_set(NULL);
+
+    mbed_trace_free();
+}
+
+#endif // MBED_CONF_MBED_TRACE_ENABLE
+
 static SocketAddress echo_server_addr;
 
+static rtos::EventFlags eventFlags;
+
 class EchoSocket : public UDPSocket {
 public:
-  EchoSocket(int size) : UDPSocket(), _async_flag(0), _data(0), _size(size) {
+  EchoSocket(int size) : UDPSocket(), _data(0), _size(size), _async_flag(0), _tx_pending(false), _rx_pending(false) {
   }
   virtual ~EchoSocket() {
     delete _data;
@@ -69,54 +114,70 @@ public:
         if (_async_flag) {
             set_blocking(false);
             sigio(callback(this, &EchoSocket::async_callback));
-        } else {
+        }
-            set_blocking(true);
-            set_timeout(SOCKET_TIMEOUT);
-            sigio(NULL);
 	}
 
-	}
 	void test_sendto(const char *const hostname = NULL) {
+	    if (!_data) {
 	        _data = new uint8_t[_size];
 	        for (int i=0; i<_size; i++) {
 	            _data[i] = (uint8_t)rand();
 	        }
-		// clear pending events
+	    }
-		TEST_ASSERT(!(EchoSocket::eventFlags.clear(_async_flag) & osFlagsError));
+	    nsapi_size_or_error_t ret;
 		if (hostname) {
-			TEST_ASSERT(sendto(hostname, ECHO_SERVER_UDP_PORT, _data, _size) == _size);
+		    ret = sendto(hostname, ECHO_SERVER_UDP_PORT, _data, _size);
 		} else {
-			TEST_ASSERT(sendto(echo_server_addr, _data, _size) == _size);
+		    ret = sendto(echo_server_addr, _data, _size);
+		}
+		if (ret == _size) { // send successful
+		    _tx_pending = false;
+		} else {
+		    TEST_ASSERT(_async_flag && ret == NSAPI_ERROR_WOULD_BLOCK);
+            _tx_pending = true;
 		}
 	}
+
 	void test_recvfrom() {
-		if (_async_flag) {
-			TEST_ASSERT((EchoSocket::eventFlags.wait_any(_async_flag, SOCKET_TIMEOUT) & (osFlagsError | _async_flag)) == _async_flag);
-		}
 		uint8_t *buf = new uint8_t[_size];
 		memset(buf, 0, _size);
 		SocketAddress recv_address;
-
+		nsapi_size_or_error_t ret = recvfrom(&recv_address, buf, _size);
-		TEST_ASSERT(recvfrom(&recv_address, buf, _size) == _size);
+		if (ret == _size) { // recv successful
-
+		    _rx_pending = false;
 	        TEST_ASSERT(recv_address == echo_server_addr);
 	        TEST_ASSERT(memcmp(_data, buf, _size) == 0);
-		delete buf;
 	        delete _data;
-		_data = 0;
+	        _data = NULL;
+	        _rx_pending = false;
+		} else {
+		    TEST_ASSERT(_async_flag && ret == NSAPI_ERROR_WOULD_BLOCK);
+            _rx_pending = true;
 		}
+        delete buf;
+	}
+
+	bool async_process() {
+        if (_tx_pending) {
+            test_sendto();
+        }
+        if (_rx_pending) {
+            test_recvfrom();
+        }
+        return _tx_pending | _rx_pending;
+	}
+
 private:
 	void async_callback() {
-		EchoSocket::eventFlags.set(_async_flag);
+	    eventFlags.set(_async_flag);
 	}
 	uint8_t *_data;
 	int _size;
 	uint32_t _async_flag; // 0 for blocking socket, signal bit for async
-	static rtos::EventFlags eventFlags;
+	bool _tx_pending;
+	bool _rx_pending;
 };
 
-rtos::EventFlags EchoSocket::eventFlags;
-
 static void network_callback(nsapi_event_t ev, intptr_t ptr)
 {
     if (ev == NSAPI_EVENT_CONNECTION_STATUS_CHANGE) {
@@ -136,6 +197,10 @@ static void udp_network_stack()
     cellular.attach(&network_callback);
     TEST_ASSERT(cellular.start_dispatch() == NSAPI_ERROR_OK);
     cellular.set_sim_pin(MBED_CONF_APP_CELLULAR_SIM_PIN);
+#ifdef MBED_CONF_APP_APN
+    CellularNetwork * network = cellular.get_network();
+    TEST_ASSERT(network->set_credentials(MBED_CONF_APP_APN) == NSAPI_ERROR_OK);
+#endif
     cellular_target_state = CellularConnectionFSM::STATE_CONNECTED;
     TEST_ASSERT(cellular.continue_to_state(cellular_target_state) == NSAPI_ERROR_OK);
 	TEST_ASSERT(network_semaphore.wait(NETWORK_TIMEOUT) == 1);
@@ -144,37 +209,48 @@ static void udp_network_stack()
 static void udp_gethostbyname()
 {
     TEST_ASSERT(cellular.get_network()->gethostbyname(ECHO_SERVER_NAME, &echo_server_addr) == 0);
-    tr_info("HOST: %s", echo_server_addr.get_ip_address());
+    tr_info("Echo server IP: %s", echo_server_addr.get_ip_address());
 	echo_server_addr.set_port(7);
-	wait(1);
 }
 
 static void udp_socket_send_receive()
 {
     EchoSocket echo_socket(4);
     TEST_ASSERT(echo_socket.open(cellular.get_network()) == NSAPI_ERROR_OK);
-    echo_socket.set_async(0);
+    echo_socket.set_blocking(true);
+    echo_socket.set_timeout(SOCKET_TIMEOUT);
     echo_socket.test_sendto();
     echo_socket.test_recvfrom();
     TEST_ASSERT(echo_socket.close() == NSAPI_ERROR_OK);
-    wait(1);
 }
 
 static void udp_socket_send_receive_async()
 {
+    int async_flag = 1;
+    TEST_ASSERT(!(eventFlags.clear(async_flag) & osFlagsError));
+
     EchoSocket echo_socket(4);
     TEST_ASSERT(echo_socket.open(cellular.get_network()) == NSAPI_ERROR_OK);
-    echo_socket.set_async(1);
+    echo_socket.set_async(async_flag);
     echo_socket.test_sendto();
     echo_socket.test_recvfrom();
+
+    while (true) {
+        TEST_ASSERT((eventFlags.wait_any(async_flag, SOCKET_TIMEOUT) & (osFlagsError)) != osFlagsError);
+        if (!echo_socket.async_process()) {
+            break;
+        }
+    }
     TEST_ASSERT(echo_socket.close() == NSAPI_ERROR_OK);
-    wait(1);
 }
 
 using namespace utest::v1;
 
 static utest::v1::status_t greentea_failure_handler(const Case *const source, const failure_t reason)
 {
+#if MBED_CONF_MBED_TRACE_ENABLE
+    trace_close();
+#endif 
     greentea_case_failure_abort_handler(source, reason);
     return STATUS_ABORT;
 }
@@ -184,7 +260,6 @@ static Case cases[] = {
 	Case("UDP gethostbyname", udp_gethostbyname, greentea_failure_handler),
 	Case("UDP socket send/receive", udp_socket_send_receive, greentea_failure_handler),
 	Case("UDP socket send/receive async", udp_socket_send_receive_async, greentea_failure_handler),
-	//Case("UDP socket multiple simultaneous", udp_socket_multiple_simultaneous, greentea_failure_handler),
 };
 
 static utest::v1::status_t test_setup(const size_t number_of_cases)
@@ -197,7 +272,12 @@ static Specification specification(test_setup, cases);
 
 int main()
 {
-	mbed_trace_init();
+#if MBED_CONF_MBED_TRACE_ENABLE
-
+    trace_open();
-	return Harness::run(specification);
+#endif
+    int ret = Harness::run(specification);
+#if MBED_CONF_MBED_TRACE_ENABLE
+    trace_close();
+#endif 
+	return ret;
 }

features/cellular/TESTS/socket/udp/template_mbed_app.json.txt

@@ -17,9 +17,9 @@
             "value": 0
         },
         "trace-level": {
-            "help": "Options are TRACE_LEVEL_ERROR,TRACE_LEVEL_WARN,TRACE_LEVEL_INFO,TRACE_LEVEL_DEBUG",
+            "help": "Note that excessive trace prints may mess up with Greentea parsing",
             "macro_name": "MBED_TRACE_MAX_LEVEL",
-            "value": "TRACE_LEVEL_INFO"
+            "value": "TRACE_LEVEL_ERROR"
         }
     },
     "target_overrides": {
@@ -27,14 +27,17 @@
             "ppp-cell-iface.apn-lookup": false,
             "cellular.use-apn-lookup": false,
             "target.features_add": ["LWIP", "COMMON_PAL"],
-            "mbed-trace.enable": false,
+            "mbed-trace.enable": true,
             "lwip.ipv4-enabled": true,
             "lwip.ipv6-enabled": true,
             "lwip.tcp-enabled": false,
             "lwip.ppp-enabled": true,
             "lwip.ethernet-enabled": false,
             "platform.stdio-convert-newlines": true,
-            "platform.default-serial-baud-rate": 115200
+            "platform.default-serial-baud-rate": 115200,
+            "drivers.uart-serial-txbuf-size": 512,
+            "drivers.uart-serial-rxbuf-size": 1024,
+            "cellular.debug-at": false
         }
     }
 }

features/cellular/framework/AT/ATHandler.cpp

@@ -35,12 +35,6 @@ using namespace mbed_cellular_util;
 
 #include "CellularLog.h"
 
-#if MBED_CONF_MBED_TRACE_ENABLE
-#define at_debug(format, ...) do { if (_debug_on) debug(format, ## __VA_ARGS__); } while (0)
-#else
-#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
 
@@ -86,12 +80,10 @@ ATHandler::ATHandler(FileHandle *fh, EventQueue &queue, int timeout, const char
     _urc_matched(false),
     _error_found(false),
     _max_resp_length(MAX_RESP_LENGTH),
-    _debug_on(false),
+    _debug_on(MBED_CONF_CELLULAR_DEBUG_AT),
     _cmd_start(false),
     _start_time(0)
 {
-    //enable_debug(true);
-
     clear_error();
 
     if (output_delimiter) {
@@ -119,9 +111,9 @@ ATHandler::ATHandler(FileHandle *fh, EventQueue &queue, int timeout, const char
     set_filehandle_sigio();
 }
 
-void ATHandler::enable_debug(bool enable)
+void ATHandler::set_debug(bool debug_on)
 {
-    _debug_on = enable;
+    _debug_on = debug_on;
 }
 
 ATHandler::~ATHandler()
@@ -280,7 +272,7 @@ void ATHandler::restore_at_timeout()
 void ATHandler::process_oob()
 {
     lock();
-    tr_debug("process_oob %d", (_fileHandle->readable() || (_recv_pos < _recv_len)));
+    tr_debug("process_oob readable=%d, pos=%u, len=%u", _fileHandle->readable(), _recv_pos,  _recv_len);
     if (_fileHandle->readable() || (_recv_pos < _recv_len)) {
         _current_scope = NotSet;
         uint32_t timeout = _at_timeout;
@@ -319,14 +311,12 @@ void ATHandler::set_filehandle_sigio()
 
 void ATHandler::reset_buffer()
 {
-    tr_debug("%s", __func__);
     _recv_pos = 0;
     _recv_len = 0;
 }
 
 void ATHandler::rewind_buffer()
 {
-    tr_debug("%s", __func__);
     if (_recv_pos > 0 && _recv_len >= _recv_pos) {
         _recv_len -= _recv_pos;
         // move what is not read to beginning of buffer
@@ -355,7 +345,6 @@ int ATHandler::poll_timeout(bool wait_for_timeout)
 
 bool ATHandler::fill_buffer(bool wait_for_timeout)
 {
-    tr_debug("%s", __func__);
     // Reset buffer when full
     if (sizeof(_recv_buff) == _recv_len) {
         tr_error("AT overflow");
@@ -369,6 +358,7 @@ bool ATHandler::fill_buffer(bool wait_for_timeout)
     if (count > 0 && (fhs.revents & POLLIN)) {
         ssize_t len = _fileHandle->read(_recv_buff + _recv_len, sizeof(_recv_buff) - _recv_len);
         if (len > 0) {
+            debug_print(_recv_buff + _recv_len, len);
             _recv_len += len;
             return true;
         }
@@ -380,7 +370,6 @@ bool ATHandler::fill_buffer(bool wait_for_timeout)
 int ATHandler::get_char()
 {
     if (_recv_pos == _recv_len) {
-        tr_debug("%s", __func__);
         reset_buffer(); // try to read as much as possible
         if (!fill_buffer()) {
             tr_warn("AT timeout");
@@ -389,14 +378,11 @@ int ATHandler::get_char()
         }
     }
 
-    tr_debug("%s: %c", __func__, _recv_buff[_recv_pos]);
-
     return _recv_buff[_recv_pos++];
 }
 
 void ATHandler::skip_param(uint32_t count)
 {
-    tr_debug("%s", __func__);
     if (_last_err || !_stop_tag || _stop_tag->found) {
         return;
     }
@@ -426,7 +412,6 @@ void ATHandler::skip_param(uint32_t count)
 
 void ATHandler::skip_param(ssize_t len, uint32_t count)
 {
-    tr_debug("%s", __func__);
     if (_last_err || !_stop_tag || _stop_tag->found) {
         return;
     }
@@ -447,7 +432,6 @@ void ATHandler::skip_param(ssize_t len, uint32_t count)
 
 ssize_t ATHandler::read_bytes(uint8_t *buf, size_t len)
 {
-    tr_debug("%s", __func__);
     if (_last_err) {
         return -1;
     }
@@ -466,13 +450,6 @@ ssize_t ATHandler::read_bytes(uint8_t *buf, size_t len)
 
 ssize_t ATHandler::read(char *buf, size_t size, bool read_even_stop_tag, bool hex)
 {
-    tr_debug("%s", __func__);
-    at_debug("\n----------read buff:----------\n");
-    for (size_t i = _recv_pos; i < _recv_len; i++) {
-        at_debug("%c", _recv_buff[i]);
-    }
-    at_debug("\n----------read end----------\n");
-
     if (_last_err || !_stop_tag || (_stop_tag->found && read_even_stop_tag == false)) {
         return -1;
     }
@@ -493,14 +470,13 @@ ssize_t ATHandler::read(char *buf, size_t size, bool read_even_stop_tag, bool he
             buf[buf_idx] = '\0';
             set_error(NSAPI_ERROR_DEVICE_ERROR);
             return -1;
-        } else if (c == _delimiter) {
+        }
+        if (c == _delimiter) {
             buf[buf_idx] = '\0';
             break;
         } else if (c == '\"') {
             match_pos = 0;
-            if (read_idx > 0) {
             read_idx--;
-            }
             continue;
         } else if (_stop_tag->len && c == _stop_tag->tag[match_pos]) {
             match_pos++;
@@ -540,8 +516,6 @@ ssize_t ATHandler::read_hex_string(char *buf, size_t size)
 
 int32_t ATHandler::read_int()
 {
-    tr_debug("%s", __func__);
-
     if (_last_err || !_stop_tag || _stop_tag->found) {
         return -1;
     }
@@ -589,7 +563,6 @@ void ATHandler::set_stop_tag(const char *stop_tag_seq)
 
 void ATHandler::set_scope(ScopeType scope_type)
 {
-    tr_debug("%s: %d", __func__, scope_type);
     if (_current_scope != scope_type) {
         _current_scope = scope_type;
         switch (_current_scope) {
@@ -618,7 +591,6 @@ void ATHandler::set_scope(ScopeType scope_type)
 // should match from recv_pos?
 bool ATHandler::match(const char* str, size_t size)
 {
-    tr_debug("%s: %s", __func__, str);
     rewind_buffer();
 
     if ((_recv_len - _recv_pos) < size) {
@@ -635,14 +607,12 @@ bool ATHandler::match(const char* str, size_t size)
 
 bool ATHandler::match_urc()
 {
-    tr_debug("%s", __func__);
     rewind_buffer();
     size_t prefix_len = 0;
     for (struct oob_t *oob = _oobs; oob; oob = oob->next) {
         prefix_len = oob->prefix_len;
         if (_recv_len >= prefix_len) {
             if (match(oob->prefix, prefix_len)) {
-                tr_debug("URC! %s\n", oob->prefix);
                 set_scope(InfoType);
                 if (oob->cb) {
                     oob->cb();
@@ -657,8 +627,6 @@ bool ATHandler::match_urc()
 
 bool ATHandler::match_error()
 {
-    tr_debug("%s", __func__);
-
     if (match(CME_ERROR, CME_ERROR_LENGTH)) {
         at_error(true, DeviceErrorTypeErrorCME);
         return true;
@@ -737,25 +705,17 @@ void ATHandler::at_error(bool error_code_expected, DeviceErrorType error_type)
             set_3gpp_error(err, error_type);
             _last_at_err.errCode = err;
             _last_at_err.errType = error_type;
-            tr_debug("ATHandler ERROR: %d", err);
+            tr_error("AT error code %ld", err);
         } else {
-            tr_debug("ATHandler ERROR reading failed");
+            tr_warn("ATHandler ERROR reading failed");
         }
     }
 
-    _last_err = NSAPI_ERROR_DEVICE_ERROR;
+    set_error(NSAPI_ERROR_DEVICE_ERROR);
 }
 
 void ATHandler::resp(const char *prefix, bool check_urc)
 {
-    tr_debug("%s: %s", __func__, prefix);
-
-    at_debug("\n----------resp buff:----------\n");
-    for (size_t i = _recv_pos; i < _recv_len; i++) {
-        at_debug("%c", _recv_buff[i]);
-    }
-    at_debug("\n----------buff----------\n");
-
     _prefix_matched = false;
     _urc_matched = false;
     _error_found = false;
@@ -810,8 +770,6 @@ void ATHandler::resp(const char *prefix, bool check_urc)
 
 void ATHandler::resp_start(const char *prefix, bool stop)
 {
-    tr_debug("%s: %s", __func__, prefix);
-
     if (_last_err) {
         return;
     }
@@ -837,7 +795,6 @@ void ATHandler::resp_start(const char *prefix, bool stop)
 // check urc because of error as urc
 bool ATHandler::info_resp()
 {
-    tr_debug("%s", __func__);
     if (_last_err || _resp_stop.found) {
         return false;
     }
@@ -868,7 +825,6 @@ bool ATHandler::info_resp()
 
 bool ATHandler::info_elem(char start_tag)
 {
-    tr_debug("%s: %c", __func__, start_tag);
     if (_last_err) {
         return false;
     }
@@ -894,7 +850,6 @@ bool ATHandler::info_elem(char start_tag)
 
 bool ATHandler::consume_char(char ch)
 {
-    tr_debug("%s: %c", __func__, ch);
     int read_char = get_char();
     if (read_char == -1) {
         return false;
@@ -909,7 +864,6 @@ bool ATHandler::consume_char(char ch)
 
 bool ATHandler::consume_to_tag(const char *tag, bool consume_tag)
 {
-    tr_debug("%s: %s", __func__, tag);
     size_t match_pos = 0;
 
     while (true) {
@@ -934,8 +888,6 @@ bool ATHandler::consume_to_tag(const char *tag, bool consume_tag)
 
 bool ATHandler::consume_to_stop_tag()
 {
-    tr_debug("%s", __func__);
-
     if (!_stop_tag || (_stop_tag && _stop_tag->found) || _error_found) {
         return true;
     }
@@ -944,7 +896,7 @@ bool ATHandler::consume_to_stop_tag()
         return true;
     }
 
-    tr_debug("consume_to_stop_tag not found");
+    tr_warn("AT stop tag not found");
     set_error(NSAPI_ERROR_DEVICE_ERROR);
     return false;
 }
@@ -955,8 +907,6 @@ void ATHandler::resp_stop()
 {
     // Do not return on error so that we can consume whatever there is in the buffer
 
-    tr_debug("%s", __func__);
-
     if (_current_scope == ElemType) {
         information_response_element_stop();
         set_scope(InfoType);
@@ -981,7 +931,6 @@ void ATHandler::resp_stop()
 
 void ATHandler::information_response_stop()
 {
-    tr_debug("%s", __func__);
     if (consume_to_stop_tag()) {
         set_scope(RespType);
     }
@@ -989,7 +938,6 @@ void ATHandler::information_response_stop()
 
 void ATHandler::information_response_element_stop()
 {
-    tr_debug("%s", __func__);
     if (consume_to_stop_tag()) {
         set_scope(InfoType);
     }
@@ -1025,8 +973,6 @@ void ATHandler::cmd_start(const char* cmd)
         rtos::Thread::wait_until(_last_response_stop + _at_send_delay);
     }
 
-    at_debug("AT cmd %s (err %d)\n", cmd, _last_err);
-
     if (_last_err != NSAPI_ERROR_OK) {
         return;
     }
@@ -1038,7 +984,6 @@ void ATHandler::cmd_start(const char* cmd)
 
 void ATHandler::write_int(int32_t param)
 {
-    at_debug("AT int %d\n", param);
     // do common checks before sending subparameter
     if (check_cmd_send() == false) {
         return;
@@ -1055,7 +1000,6 @@ void ATHandler::write_int(int32_t param)
 
 void ATHandler::write_string(const char* param, bool useQuotations)
 {
-    at_debug("AT str %s (with quotes %d)\n", param, useQuotations);
     // do common checks before sending subparameter
     if (check_cmd_send() == false) {
         return;
@@ -1076,7 +1020,6 @@ void ATHandler::write_string(const char* param, bool useQuotations)
 
 void ATHandler::cmd_stop()
 {
-    at_debug("AT stop %s (err %d)\n", _output_delimiter, _last_err);
     if (_last_err != NSAPI_ERROR_OK) {
         return;
     }
@@ -1086,8 +1029,6 @@ void ATHandler::cmd_stop()
 
 size_t ATHandler::write_bytes(const uint8_t *data, size_t len)
 {
-    at_debug("AT write bytes %d (err %d)\n", len, _last_err);
-
     if (_last_err != NSAPI_ERROR_OK) {
         return 0;
     }
@@ -1112,6 +1053,7 @@ size_t ATHandler::write(const void *data, size_t len)
             set_error(NSAPI_ERROR_DEVICE_ERROR);
             return 0;
         }
+        debug_print((char*)data + write_len, ret);
         write_len += (size_t)ret;
     }
 
@@ -1145,3 +1087,26 @@ void ATHandler::flush()
         reset_buffer();
     }
 }
+
+void ATHandler::debug_print(char *p, int len)
+{
+#if MBED_CONF_MBED_TRACE_ENABLE
+    if (_debug_on) {
+        mbed_cellular_trace::mutex_wait();
+        for (ssize_t i = 0; i < len; i++) {
+            char c = *p++;
+            if (!isprint(c)) {
+                if (c == '\r') {
+                } else if (c == '\n') {
+                    debug("%c", c);
+                } else {
+                    debug("[%d]", c);
+                }
+            } else {
+                debug("%c", c);
+            }
+        }
+        mbed_cellular_trace::mutex_release();
+    }
+#endif
+}

features/cellular/framework/AT/ATHandler.h

@@ -360,17 +360,23 @@ public:
      */
     bool consume_to_stop_tag();
 
-    /**  Sets _debug_on flag.
-     *
-     *  @param enable value to be set for _debug_on flag
-     */
-    void enable_debug(bool enable);
-
     /** Return the last 3GPP error code.
      *  @return last 3GPP error code
      */
     int get_3gpp_error();
 
+public: // just for debugging
+    /**
+     * AT debugging, when enabled will print all data read and written,
+     * non-printable chars are printed as "[%d]".
+     *
+     * AT debug can be enabled at compile time using MBED_CONF_CELLULAR_DEBUG_AT flag or at runtime
+     * calling set_debug(). Note that MBED_CONF_MBED_TRACE_ENABLE must also be enabled.
+     *
+     *  @param debug_on Enable/disable debugging
+     */
+    void set_debug(bool debug_on);
+
 private:
 
     // should fit any prefix and int
@@ -501,6 +507,9 @@ private:
     bool find_urc_handler(const char *prefix, mbed::Callback<void()> callback);
 
     ssize_t read(char *buf, size_t size, bool read_even_stop_tag, bool hex);
+
+    // print contents of a buffer to trace log
+    void debug_print(char *p, int len);
 };
 
 } // namespace mbed

features/cellular/framework/AT/AT_CellularDevice.cpp

@@ -62,7 +62,7 @@ ATHandler* AT_CellularDevice::get_at_handler(FileHandle *fileHandle)
     atHandler = new ATHandler(fileHandle, _queue, _default_timeout, "\r", get_send_delay());
     if (atHandler) {
         if (_modem_debug_on) {
-            atHandler->enable_debug(_modem_debug_on);
+            atHandler->set_debug(_modem_debug_on);
         }
         atHandler->_nextATHandler = _atHandlers;
         _atHandlers = atHandler;
@@ -234,7 +234,7 @@ void AT_CellularDevice::modem_debug_on(bool on)
 
     ATHandler *atHandler = _atHandlers;
     while (atHandler) {
-        atHandler->enable_debug(_modem_debug_on);
+        atHandler->set_debug(_modem_debug_on);
         atHandler = atHandler->_nextATHandler;
     }
 }

features/cellular/framework/AT/AT_CellularNetwork.cpp

@@ -115,13 +115,13 @@ void AT_CellularNetwork::read_reg_params_and_compare(RegistrationType type)
 #if MBED_CONF_MBED_TRACE_ENABLE
     switch (reg_status) {
         case NotRegistered:
-            tr_error("not registered");
+            tr_warn("not registered");
             break;
         case RegistrationDenied:
-            tr_error("registration denied");
+            tr_warn("registration denied");
             break;
         case Unknown:
-            tr_error("registration status unknown");
+            tr_warn("registration status unknown");
             break;
         default:
             break;

features/cellular/framework/AT/AT_CellularSIM.cpp

@@ -61,13 +61,13 @@ nsapi_error_t AT_CellularSIM::get_sim_state(SimState &state)
 #if MBED_CONF_MBED_TRACE_ENABLE
     switch (state) {
         case SimStatePinNeeded:
-            tr_error("SIM PIN required");
+            tr_info("SIM PIN required");
             break;
         case SimStatePukNeeded:
             tr_error("SIM PUK required");
             break;
         case SimStateUnknown:
-            tr_error("SIM state unknown");
+            tr_warn("SIM state unknown");
             break;
         default:
             tr_info("SIM is ready");

features/cellular/framework/common/CellularLog.cpp

@@ -0,0 +1,57 @@
+/*
+ * Copyright (c) , Arm Limited and affiliates.
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "CellularLog.h"
+
+#if MBED_CONF_MBED_TRACE_ENABLE
+
+namespace mbed_cellular_trace {
+
+typedef struct trace_s {
+    void (*mutex_wait_f)(void);
+    void (*mutex_release_f)(void);
+} trace_t;
+
+static trace_t m_trace = {
+    .mutex_wait_f = 0,
+    .mutex_release_f = 0,
+};
+
+void mutex_wait_function_set(void (*mutex_wait_f)(void)) {
+    m_trace.mutex_wait_f = mutex_wait_f;
+}
+
+void mutex_release_function_set(void (*mutex_release_f)(void)) {
+    m_trace.mutex_release_f = mutex_release_f;
+}
+
+
+void mutex_wait() {
+    if (m_trace.mutex_wait_f) {
+        m_trace.mutex_wait_f();
+    }
+}
+
+void mutex_release() {
+    if (m_trace.mutex_release_f) {
+        m_trace.mutex_release_f();
+    }
+}
+
+} // namespace mbed_cellular_trace
+
+#endif // MBED_CONF_MBED_TRACE_ENABLE

features/cellular/framework/common/CellularLog.h

@@ -18,6 +18,8 @@
 #ifndef CELLULAR_LOG_H_
 #define CELLULAR_LOG_H_
 
+#include "rtos.h"
+
 #if defined(HAVE_DEBUG) && !defined(FEA_TRACE_SUPPORT)
 #define FEA_TRACE_SUPPORT
 #endif
@@ -26,7 +28,7 @@
 
 #include "mbed-trace/mbed_trace.h"
 #ifndef TRACE_GROUP
-#define TRACE_GROUP  "cellular"
+#define TRACE_GROUP  "CELL"
 #endif // TRACE_GROUP
 
 #else
@@ -38,4 +40,15 @@
 
 #endif // FEATURE_COMMON_PAL
 
+/**
+ * Set mutex wait/release functions for 'tr_' macros,
+ * implementation here is modified from that found from mbed_trace.
+ */
+namespace mbed_cellular_trace {
+void mutex_wait_function_set(void (*mutex_wait_f)(void));
+void mutex_release_function_set(void (*mutex_release_f)(void));
+void mutex_wait();
+void mutex_release();
+}
+
 #endif // CELLULAR_LOG_H_

features/cellular/mbed_lib.json

@@ -8,6 +8,10 @@
         "random_max_start_delay": {
             "help": "Maximum random delay value used in start-up sequence in milliseconds",
             "value": 0
+        },
+        "debug-at": {
+            "help": "Enable AT debug prints",
+            "value": false
         }
     }
 }