Cellular: Updated debug prints, and network registration return value

Updated cellular debug trace prints:
 - Removed unnecessary prints.
 - Tracing more in DEBUG level.
 - Read/write bytes not printed on big packets.
 - Signal quality (RSSI) traced to log network problems.
 - Dismissed AT data is traced.
 - Modem type and firmware version are traced.

Network registration returns NotRegistered instead of StatusNotAvailable,
because that's not in 3GPP TS 27.007.
pull/8767/head
Ari Parkkila 2018-11-15 05:22:03 -08:00
parent 8a2044b5fc
commit 9bdeb68e74
13 changed files with 217 additions and 158 deletions

View File

@ -185,12 +185,12 @@ TEST_F(TestAT_CellularNetwork, test_AT_CellularNetwork_get_registration_params)
reg_params._periodic_tau = 3;
EXPECT_TRUE(NSAPI_ERROR_DEVICE_ERROR == cn.get_registration_params(CellularNetwork::C_EREG, reg_params));
EXPECT_TRUE(reg_params._status == CellularNetwork::StatusNotAvailable);
EXPECT_TRUE(reg_params._status == CellularNetwork::NotRegistered);
EXPECT_TRUE(reg_params._act == CellularNetwork::RAT_UNKNOWN);
EXPECT_TRUE(reg_params._cell_id == -1 && reg_params._active_time == -1 && reg_params._periodic_tau == -1);
EXPECT_TRUE(NSAPI_ERROR_DEVICE_ERROR == cn.get_registration_params(CellularNetwork::C_GREG, reg_params));
EXPECT_TRUE(reg_params._status == CellularNetwork::StatusNotAvailable);
EXPECT_TRUE(reg_params._status == CellularNetwork::NotRegistered);
EXPECT_TRUE(reg_params._act == CellularNetwork::RAT_UNKNOWN);
EXPECT_TRUE(reg_params._cell_id == -1);
@ -201,12 +201,12 @@ TEST_F(TestAT_CellularNetwork, test_AT_CellularNetwork_get_registration_params)
reg_params._periodic_tau = 3;
EXPECT_TRUE(NSAPI_ERROR_DEVICE_ERROR == nw.get_registration_params(CellularNetwork::C_EREG, reg_params));
EXPECT_TRUE(reg_params._status == CellularNetwork::StatusNotAvailable);
EXPECT_TRUE(reg_params._status == CellularNetwork::NotRegistered);
EXPECT_TRUE(reg_params._act == CellularNetwork::RAT_UNKNOWN);
EXPECT_TRUE(reg_params._cell_id == -1 && reg_params._active_time == -1 && reg_params._periodic_tau == -1);
// Check get_registration_params without specifying the registration type
EXPECT_TRUE(NSAPI_ERROR_OK == cn.get_registration_params(reg_params_check));
EXPECT_TRUE(reg_params_check._status == CellularNetwork::StatusNotAvailable);
EXPECT_TRUE(reg_params_check._status == CellularNetwork::NotRegistered);
EXPECT_TRUE(reg_params_check._act == CellularNetwork::RAT_UNKNOWN);
EXPECT_TRUE(reg_params_check._cell_id == -1 && reg_params_check._active_time == -1 && reg_params_check._periodic_tau == -1);
}
@ -497,7 +497,7 @@ TEST_F(TestAT_CellularNetwork, test_AT_CellularNetwork_get_signal_quality)
ATHandler_stub::int_value = 1;
ATHandler_stub::nsapi_error_value = NSAPI_ERROR_OK;
EXPECT_TRUE(NSAPI_ERROR_OK == cn.get_signal_quality(rs, ber));
EXPECT_TRUE(rs == 1 && ber == 1);
EXPECT_TRUE(rs == -111 && ber == 1);
}
TEST_F(TestAT_CellularNetwork, test_AT_CellularNetwork_get_3gpp_error)

View File

@ -79,7 +79,8 @@ public:
AttachedEmergencyOnly,
RegisteredCSFBNotPreferredHome,
RegisteredCSFBNotPreferredRoaming,
AlreadyRegistered = 11 // our our definition when modem says that we are not registered but we have active PDP Context
AlreadyRegistered = 11, // our definition when modem says that we are not registered but we have active PDP Context
RegistrationStatusMax
};
/* Network registration type */
@ -107,7 +108,8 @@ public:
RAT_E_UTRAN,
RAT_CATM1,
RAT_NB1,
RAT_UNKNOWN
RAT_UNKNOWN,
RAT_MAX = 11 // to reserve string array
};
// 3GPP TS 27.007 - 7.3 PLMN selection +COPS
@ -342,7 +344,7 @@ public:
*/
virtual bool is_active_context() = 0;
/** Gets current network registration parameters:
/** Gets the latest received registration parameters from the network:
* type, status, access technology, cell_id, lac, active_time, periodic_tau.
*
* @param reg_params see registration_params_t
@ -351,7 +353,7 @@ public:
*/
virtual nsapi_error_t get_registration_params(registration_params_t &reg_params) = 0;
/** Gets the network registration parameters based on required registration type:
/** Gets the current network registration parameters from the network with type:
* status, access technology, cell_id, lac, active_time, periodic_tau.
*
* @param type see RegistrationType values

View File

@ -36,6 +36,9 @@ using namespace mbed_cellular_util;
// 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
// Suppress logging of very big packet payloads, maxlen is approximate due to write/read are cached
#define DEBUG_MAXLEN 80
const char *mbed::OK = "OK\r\n";
const uint8_t OK_LENGTH = 4;
const char *mbed::CRLF = "\r\n";
@ -281,8 +284,8 @@ void ATHandler::process_oob()
return;
}
lock();
tr_debug("process_oob readable=%d, pos=%u, len=%u", _fileHandle->readable(), _recv_pos, _recv_len);
if (_fileHandle->readable() || (_recv_pos < _recv_len)) {
tr_debug("AT OoB readable %d, len %u", _fileHandle->readable(), _recv_len - _recv_pos);
_current_scope = NotSet;
uint32_t timeout = _at_timeout;
_at_timeout = PROCESS_URC_TIME;
@ -302,8 +305,8 @@ void ATHandler::process_oob()
}
}
_at_timeout = timeout;
tr_debug("AT OoB done");
}
tr_debug("process_oob exit");
unlock();
}
@ -355,6 +358,7 @@ bool ATHandler::fill_buffer(bool wait_for_timeout)
// Reset buffer when full
if (sizeof(_recv_buff) == _recv_len) {
tr_error("AT overflow");
debug_print(_recv_buff, _recv_len);
reset_buffer();
}
@ -443,15 +447,22 @@ ssize_t ATHandler::read_bytes(uint8_t *buf, size_t len)
return -1;
}
bool debug_on = _debug_on;
size_t read_len = 0;
for (; read_len < len; read_len++) {
int c = get_char();
if (c == -1) {
set_error(NSAPI_ERROR_DEVICE_ERROR);
_debug_on = debug_on;
return -1;
}
buf[read_len] = c;
if (_debug_on && read_len >= DEBUG_MAXLEN) {
debug_print("..", sizeof(".."));
_debug_on = false;
}
}
_debug_on = debug_on;
return read_len;
}
@ -739,13 +750,13 @@ device_err_t ATHandler::get_last_device_error() const
void ATHandler::set_error(nsapi_error_t err)
{
if (err != NSAPI_ERROR_OK) {
tr_debug("AT error %d", err);
}
if (_last_err == NSAPI_ERROR_OK) {
_last_err = err;
}
if (_last_err != err) {
tr_warn("AT error code changed from %d to %d!", _last_err, err);
}
}
int ATHandler::get_3gpp_error()
@ -977,7 +988,7 @@ bool ATHandler::consume_to_stop_tag()
return true;
}
tr_warn("AT stop tag not found");
tr_debug("AT stop tag not found");
set_error(NSAPI_ERROR_DEVICE_ERROR);
return false;
}
@ -1130,20 +1141,31 @@ size_t ATHandler::write(const void *data, size_t len)
fhs.fh = _fileHandle;
fhs.events = POLLOUT;
size_t write_len = 0;
bool debug_on = _debug_on;
for (; write_len < len;) {
int count = poll(&fhs, 1, poll_timeout());
if (count <= 0 || !(fhs.revents & POLLOUT)) {
set_error(NSAPI_ERROR_DEVICE_ERROR);
_debug_on = debug_on;
return 0;
}
ssize_t ret = _fileHandle->write((uint8_t *)data + write_len, len - write_len);
if (ret < 0) {
set_error(NSAPI_ERROR_DEVICE_ERROR);
_debug_on = debug_on;
return 0;
}
if (_debug_on && write_len < DEBUG_MAXLEN) {
if (write_len + ret < DEBUG_MAXLEN) {
debug_print((char *)data + write_len, ret);
} else {
debug_print("..", sizeof(".."));
_debug_on = false;
}
}
write_len += (size_t)ret;
}
_debug_on = debug_on;
return write_len;
}
@ -1175,13 +1197,14 @@ bool ATHandler::check_cmd_send()
void ATHandler::flush()
{
tr_debug("AT flush");
reset_buffer();
while (fill_buffer(false)) {
reset_buffer();
}
}
void ATHandler::debug_print(char *p, int len)
void ATHandler::debug_print(const char *p, int len)
{
#if MBED_CONF_CELLULAR_DEBUG_AT
if (_debug_on) {

View File

@ -524,7 +524,7 @@ private:
bool find_urc_handler(const char *prefix);
// print contents of a buffer to trace log
void debug_print(char *p, int len);
void debug_print(const char *p, int len);
};
} // namespace mbed

View File

@ -44,7 +44,7 @@ AT_CellularContext::AT_CellularContext(ATHandler &at, CellularDevice *device, co
AT_CellularBase(at), _ip_stack_type_requested(DEFAULT_STACK), _is_connected(false), _is_blocking(true),
_current_op(OP_INVALID), _device(device), _nw(0), _fh(0)
{
tr_debug("AT_CellularContext::AT_CellularContext(): apn: %s", apn);
tr_info("New CellularContext %s (%p)", apn ? apn : "", this);
_stack = NULL;
_ip_stack_type = DEFAULT_STACK;
_authentication_type = CellularContext::CHAP;
@ -62,6 +62,8 @@ AT_CellularContext::AT_CellularContext(ATHandler &at, CellularDevice *device, co
AT_CellularContext::~AT_CellularContext()
{
tr_info("Delete CellularContext %s (%p)", _apn ? _apn : "", this);
(void)disconnect();
if (_nw) {
@ -71,12 +73,14 @@ AT_CellularContext::~AT_CellularContext()
void AT_CellularContext::set_file_handle(FileHandle *fh)
{
tr_info("CellularContext filehandle %p", fh);
_fh = fh;
_at.set_file_handle(_fh);
}
nsapi_error_t AT_CellularContext::connect()
{
tr_info("CellularContext connect");
if (_is_connected) {
return NSAPI_ERROR_IS_CONNECTED;
}
@ -200,6 +204,7 @@ void AT_CellularContext::attach(Callback<void(nsapi_event_t, intptr_t)> status_c
nsapi_error_t AT_CellularContext::set_blocking(bool blocking)
{
nsapi_error_t err = NSAPI_ERROR_OK;
tr_info("CellularContext set blocking %d", blocking);
#if NSAPI_PPP_AVAILABLE
err = nsapi_ppp_set_blocking(blocking);
#endif
@ -209,6 +214,7 @@ nsapi_error_t AT_CellularContext::set_blocking(bool blocking)
void AT_CellularContext::set_plmn(const char *plmn)
{
tr_info("CellularContext plmn %s", plmn);
_device->set_plmn(plmn);
}
@ -301,12 +307,6 @@ nsapi_error_t AT_CellularContext::do_user_authentication()
bool AT_CellularContext::get_context()
{
if (_apn) {
tr_debug("APN in use: %s", _apn);
} else {
tr_debug("NO APN");
}
_at.cmd_start("AT+CGDCONT?");
_at.cmd_stop();
_at.resp_start("+CGDCONT:");
@ -388,7 +388,8 @@ bool AT_CellularContext::get_context()
memcpy(_found_apn, apn, apn_len + 1);
}
tr_debug("Context id %d", _cid);
tr_info("Found PDP context %d", _cid);
return true;
}
@ -450,7 +451,7 @@ bool AT_CellularContext::set_new_context(int cid)
_ip_stack_type = tmp_stack;
_cid = cid;
_new_context_set = true;
tr_info("New PDP context id %d was created", _cid);
tr_info("New PDP context %d, stack %s", _cid, pdp_type);
}
return success;
@ -468,9 +469,10 @@ nsapi_error_t AT_CellularContext::do_activate_context()
_at.unlock();
// in PPP we don't activate any context but leave it to PPP stack
return err;
#endif // NSAPI_PPP_AVAILABLE
#else
// try to authenticate user before activating or modifying context
err = do_user_authentication();
#endif // NSAPI_PPP_AVAILABLE
} else {
err = NSAPI_ERROR_NO_CONNECTION;
}
@ -566,7 +568,7 @@ void AT_CellularContext::do_connect()
#if NSAPI_PPP_AVAILABLE
nsapi_error_t AT_CellularContext::open_data_channel()
{
tr_info("Open data channel in PPP mode");
tr_info("CellularContext PPP connect");
if (is_supported(AT_CGDATA)) {
_at.cmd_start("AT+CGDATA=\"PPP\",");
_at.write_int(_cid);
@ -596,7 +598,7 @@ nsapi_error_t AT_CellularContext::open_data_channel()
void AT_CellularContext::ppp_status_cb(nsapi_event_t ev, intptr_t ptr)
{
tr_debug("AT_CellularContext::ppp_status_cb, network_callback called with event: %d, ptr: %d", ev, ptr);
tr_debug("ppp_status_cb: event %d, ptr %d", ev, ptr);
if (ev == NSAPI_EVENT_CONNECTION_STATUS_CHANGE && ptr == NSAPI_STATUS_GLOBAL_UP) {
_is_connected = true;
} else {
@ -613,13 +615,14 @@ void AT_CellularContext::ppp_status_cb(nsapi_event_t ev, intptr_t ptr)
nsapi_error_t AT_CellularContext::disconnect()
{
tr_info("CellularContext disconnect");
if (!_nw || !_is_connected) {
return NSAPI_ERROR_NO_CONNECTION;
}
#if NSAPI_PPP_AVAILABLE
nsapi_error_t err = nsapi_ppp_disconnect(_at.get_file_handle());
if (err != NSAPI_ERROR_OK) {
tr_error("Cellular disconnect failed!");
tr_error("CellularContext disconnect failed!");
// continue even in failure due to ppp disconnect in any case releases filehandle
}
// after ppp disconnect if we wan't to use same at handler we need to set filehandle again to athandler so it
@ -710,7 +713,6 @@ nsapi_error_t AT_CellularContext::get_rate_control(
int next_element = _at.read_int();
if (next_element >= 0) {
reports = (RateControlExceptionReports)next_element;
tr_debug("reports %d", reports);
next_element = _at.read_int();
} else {
comma_found = false;
@ -718,7 +720,6 @@ nsapi_error_t AT_CellularContext::get_rate_control(
if (comma_found && next_element >= 0) {
timeUnit = (RateControlUplinkTimeUnit)next_element;
tr_debug("time %d", timeUnit);
next_element = _at.read_int();
} else {
comma_found = false;
@ -726,7 +727,9 @@ nsapi_error_t AT_CellularContext::get_rate_control(
if (comma_found && next_element >= 0) {
uplinkRate = next_element;
tr_debug("rate %d", uplinkRate);
}
if (_at.get_last_error() == NSAPI_ERROR_OK) {
tr_debug("CGAPNRC: reports %d, time %d, rate %d", reports, timeUnit, uplinkRate);
}
}
_at.resp_stop();
@ -813,7 +816,7 @@ void AT_CellularContext::cellular_callback(nsapi_event_t ev, intptr_t ptr)
cell_callback_data_t *data = (cell_callback_data_t *)ptr;
cellular_connection_status_t st = (cellular_connection_status_t)ev;
_cb_data.error = data->error;
tr_debug("AT_CellularContext::cellular_callback, network_callback called with event: %d, err: %d, data: %d", ev, data->error, data->status_data);
tr_debug("CellularContext: event %d, err %d, data %d", ev, data->error, data->status_data);
#if USE_APN_LOOKUP
if (st == CellularSIMStatusChanged && data->status_data == CellularSIM::SimStateReady &&
_cb_data.error == NSAPI_ERROR_OK) {
@ -880,13 +883,15 @@ void AT_CellularContext::cellular_callback(nsapi_event_t ev, intptr_t ptr)
}
}
} else {
tr_debug("AT_CellularContext::cellular_callback, network_callback called with event: %d, ptr: %d", ev, ptr);
tr_debug("CellularContext: event %d, ptr %d", ev, ptr);
#if NSAPI_PPP_AVAILABLE
if (_is_blocking) {
if (ev == NSAPI_EVENT_CONNECTION_STATUS_CHANGE && ptr == NSAPI_STATUS_GLOBAL_UP) {
tr_info("CellularContext IP %s", get_ip_address());
_cb_data.error = NSAPI_ERROR_OK;
_semaphore.release();
} else if (ev == NSAPI_EVENT_CONNECTION_STATUS_CHANGE && ptr == NSAPI_STATUS_DISCONNECTED) {
tr_info("PPP disconnected");
_cb_data.error = NSAPI_ERROR_NO_CONNECTION;
_semaphore.release();
}
@ -907,5 +912,8 @@ void AT_CellularContext::call_network_cb(nsapi_connection_status_t status)
if (_status_cb) {
_status_cb(NSAPI_EVENT_CONNECTION_STATUS_CHANGE, _connect_status);
}
if (_nw && _connect_status == NSAPI_STATUS_DISCONNECTED) {
tr_info("CellularContext disconnected");
}
}
}

View File

@ -365,5 +365,17 @@ void AT_CellularDevice::modem_debug_on(bool on)
nsapi_error_t AT_CellularDevice::init_module()
{
#if MBED_CONF_MBED_TRACE_ENABLE
CellularInformation *information = open_information();
if (information) {
char *pbuf = new char[100];
nsapi_error_t ret = information->get_model(pbuf, sizeof(*pbuf));
close_information();
if (ret == NSAPI_ERROR_OK) {
tr_info("Model %s", pbuf);
}
delete[] pbuf;
}
#endif
return NSAPI_ERROR_OK;
}

View File

@ -37,6 +37,39 @@ static const at_reg_t at_reg[] = {
{ CellularNetwork::C_REG, "AT+CREG", "+CREG:"}
};
#if MBED_CONF_MBED_TRACE_ENABLE
static const char *const reg_type_str[(int)AT_CellularNetwork::RegistrationStatusMax] = {
"NotRegistered",
"RegisteredHomeNetwork",
"SearchingNetwork",
"RegistrationDenied",
"RegistrationUnknown",
"RegisteredRoaming",
"RegisteredSMSOnlyHome",
"RegisteredSMSOnlyRoaming",
"AttachedEmergencyOnly",
"RegisteredCSFBNotPreferredHome",
"RegisteredCSFBNotPreferredRoaming",
"AlreadyRegistered"
};
static const char *const rat_str[AT_CellularNetwork::RAT_MAX] = {
"GSM",
"GSM_COMPACT",
"UTRAN",
"EGPRS",
"HSDPA",
"HSUPA",
"HSDPA_HSUPA",
"E_UTRAN",
"CATM1",
"NB1",
"RAT unknown",
};
#endif
AT_CellularNetwork::AT_CellularNetwork(ATHandler &atHandler) : AT_CellularBase(atHandler),
_connection_status_cb(NULL), _op_act(RAT_UNKNOWN), _connect_status(NSAPI_STATUS_DISCONNECTED)
{
@ -79,7 +112,7 @@ AT_CellularNetwork::~AT_CellularNetwork()
void AT_CellularNetwork::urc_no_carrier()
{
tr_error("Data call failed: no carrier");
tr_info("NO CARRIER");
call_network_cb(NSAPI_STATUS_DISCONNECTED);
}
@ -89,7 +122,7 @@ void AT_CellularNetwork::urc_cgev()
if (_at.read_string(buf, 13) < 8) { // smallest string length we wan't to compare is 8
return;
}
tr_debug("urc_cgev: %s", buf);
tr_debug("CGEV: %s", buf);
bool call_cb = false;
// NOTE! If in future there will be 2 or more active contexts we might wan't to read context id also but not for now.
@ -116,26 +149,9 @@ void AT_CellularNetwork::urc_cgev()
void AT_CellularNetwork::read_reg_params_and_compare(RegistrationType type)
{
registration_params_t reg_params;
read_reg_params(reg_params);
#if MBED_CONF_MBED_TRACE_ENABLE
switch (reg_params._status) {
case NotRegistered:
tr_warn("not registered");
break;
case RegistrationDenied:
tr_warn("registration denied");
break;
case Unknown:
tr_warn("registration status unknown");
break;
default:
break;
}
#endif
read_reg_params(type, reg_params);
if (_at.get_last_error() == NSAPI_ERROR_OK && _connection_status_cb) {
tr_debug("type: %d, status: %d, lac: %d, cellID: %d, act: %d", type, reg_params._status, reg_params._lac, reg_params._cell_id, reg_params._act);
_reg_params._type = type;
cell_callback_data_t data;
data.error = NSAPI_ERROR_OK;
@ -159,19 +175,16 @@ void AT_CellularNetwork::read_reg_params_and_compare(RegistrationType type)
void AT_CellularNetwork::urc_creg()
{
tr_debug("urc_creg");
read_reg_params_and_compare(C_REG);
}
void AT_CellularNetwork::urc_cereg()
{
tr_debug("urc_cereg");
read_reg_params_and_compare(C_EREG);
}
void AT_CellularNetwork::urc_cgreg()
{
tr_debug("urc_cgreg");
read_reg_params_and_compare(C_GREG);
}
@ -258,18 +271,19 @@ nsapi_error_t AT_CellularNetwork::set_registration(const char *plmn)
return _at.unlock_return_error();
}
void AT_CellularNetwork::read_reg_params(registration_params_t &reg_params)
void AT_CellularNetwork::read_reg_params(RegistrationType type, registration_params_t &reg_params)
{
const int MAX_STRING_LENGTH = 9;
char string_param[MAX_STRING_LENGTH] = {0};
reg_params._type = type;
int int_param = _at.read_int();
reg_params._status = (RegistrationStatus)int_param;
reg_params._status = (int_param >= 0 && int_param < RegistrationStatusMax) ? (RegistrationStatus)int_param : NotRegistered;
int len = _at.read_string(string_param, TWO_BYTES_HEX + 1);
if (len > 0) {
reg_params._lac = hex_str_to_int(string_param, TWO_BYTES_HEX);
tr_debug("lac %s %d", string_param, reg_params._lac);
} else {
reg_params._lac = -1;
}
@ -277,28 +291,25 @@ void AT_CellularNetwork::read_reg_params(registration_params_t &reg_params)
len = _at.read_string(string_param, FOUR_BYTES_HEX + 1);
if (len > 0) {
reg_params._cell_id = hex_str_to_int(string_param, FOUR_BYTES_HEX);
tr_debug("cell_id %s %d", string_param, reg_params._cell_id);
} else {
reg_params._cell_id = -1;
}
int_param = _at.read_int();
reg_params._act = (int_param == -1) ? RAT_UNKNOWN : (RadioAccessTechnology)int_param;
reg_params._act = (int_param >= 0 && int_param < RAT_MAX) ? (RadioAccessTechnology)int_param : RAT_UNKNOWN ;
// Skip [<cause_type>],[<reject_cause>]
_at.skip_param(2);
len = _at.read_string(string_param, ONE_BYTE_BINARY + 1);
reg_params._active_time = calculate_active_time(string_param, len);
if (reg_params._active_time != -1) {
tr_debug("active_time %s %d", string_param, reg_params._active_time);
}
len = _at.read_string(string_param, ONE_BYTE_BINARY + 1);
reg_params._periodic_tau = calculate_periodic_tau(string_param, len);
if (reg_params._periodic_tau == -1) {
tr_debug("periodic_tau %s %d", string_param, reg_params._periodic_tau);
}
#if MBED_CONF_MBED_TRACE_ENABLE
tr_debug("%s %s, LAC %d, cell %d, %s", at_reg[(int)type].urc_prefix, reg_type_str[reg_params._status], reg_params._lac, reg_params._cell_id, rat_str[reg_params._act]);
#endif
}
AT_CellularNetwork::RegistrationMode AT_CellularNetwork::has_registration(RegistrationType reg_type)
@ -485,6 +496,12 @@ nsapi_error_t AT_CellularNetwork::get_signal_quality(int &rssi, int &ber)
return NSAPI_ERROR_DEVICE_ERROR;
}
if (rssi == 99) {
rssi = 0;
} else {
rssi = -113 + 2 * rssi;
}
return _at.unlock_return_error();
}
@ -593,8 +610,7 @@ nsapi_error_t AT_CellularNetwork::get_registration_params(RegistrationType type,
_at.resp_start(rsp[i]);
(void)_at.read_int(); // ignore urc mode subparam
_reg_params._type = type;
read_reg_params(reg_params);
read_reg_params(type, reg_params);
_at.resp_stop();
_reg_params = reg_params;

View File

@ -117,7 +117,7 @@ private:
void urc_cgev();
void read_reg_params_and_compare(RegistrationType type);
void read_reg_params(registration_params_t &reg_params);
void read_reg_params(RegistrationType type, registration_params_t &reg_params);
// Returns active time(Table 10.5.163/3GPP TS 24.008: GPRS Timer 2 information element) in seconds
int calculate_active_time(const char *active_time_string, int active_time_length);

View File

@ -41,6 +41,18 @@ AT_CellularStack::~AT_CellularStack()
_socket = NULL;
}
int AT_CellularStack::find_socket_index(nsapi_socket_t handle)
{
int max_socket_count = get_max_socket_count();
for (int i = 0; i < max_socket_count; i++) {
if (_socket[i] == handle) {
return i;
}
}
return -1;
}
/** NetworkStack
*/
@ -115,21 +127,14 @@ nsapi_error_t AT_CellularStack::socket_open(nsapi_socket_t *handle, nsapi_protoc
}
}
int index = -1;
for (int i = 0; i < max_socket_count; i++) {
if (!_socket[i]) {
index = i;
break;
}
}
int index = find_socket_index(0);
if (index == -1) {
tr_error("No socket found!");
tr_error("No free sockets!");
_socket_mutex.unlock();
return NSAPI_ERROR_NO_SOCKET;
}
tr_info("Socket open index: %d", index);
tr_info("Socket %d open", index);
// create local socket structure, socket on modem is created when app calls sendto/recvfrom
_socket[index] = new CellularSocket;
CellularSocket *psock;
@ -156,18 +161,8 @@ nsapi_error_t AT_CellularStack::socket_close(nsapi_socket_t handle)
}
int sock_id = socket->id;
bool sock_created = socket->created;
int max_socket_count = get_max_socket_count();
int index = -1;
for (int i = 0; i < max_socket_count; i++) {
if (_socket[i] == socket) {
index = i;
break;
}
}
tr_info("Close socket index: %d id: %d created: %d", index, sock_id, socket->created);
int index = find_socket_index(handle);
if (index == -1) {
tr_error("No socket found to be closed");
return err;
@ -181,6 +176,12 @@ nsapi_error_t AT_CellularStack::socket_close(nsapi_socket_t handle)
err = socket_close_impl(sock_id);
}
if (!err) {
tr_info("Socket %d closed", index);
} else {
tr_info("Socket %d close (id %d, created %d, started %d, error %d)", index, sock_id, socket->created, socket->started, err);
}
_socket[index] = NULL;
delete socket;
@ -260,10 +261,8 @@ nsapi_size_or_error_t AT_CellularStack::socket_sendto(nsapi_socket_t handle, con
_at.unlock();
if (ret_val != NSAPI_ERROR_OK) {
tr_error("Error creating socket to send to: %s error code: %d", addr.get_ip_address(), ret_val);
tr_error("Socket %d create %s error %d", find_socket_index(socket), addr.get_ip_address(), ret_val);
return ret_val;
} else {
tr_info("Success creating socket to send to: %s", addr.get_ip_address());
}
}
@ -276,14 +275,14 @@ nsapi_size_or_error_t AT_CellularStack::socket_sendto(nsapi_socket_t handle, con
ret_val = socket_sendto_impl(socket, addr, data, size);
if (ret_val > 0) {
tr_info("Success sending %d Bytes to: %s", ret_val, addr.get_ip_address());
} else if (ret_val != NSAPI_ERROR_WOULD_BLOCK) {
tr_error("Error sending to: %s error code: %d", addr.get_ip_address(), ret_val);
}
_at.unlock();
if (ret_val >= 0) {
tr_info("Socket %d sent %d bytes to %s port %d", find_socket_index(socket), ret_val, addr.get_ip_address(), addr.get_port());
} else if (ret_val != NSAPI_ERROR_WOULD_BLOCK) {
tr_error("Socket %d sendto %s error %d", find_socket_index(socket), addr.get_ip_address(), ret_val);
}
return ret_val;
}
@ -308,6 +307,7 @@ nsapi_size_or_error_t AT_CellularStack::socket_recvfrom(nsapi_socket_t handle, S
_at.unlock();
if (ret_val != NSAPI_ERROR_OK) {
tr_error("Socket %d create %s error %d", find_socket_index(socket), addr->get_ip_address(), ret_val);
return ret_val;
}
}
@ -318,6 +318,12 @@ nsapi_size_or_error_t AT_CellularStack::socket_recvfrom(nsapi_socket_t handle, S
_at.unlock();
if (ret_val >= 0) {
tr_info("Socket %d recv %d bytes from %s port %d", find_socket_index(socket), ret_val, addr->get_ip_address(), addr->get_port());
} else if (ret_val != NSAPI_ERROR_WOULD_BLOCK) {
tr_error("Socket %d recv error %d", find_socket_index(socket), ret_val);
}
return ret_val;
}

View File

@ -182,6 +182,8 @@ protected:
nsapi_ip_stack_t _stack_type;
private:
int find_socket_index(nsapi_socket_t handle);
// mutex for write/read to a _socket array, needed when multiple threads may open sockets simultaneously
PlatformMutex _socket_mutex;
};

View File

@ -157,7 +157,7 @@ void CellularDevice::cellular_callback(nsapi_event_t ev, intptr_t ptr)
{
if (ev >= NSAPI_EVENT_CELLULAR_STATUS_BASE && ev <= NSAPI_EVENT_CELLULAR_STATUS_END) {
cell_callback_data_t *ptr_data = (cell_callback_data_t *)ptr;
tr_debug("Device: network_callback called with event: %d, err: %d, data: %d", ev, ptr_data->error, ptr_data->status_data);
tr_debug("callback: %d, err: %d, data: %d", ev, ptr_data->error, ptr_data->status_data);
cellular_connection_status_t cell_ev = (cellular_connection_status_t)ev;
if (cell_ev == CellularRegistrationStatusChanged && _state_machine) {
// broadcast only network registration changes to state machine
@ -180,7 +180,7 @@ void CellularDevice::cellular_callback(nsapi_event_t ev, intptr_t ptr)
}
}
} else {
tr_debug("Device: network_callback called with event: %d, ptr: %d", ev, ptr);
tr_debug("callback: %d, ptr: %d", ev, ptr);
if (ev == NSAPI_EVENT_CONNECTION_STATUS_CHANGE && ptr == NSAPI_STATUS_DISCONNECTED) {
// we have been disconnected, reset state machine so that application can start connect sequence again
if (_state_machine) {

View File

@ -89,6 +89,7 @@ void CellularStateMachine::reset()
void CellularStateMachine::stop()
{
tr_debug("CellularStateMachine stop");
if (_queue_thread) {
_queue.break_dispatch();
_queue_thread->terminate();
@ -118,10 +119,10 @@ bool CellularStateMachine::power_on()
{
_cb_data.error = _power->on();
if (_cb_data.error != NSAPI_ERROR_OK && _cb_data.error != NSAPI_ERROR_UNSUPPORTED) {
tr_warn("Cellular start failed. Power off/on.");
tr_warn("Power on failed. Try to power off/on.");
_cb_data.error = _power->off();
if (_cb_data.error != NSAPI_ERROR_OK && _cb_data.error != NSAPI_ERROR_UNSUPPORTED) {
tr_error("Cellular power down failing after failed power up attempt!");
tr_error("Power off failed!");
}
return false;
}
@ -162,14 +163,14 @@ bool CellularStateMachine::open_sim()
if (state == CellularSIM::SimStatePinNeeded) {
if (strlen(_sim_pin)) {
tr_info("Entering PIN to open SIM");
tr_info("Entering PIN to open SIM.");
_cb_data.error = _sim->set_pin(_sim_pin);
if (_cb_data.error) {
tr_error("SIM pin set failed with: %d", _cb_data.error);
tr_error("Failed to set PIN: error %d", _cb_data.error);
}
} else {
// No sim pin provided even it's needed, stop state machine
tr_error("PIN required but No SIM pin provided.");
tr_error("PIN required but no SIM pin provided.");
_retry_count = RETRY_ARRAY_SIZE;
return false;
}
@ -185,7 +186,6 @@ bool CellularStateMachine::is_registered()
for (int type = 0; type < CellularNetwork::C_MAX; type++) {
if (get_network_registration((CellularNetwork::RegistrationType) type, status, is_registered)) {
tr_debug("get_network_registration: type=%d, status=%d", type, status);
if (is_registered) {
break;
}
@ -242,7 +242,7 @@ bool CellularStateMachine::get_network_registration(CellularNetwork::Registratio
}
if (is_roaming) {
tr_warn("Roaming cellular network!");
tr_info("Roaming network.");
}
return true;
@ -250,7 +250,7 @@ bool CellularStateMachine::get_network_registration(CellularNetwork::Registratio
void CellularStateMachine::report_failure(const char *msg)
{
tr_error("Cellular stm failed with: %s", msg);
tr_error("CellularStateMachine failure: %s", msg);
_event_id = -1;
if (_event_status_cb) {
@ -258,7 +258,7 @@ void CellularStateMachine::report_failure(const char *msg)
_event_status_cb(_current_event, (intptr_t)&_cb_data);
}
tr_error("Target state %s was not reached. Returning from state: %s", get_state_string(_target_state), get_state_string(_state));
tr_error("CellularStateMachine target state %s, current state %s", get_state_string(_target_state), get_state_string(_state));
}
const char *CellularStateMachine::get_state_string(CellularState state) const
@ -332,7 +332,7 @@ void CellularStateMachine::enter_to_state(CellularState state)
void CellularStateMachine::retry_state_or_fail()
{
if (++_retry_count < RETRY_ARRAY_SIZE) {
tr_debug("Retry State %s, retry %d/%d", get_state_string(_state), _retry_count, RETRY_ARRAY_SIZE);
tr_debug("%s: retry %d/%d", get_state_string(_state), _retry_count, RETRY_ARRAY_SIZE);
_event_timeout = _retry_timeout_array[_retry_count];
_is_retry = true;
} else {
@ -343,19 +343,19 @@ void CellularStateMachine::retry_state_or_fail()
void CellularStateMachine::state_init()
{
// we should check that if power is already on then we can jump to device ready state
_cellularDevice.set_timeout(TIMEOUT_POWER_ON);
tr_info("Cellular state init (timeout %d ms)", TIMEOUT_POWER_ON);
tr_info("Start connecting (timeout %d s)", TIMEOUT_POWER_ON / 1000);
if (!_power) {
_power = _cellularDevice.open_power();
}
_cb_data.error = _power->is_device_ready();
if (_cb_data.error != NSAPI_ERROR_OK) {
_event_timeout = _start_time;
tr_info("Init state, waiting %d ms before POWER state)", _start_time);
if (_start_time > 0) {
tr_info("Startup delay %d ms", _start_time);
}
enter_to_state(STATE_POWER_ON);
} else {
tr_info("Device was ready to accept commands, jump to device ready");
enter_to_state(STATE_DEVICE_READY);
}
}
@ -363,7 +363,7 @@ void CellularStateMachine::state_init()
void CellularStateMachine::state_power_on()
{
_cellularDevice.set_timeout(TIMEOUT_POWER_ON);
tr_info("Cellular power ON (timeout %d ms)", TIMEOUT_POWER_ON);
tr_info("Modem power ON (timeout %d s)", TIMEOUT_POWER_ON / 1000);
if (power_on()) {
enter_to_state(STATE_DEVICE_READY);
} else {
@ -374,7 +374,7 @@ void CellularStateMachine::state_power_on()
bool CellularStateMachine::device_ready()
{
tr_info("Cellular device ready");
tr_info("Modem ready");
if (_cellularDevice.init_module() != NSAPI_ERROR_OK) {
return false;
}
@ -408,7 +408,7 @@ void CellularStateMachine::state_device_ready()
void CellularStateMachine::state_sim_pin()
{
_cellularDevice.set_timeout(TIMEOUT_SIM_PIN);
tr_info("Sim state (timeout %d ms)", TIMEOUT_SIM_PIN);
tr_info("Setup SIM (timeout %d s)", TIMEOUT_SIM_PIN / 1000);
if (open_sim()) {
if (!_network) {
_network = _cellularDevice.open_network();
@ -442,8 +442,8 @@ void CellularStateMachine::state_sim_pin()
void CellularStateMachine::state_registering()
{
_cellularDevice.set_timeout(TIMEOUT_NETWORK);
tr_info("Network registration (timeout %d s)", TIMEOUT_REGISTRATION / 1000);
if (is_registered()) {
tr_info("Sending Registration changed from plmn");
_cb_data.status_data = CellularNetwork::AlreadyRegistered;
_cb_data.error = NSAPI_ERROR_OK;
_event_status_cb(_current_event, (intptr_t)&_cb_data);
@ -463,11 +463,10 @@ void CellularStateMachine::state_registering()
void CellularStateMachine::state_manual_registering_network()
{
_cellularDevice.set_timeout(TIMEOUT_REGISTRATION);
tr_info("state_manual_registering_network");
tr_info("Manual registration %s (timeout %d s)", _plmn, TIMEOUT_REGISTRATION / 1000);
if (!_plmn_network_found) {
if (is_registered() && is_registered_to_plmn()) {
// we have to send registration changed event as network thinks that we are not registered even we have active PDP context
tr_info("Sending REgistration changed from plmn");
_cb_data.status_data = CellularNetwork::AlreadyRegistered;
_cb_data.error = NSAPI_ERROR_OK;
_event_status_cb(_current_event, (intptr_t)&_cb_data);
@ -486,8 +485,8 @@ void CellularStateMachine::state_manual_registering_network()
void CellularStateMachine::state_attaching()
{
_cellularDevice.set_timeout(TIMEOUT_CONNECT);
tr_info("Attaching network (timeout %d s)", TIMEOUT_CONNECT / 1000);
_cb_data.error = _network->set_attach();
tr_info("CellularStateMachine::state_attaching(): %d", _cb_data.error);
if (_cb_data.error == NSAPI_ERROR_OK) {
_cellularDevice.close_sim();
_sim = NULL;
@ -503,7 +502,7 @@ void CellularStateMachine::state_attaching()
void CellularStateMachine::continue_from_state(CellularState state)
{
_mutex.lock();
tr_info("Continue state from %s to %s", get_state_string((CellularStateMachine::CellularState)_state),
tr_info("%s => %s", get_state_string((CellularStateMachine::CellularState)_state),
get_state_string((CellularStateMachine::CellularState)state));
_state = state;
enter_to_state(state);
@ -533,7 +532,6 @@ nsapi_error_t CellularStateMachine::run_to_state(CellularStateMachine::CellularS
void CellularStateMachine::pre_event(CellularState state)
{
tr_debug("CellularStateMachine::pre_event, state: %s, _target_state: %s, _event_id: %d", get_state_string(state), get_state_string(_target_state), _event_id);
if (_target_state < state) {
// new wanted state will not be achieved with current _target_state so update it
_target_state = state;
@ -571,7 +569,20 @@ bool CellularStateMachine::get_current_status(CellularStateMachine::CellularStat
void CellularStateMachine::event()
{
tr_debug("CellularStateMachine::event(): %s", get_state_string(_state));
#if MBED_CONF_MBED_TRACE_ENABLE
if (_network) {
int rssi;
int ber;
if (_network->get_signal_quality(rssi, ber) == NSAPI_ERROR_OK) {
if (rssi == 0) {
tr_info("RSSI unknown");
} else {
tr_info("RSSI %d dBm", rssi);
}
}
}
#endif
_event_timeout = -1;
_is_retry = false;
@ -610,17 +621,16 @@ void CellularStateMachine::event()
}
if ((_target_state == _state && _cb_data.error == NSAPI_ERROR_OK && !_is_retry) || _event_id == STM_STOPPED) {
tr_info("Target state reached: %s, _cb_data.error: %d, _event_id: %d", get_state_string(_target_state), _cb_data.error, _event_id);
_event_id = -1;
return;
}
if (_next_state != _state || _event_timeout >= 0) {
if (_next_state != _state) { // state exit condition
tr_info("Cellular state from %s to %s", get_state_string((CellularStateMachine::CellularState)_state),
tr_debug("%s => %s", get_state_string((CellularStateMachine::CellularState)_state),
get_state_string((CellularStateMachine::CellularState)_next_state));
} else {
tr_info("Cellular event in %d seconds", _event_timeout);
tr_info("Continue after %d seconds", _event_timeout);
}
_state = _next_state;
if (_event_timeout == -1) {
@ -629,7 +639,7 @@ void CellularStateMachine::event()
_event_id = _queue.call_in(_event_timeout * 1000, callback(this, &CellularStateMachine::event));
if (!_event_id) {
_cb_data.error = NSAPI_ERROR_NO_MEMORY;
report_failure("Cellular event failure!");
report_failure("CellularStateMachine event failure!");
return;
}
}
@ -656,12 +666,6 @@ void CellularStateMachine::set_cellular_callback(mbed::Callback<void(nsapi_event
void CellularStateMachine::cellular_event_changed(nsapi_event_t ev, intptr_t ptr)
{
cell_callback_data_t *data = (cell_callback_data_t *)ptr;
if (ev >= NSAPI_EVENT_CELLULAR_STATUS_BASE && ev <= NSAPI_EVENT_CELLULAR_STATUS_END) {
tr_debug("FSM: cellular_event_changed called with event: %d, err: %d, data: %d _state: %s", ev, data->error, data->status_data, get_state_string(_state));
} else {
tr_debug("FSM: cellular_event_changed called with event: %d, ptr: %d _state: %s", ev, ptr, get_state_string(_state));
}
if ((cellular_connection_status_t)ev == CellularRegistrationStatusChanged &&
(_state == STATE_REGISTERING_NETWORK || _state == STATE_MANUAL_REGISTERING_NETWORK)) {
// expect packet data so only these states are valid

View File

@ -154,6 +154,8 @@ bool GEMALTO_CINTERION_CellularStack::is_protocol_supported(nsapi_protocol_t pro
nsapi_error_t GEMALTO_CINTERION_CellularStack::socket_close_impl(int sock_id)
{
tr_debug("Cinterion close %d", sock_id);
_at.set_at_timeout(FAILURE_TIMEOUT);
_at.cmd_start("AT^SISC=");
@ -169,7 +171,6 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::socket_close_impl(int sock_id)
_at.restore_at_timeout();
tr_debug("Closed socket %d (err %d)", sock_id, _at.get_last_error());
return _at.get_last_error();
}
@ -210,7 +211,7 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::socket_open_defer(CellularSocket
}
socket->created = true;
tr_debug("Socket %d created (err %d)", socket->id, _at.get_last_error());
tr_debug("Cinterion open %d (err %d)", socket->id, _at.get_last_error());
return _at.get_last_error();
}
@ -247,20 +248,17 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::create_socket_impl(CellularSocket
if (paramValueLen >= 0) {
if (strcmp(paramTag, "srvType") == 0) {
if (strcmp(paramValue, "Socket") == 0) {
tr_debug("srvType %s", paramValue);
foundSrvType = true;
}
}
if (strcmp(paramTag, "address") == 0) {
if (strncmp(paramValue, "sock", sizeof("sock")) == 0) {
tr_debug("address %s", paramValue);
foundSrvType = true;
}
}
if (strcmp(paramTag, "conId") == 0) {
char buf[10];
std::sprintf(buf, "%d", connection_profile_id);
tr_debug("conId %s", paramValue);
if (strcmp(paramValue, buf) == 0) {
foundConIdType = true;
}
@ -287,8 +285,6 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::create_socket_impl(CellularSocket
_at.cmd_stop_read_resp();
}
tr_debug("Internet service %d (err %d)", internet_service_id, _at.get_last_error());
if (socket->proto == NSAPI_UDP) {
if (GEMALTO_CINTERION_Module::get_model() != GEMALTO_CINTERION_Module::ModelBGS2) {
return socket_open_defer(socket);
@ -301,8 +297,6 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::create_socket_impl(CellularSocket
nsapi_size_or_error_t GEMALTO_CINTERION_CellularStack::socket_sendto_impl(CellularSocket *socket,
const SocketAddress &address, const void *data, nsapi_size_t size)
{
tr_debug("Socket %d, sendto %s, len %d", socket->id, address.get_ip_address(), size);
if (socket->proto == NSAPI_UDP) {
const int ip_version = address.get_ip_version();
if ((ip_version == NSAPI_IPv4 && _stack_type != IPV4_STACK) ||
@ -404,8 +398,6 @@ sisw_retry:
_at.resp_stop();
_at.restore_at_timeout();
tr_debug("Socket %d sendto %s, %d bytes (err %d)", socket->id, address.get_ip_address(), accept_len, _at.get_last_error());
if (_at.get_last_error() == NSAPI_ERROR_OK) {
socket->tx_ready = false;
}
@ -416,8 +408,6 @@ sisw_retry:
nsapi_size_or_error_t GEMALTO_CINTERION_CellularStack::socket_recvfrom_impl(CellularSocket *socket, SocketAddress *address,
void *buffer, nsapi_size_t size)
{
tr_debug("Socket %d recvfrom %d bytes", socket->id, size);
// we must use this flag, otherwise ^SISR URC can come while we are reading response and there is
// no way to detect if that is really an URC or response
if (!socket->rx_avail) {
@ -504,7 +494,6 @@ sisr_retry:
port_start++; // skip ':'
int port = std::strtol(port_start, NULL, 10);
address->set_port(port);
tr_debug("IP address %s, port %d", address->get_ip_address(), address->get_port());
*ip_stop = tmp_ch; // restore original IP string
}
}
@ -518,8 +507,6 @@ sisr_retry:
_at.resp_stop();
tr_debug("Socket %d, recvfrom %s, %d bytes (err %d)", socket->id, socket->remoteAddress.get_ip_address(), len, _at.get_last_error());
return (_at.get_last_error() == NSAPI_ERROR_OK) ? (recv_len ? recv_len : NSAPI_ERROR_WOULD_BLOCK) : NSAPI_ERROR_DEVICE_ERROR;
}
@ -543,7 +530,6 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::create_connection_profile(int con
char paramTag[16];
int paramTagLen = _at.read_string(paramTag, sizeof(paramTag));
if (paramTagLen > 0) {
tr_debug("paramTag %s", paramTag);
char paramValue[100 + 1]; // APN may be up to 100 chars
int paramValueLen = _at.read_string(paramValue, sizeof(paramValue));
if (paramValueLen >= 0) {
@ -587,7 +573,7 @@ nsapi_error_t GEMALTO_CINTERION_CellularStack::create_connection_profile(int con
_at.cmd_stop_read_resp();
}
tr_debug("Connection profile %d, stack_type %d (err %d)", connection_profile_id, _stack_type, _at.get_last_error());
tr_debug("Cinterion profile %d, %s (err %d)", connection_profile_id, (_stack_type == IPV4_STACK) ? "IPv4" : "IPv6", _at.get_last_error());
return _at.get_last_error();
}