UBLOX Cellular: socket failed to connect

[pilotak]

Description

Just before PR #10639 following code worked perfectly.

nsapi_error_t Test::connect() {
    nsapi_error_t ret = NSAPI_ERROR_DEVICE_ERROR;

    if (_network) {
        ret = _network->connect();

        if (ret == NSAPI_ERROR_OK || ret == NSAPI_ERROR_IS_CONNECTED) {
            ret = _socket.open(_network);

            if (ret == NSAPI_ERROR_OK) {
                debug("open OK\n");

                ret = _socket.connect(_server, _port);

                if (ret == NSAPI_ERROR_OK || ret == NSAPI_ERROR_IS_CONNECTED) {
                    debug("connected\n");
                    return ret;

                } else {
                    debug("connect FAILED: %i\n", ret);
                }

            } else {
                debug("open FAILED\n");
            }

            _socket.close();

        } else {
            debug("network connect failed");
        }

    } else {
        debug("no network\n");
    }

    _is_connected = false;
    return ret;
}

here is a log:

[INFO][CELL]: CellularContext connect
[INFO][CELL]: AT TX (12): AT+UPSND=0,8
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: Socket 0 open
open OK
[INFO][CELL]: AT RX ( 6): <cr><ln>+UPS
[INFO][CELL]: AT RX (11): ND: 0,8,0<cr><ln>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX (12): AT+UPSD=0,1,
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 8): internet
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 2): <cr><ln>
[INFO][CELL]: AT RX ( 4): OK<cr><ln>
[INFO][CELL]: AT TX (21): AT+UPSD=0,7,"0.0.0.0"
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 5): <cr><ln>OK<cr>
[INFO][CELL]: AT RX ( 1): <ln>
[INFO][CELL]: AT TX (12): AT+UPSD=0,6,
[INFO][CELL]: AT TX ( 1): 0
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX (12): AT+UPSDA=0,3
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 4): <cr><ln>OK
[INFO][CELL]: AT RX ( 2): <cr><ln>
[INFO][CELL]: AT TX (10): AT+USOCR=6
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 8): <cr><ln>+USOCR
[INFO][CELL]: AT RX (10): : 0<cr><ln><cr><ln>OK<cr>
[INFO][CELL]: AT RX ( 1): <ln>
[INFO][CELL]: AT TX ( 9): AT+USOCO=
[INFO][CELL]: AT TX ( 1): 0
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX (13): 12.34.567.890
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 5): 20838
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
connected

but after that PR got merged i can't connect to socket and as you can see AT+USOCO has as next argument -1 instead if socket id 0.
For some reason even though it fails (+CME ERROR: 4 and AT error -3012) _socket.connect() doesn't return negative number as error, but that may be another issue or i misunderstood the returns of TCPSocket _socket

[INFO][CELL]: CellularContext connect
[INFO][CELL]: AT TX (12): AT+UPSND=0,8
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: Socket 0 open
open OK
[INFO][CELL]: AT RX (11): <cr><ln>+UPSND: 0
[INFO][CELL]: AT RX (12): ,8,0<cr><ln><cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX (12): AT+UPSD=0,1,
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 8): internet
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX (21): AT+UPSD=0,7,"0.0.0.0"
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX (12): AT+UPSD=0,6,
[INFO][CELL]: AT TX ( 1): 0
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 2): <cr><ln>
[INFO][CELL]: AT RX ( 4): OK<cr><ln>
[INFO][CELL]: AT TX (12): AT+UPSDA=0,3
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>OK<cr><ln>
[INFO][CELL]: AT TX ( 9): AT+USOCO=
[INFO][CELL]: AT TX ( 2): -1
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX (13): 12.34.567.890
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 5): 20838
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 6): <cr><ln>+CME
[INFO][CELL]: AT RX (11):  ERROR: 4<cr><ln>
[ERR ][CELL]: AT error code 4
[DBG ][CELL]: AT error -3012
connected

Board: STM32F412ZG and STM32F303RE as well
Modem: SARA-G350
compiled with ARM-GCC

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug

[0xc0170]

cc @AriParkkila
@ARMmbed/mbed-os-wan

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-1231

[AriParkkila]

@pilotak yes, that seems like a regression. Please retry with this fix #10696

[pilotak]

#10696 fixes this issue, thank you

[pilotak]

the second part of this issue is that when socket fails to connect i doesn't return negative number. Bellow is log when server i'm connecting to is down. Or do you want me to create a different issue?

[INFO][CELL]: AT TX ( 9): AT+USOCO=
[INFO][CELL]: AT TX ( 1): 0
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX (13): 12.34.567.890
[INFO][CELL]: AT TX ( 1): "
[INFO][CELL]: AT TX ( 1): ,
[INFO][CELL]: AT TX ( 5): 20838
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX (16): <cr><ln>ERROR<cr><ln><cr><ln>+UUSO
[DBG ][CELL]: AT error -3012
[DBG ][CELL]: AT OoB readable 1, len 7
[INFO][CELL]: AT RX ( 7): CL: 0<cr><ln>
[DBG ][CELL]: AT OoB done
connected

Coresponding code:

ret = _socket.connect(_server, _port);

if (ret == NSAPI_ERROR_OK || ret == NSAPI_ERROR_IS_CONNECTED) {
    debug("connected\n");
    return ret;

} else {
    debug("connect FAILED: %i\n", ret);
}

[AriParkkila]

@pilotak could you re-try with the updated #10696

[pilotak]

@AriParkkila perfect thanks a lot, it returns NSAPI_ERROR_NO_CONNECTION (-3004) if server is unavailable. This can be considered as resolved.

One more last thing though. Once you are succesfully connected to server and server stops working I can see in debug:

[DBG ][CELL]: AT OoB readable 1, len 0
[INFO][CELL]: AT RX (14): <cr><ln>+UUSOCL: 0<cr><ln>
[DBG ][CELL]: AT OoB done

which is perfect but i have callback registered with _socket.sigio(callback(this, &Test::socketCb)); but there is no cb called. If I try to listen for data _socket.recv(buffer, size) after i received above, no negative error is returned so it looks the socket is still open (from OS point of view).
The only way to check if the socket is still open is to write data to it _socket.send(data, size) - this will give you NSAPI_ERROR_DEVICE_ERROR (-3012)

[AriParkkila]

@pilotak UBLOX_AT_CellularStack seems to be missing a callback on socket closed. @ARMmbed/team-ublox please check that.

[pilotak]

@AriParkkila do you want me to create a separate issue for that? cause week is over and i don't know if somebody spotted that mentioning

[AriParkkila]

@pilotak That sounds like a good idea. Please create a new issue to add missing callbacks, and I guess this issue can then be closed.