arduino-libraries / MKRGSM

GNU Lesser General Public License v2.1
55 stars 51 forks source link

GSMClient::connect() drives GSMClient state machine before initializing _state to CLIENT_STATE_CREATE_SOCKET; #55

Closed Nels52 closed 6 years ago

Nels52 commented 6 years ago

If the modem fails to respond to an AT command the GSMClient state machine hangs in a state other than CLIENT_STATE_CREATE_SOCKET. After the modem is reinitialized with GSM::begin() and GPRS::attachGPRS() methods the GSMClient::connect() method returns ERROR because this method fails to reset the state to CLIENT_STATE_CREATE_SOCKET before driving the GSMClient state machine.

The problem is detailed below:

  1. All of my modem interface instances (GSM, GPRS, and GSMClient) are configured to operate asynchronously so my script can control the progression thru their state machines using the ready() methods in each class. This prevents unrecoverable hangs when no response is received from the modem to an AT command.
    1. Script issues GSMClient::connect() which generates an AT+USOCR=6 command to open a socket.
    2. Script attempts to recover by invoking GSM::begin() followed by GPRS::attachGPRS().
    3. If both GSM and GPRS are restarted successfully GSMClient::connect() is invoked again.
    4. The GSMClient::connect() issues an AT+USOCO=... command because the GSMClient has been left in the CLIENT_STATE_WAIT_CREATE_SOCKET_RESPONSE state by the modem hang in step 2.
    5. The AT+USOCO=... command returns ERROR because the socket is not valid.
    6. The next GSMClient::ready() method call generates an AT+USOCL command which also returns ERROR, however, the GSMClient state has been returned to CLIENT_STATE_IDLE so that the next GSMClient::connect() method call will work properly.

I have changed the GSMClient::connect() method to address this issue and it works without any adverse affects. The change is a simple one to the beginning of the GSMClient::connect() method:

Here is the beginning of the GSMClient::connect() version in the 1.2.1 library:

if (_synch) { while (ready() == 0); } else if (ready() == 0) { return 0; } _state = CLIENT_STATE_CREATE_SOCKET;

I have made the following changes:

if (_synch) { while (MODEM.ready() == 0); } else if (MODEM.ready() == 0) { return 0; } _state = CLIENT_STATE_CREATE_SOCKET;

By replacing the ready() calls with MODEM.ready() calls the GSMClient state machine is not erroneously driven before the _state is initialized. Therefore, the method still returns 0 in asynchronous mode OR stays in a while loop in synchronous mode if an AT command is outstanding. Normally this will not be the case but I understand the need to check for an outstanding AT command before continuing with the connect request.

NOTE: I have not tested synchronous mode but looking at the code change I don't see an issue.

Nels52 commented 6 years ago

Hi @sandeepmistry,

I have attached my script (HomeMonitorV2,txt) and the Serial output (SerialOutput.txt) from that script with debug enabled. In the serial output you will see where my script times out a connection request: "Connection Timed OUT loopCount = 600". After the GSM and GPRS have been restarted you will see where a connnection is attempted: "GSMClient state machine out of sync". Because the GSMClient is in the CLIENT_STATE_WAIT_CREATE_SOCKET_RESPONSE state the AT+USOCO=0,"cloudsocket.hologram.io",9999 command is issued with an invalid socket. The modem returns ERROR to this command and the AT+USOCL=0 command that follows. When the GSMClient::connect() is issued after these ERROR returns a connection is successfully established because the GSMClient has been set the initial CLIENT_STATE_CREATE_SOCKET state.

HomeMonitorV2.txt SerialOutput.txt

Rocketct commented 6 years ago

Hi @Nels52, thank you for open the issue we are work on this, i should ask a more minimal sketch that reproduce the error?

Nels52 commented 6 years ago

Hi @Rocketct, I have embedded a stripped down version of my script. I have compiled it but not loaded and tested it but it should recreate the issue. The key to recreation is to connect to a web server, send a message and disconnect from the web server. In my case I use Hologram which automatically disconnects after receiving a message. It most likely will take multiple iterations before the client connect sequence hangs. A little more than a week ago my connect sequence would hang several times a day. However, it appears something has changed with my network (changes/fixes by my network provider??) and now my client connect sequence hasn't failed for a week.

Hope this helps. Let me know if you need further assistance.

/*
 Reproduce GSMClient Connect Issue

 This script sends a test message to a web server (in my case Hologram) every 10 minutes.
 After sending the test message the Hologram web server disconnects.  Therefore the connect sequence must
 be reinitiated every time the test message is sent.  If you use a different web server you must ensure that
 the connection is terminated each time a message is sent.

 The issue occurs when the connection sequence hangs (usually on the AT+USOCR=6 command). When this happens the
 script restarts GSM and GPRS from scratch (GSM.begin() and GPRS.attachGPRS()).  After GSM and GPRS are restarted
 successfully the GSMClient.connect(server, port) fails (ERROR is returned to next AT command sent to the modem)
 because the GSMClient state has not been reinitialized.

 In summary:
  - Use GSM, GPRS, and GSMClient instances running in asynchronous mode.
  - Restart GSM and GPRS instances after a GSMClient connect sequence hangs.
  - Reconnect GSMClient after successfully restarting GSM and GPRS.

 Circuit:
 * MKR GSM 1400 board
 * Antenna
 * SIM card with a data plan

*/

// libraries
#include <MKRGSM.h>

// Replace "arduino_secrets.h" as all the information for that is publicly available from https://hologram.io/docs/guide/connect/connect-device/#apn-settings

// Hologram SIM does not use a PIN number
const char PINNUMBER[] = " ";

// APN data. In my example I use the hologram web server.  However, any web server can be used.
const char GPRS_APN[] = "hologram";
const char GPRS_LOGIN[] = " ";
const char GPRS_PASSWORD[] = " ";
String HOLOGRAM_API_KEY = "xxxxxx";   // Need your own hologram generated key here

String TOPIC = "MY_TOPIC";
String MESSAGE_TEST = "Test Message";

String HOLOGRAM_RESPONSE_ARRAY[] = {"Send successful, no error",
                                    "Connection was closed so we couldn’t read enough",
                                    "Couldn’t parse the message",
                                    "Auth section of message was invalid",
                                    "Payload type was invalid",
                                    "Protocol type was invalid",
                                    "An internal error occurred",
                                    "Metadata section of message was formatted incorrectly",
                                    "Topic contained invalid characters or was too long"};

/// Test multiple connections within one run
// initialize the library instances
GSMClient client(false);     // Instantiate a GSMClient instance operating in asynchronous mode
GPRS gprs;
GSM gsmAccess(true);         // Turn debug on so we see all AT commands and responses

// Hologram's Embedded API (https://hologram.io/docs/reference/cloud/embedded/) URL and port
char server[] = "cloudsocket.hologram.io";
int port = 9999;

bool clientConnected = false;     // Connection state flag
bool restartClient = true;        // Client restarted flag - initially set to ensure temperature is reported at startup
bool sendTestMessage = false;      // Send test message
unsigned long lastConnectTime = 0;    // Last time temperature was read

// Script defines
#define BAUD_RATE_115200                      115200    // Serial ports baud rate
#define CONNECT_INTERNAL_10_MINUTES           600000    // 10 minutes in milliseconds

// Execute once at startup
void setup()
{

  // Initialize serial communications
  Serial.begin(BAUD_RATE_115200);

  /// Wait for Serial port before proceeding with script
  while (!Serial)
  {
    ; // wait for serial port to connect. Needed for native USB port only
  }

  // Initialize web client
  do 
  {
  } while (!startWebClient()); 
}

void loop()
{
  unsigned long runTime;
  bool connectStatus;

  // Check the client connection status. It should be 0 (not connected, i.e. socket = -1).  However, there could be a residual 
  // socket value if the GSM and GPRS have been restarted due to a AT+USOCO=... command hang. Issue a client.stop() to close
  // the socket and reset the _socket variable to -1 in the GSMClient. The AT+USOCL= command issued to the modem will end in
  // ERRROR because the socket is no longer valid due to the modem restart.
  //
  // This check also forces a call to the MODEM poll() method which removes URCs from the UART interface
  // between the SAMD microcontroller and the ublox SARA U201 modem. It seems like a good idea to remove URCs
  // in a timely manner, although it didn't reduce hang conditions on the SARA U201 interface. 
  connectStatus = client.connected();
  if (connectStatus)
  {
    Serial.print("Unexpected client connect status: ");
    Serial.println(connectStatus);
    client.stop();
  }

  // Run Time is the number milliseconds since the MKR board began running the current program instance.
  runTime = millis();

  // Protect against run time wrap which occurs after approximately 50 days.
  if (runTime < lastConnectTime)
  {
    lastConnectTime = runTime;
  }

  // Connect to the web server and send a message if the connect time threshold has been reached
  if ((runTime - lastConnectTime) >= CONNECT_INTERNAL_10_MINUTES)
  {
     sendTestMessage = true;
  }

  // Check if it is time to send a message to the Hologram server
  if (sendTestMessage || restartClient)
  {
    // We should not be connected.
    if (!clientConnected)
    {
      Serial.println("connecting...");

      // If able to connect to Hologram server. 
      if (connectClient())
      {
        Serial.println("connected");
        clientConnected = true;

        // Send message to Hologram iot server
        sendMessageToHologram();

        // If the Hologram web server fails to respond and/or close restart the client.
        if (!checkForResponseFromHologram())
        {
          // Restart Web client
          Serial.println("Response/Close NOT received");
          do
          {
            Serial.println("Restarting Web client");
          } while (!startWebClient());
        }     
      } else {
        // Restart Web client
        Serial.println("Connection failed");
        do
        {
          Serial.println("Restarting Web client");
        } while (!startWebClient());
      }
    } else {
      Serial.println("Client unexpectedly still connected");
    }
  }
}

// Initialize GSM and GPRS
bool startWebClient()
{
  int  gsmBeginStatus;
  int  gprsAttachStatus;
  int  startWebClientInitializationCount = 0;
  int  gsmReadyStatus = 0;

  Serial.println("startWebClient");

  // Initialize the GSM with a modem restart and asynchronous operation mode.
  // I modified the MODEM instance in the MKRGSM 1400 library to initialize with a baud rate of 115200.
  gsmBeginStatus = gsmAccess.begin(PINNUMBER, true, false);
  if (gsmBeginStatus == 0)
  {
    // Modem has been restarted. Delay for 2 seconds and loop while GSM component initializes and registers with network
    delay(2000);

    // March thru the GSM state machine one AT command at a time using the ready() method.
    // This allows us to detect a hang condition on the SARA U201 UART interface
    do
    {
      gsmReadyStatus = gsmAccess.ready();
      startWebClientInitializationCount++;
      delay(100);       
    } while ((gsmReadyStatus == 0) && (startWebClientInitializationCount < 600));

    // If the GSM registered with the network attach to the GPRS network with the APN, login and password
    if (gsmReadyStatus == 1)
    {
      Serial.print("GSM registered successfully after ");
      Serial.print(startWebClientInitializationCount * 100);
      Serial.println(" ms");

      // Perform an asynchronous attach to the GPRS network.  That way we can prevent a GPRS hang in the MKRGSM1400 library
      gprs.attachGPRS(GPRS_APN, GPRS_LOGIN, GPRS_PASSWORD, false);
      do 
      {
        delay(100);
        startWebClientInitializationCount++;
        gprsAttachStatus = gprs.ready();
      } while ((gprsAttachStatus == 0) && (startWebClientInitializationCount < 600));

      if (gprsAttachStatus == 1)
      {
        gprsAttachStatus = gprs.status();
        if (gprsAttachStatus == GPRS_READY)
        {
          Serial.println("Attached to APN");
          restartClient = true;
          return true;
        } else {
          Serial.print("GPRS status: ");
          Serial.println(gprsAttachStatus);
          return false;
        }
      } else if (gprsAttachStatus == 0) {      
        Serial.println();
        Serial.print("GPRS Attach timed OUT after ");
        Serial.print(startWebClientInitializationCount * 100);
        Serial.println(" ms");
        return false;
      } else {
        // Print gprsAttachStatus as ASCII encoded hex because occasionally we get garbage return characters when the network is in turmoil.
        // It appears the _ready variable in the MODEM Class instance is being overwritten with garbage.
        Serial.print("GPRS Attach status: ");
        Serial.println(gprsAttachStatus, HEX);
        return false;
      }
    } else if (gsmReadyStatus == 0) {
      Serial.print("GSM Ready status timed OUT after ");
      Serial.print(startWebClientInitializationCount * 100);
      Serial.println(" ms");
      return false;
    } else {
      // Print gsmReadyStatus as ASCII encoded hex because occasionally we get garbage return characters when the network is in turmoil.
      Serial.print("GSM Ready status: ");
      Serial.println(gsmReadyStatus, HEX);
      return false;
    }
  } else {
    Serial.print("GSM Begin status: ");
    Serial.println(gsmBeginStatus);
    return false;
  }
}

// Connect to the APN
bool connectClient()
{
  int connectStatus;
  int loopCount;

  connectStatus = client.connect(server, port);
  if (connectStatus == 0)
  {
    // The GSMClient has an AT command outstanding to the MODEM.  This is an unexpected condition.
    // Return false to cause a MODEM restart and GSM and GPRS initialization.
    Serial.println("GSMClient unexpected AT command outstanding");
    return false;
  }

  // Stay in a while loop and wait for connection to complete or 60 second timeout
  loopCount = 0;
  while (loopCount < 600)
  {
    connectStatus = client.ready();

    // If command in progress delay 100 ms, increment count and check again
    if (connectStatus == 0) {
      loopCount++;
      delay(100);
    } else if (connectStatus == 1) {
      // AT Command has completed. Return codes:
      //                           1 - success
      //                           2 - error
      //                           3 - no carrier
      Serial.print("Connect after ");
      Serial.print(loopCount * 100);
      Serial.println(" ms");
      return true;
    } else {
      Serial.print("Connect failed: ");
      Serial.println(connectStatus);
      return false;
    }
  }

  // Connection timed out.
  Serial.println();
  Serial.print("Connection Timed OUT loopCount = ");
  Serial.println(loopCount);
  return false;
}

// Send test message to Hologram web server
void sendMessageToHologram()
{

  // Send Test Message using Hologram's embedded API.
  client.println("{\"k\":\"" + HOLOGRAM_API_KEY +"\",\"d\":\""+ MESSAGE_TEST + "\",\"t\":\""+TOPIC+"\"}");

  // Clear restart and send test message flags
  restartClient = false;
  sendTestMessage = false;
}

// Hologram web server should respond with an ASCII string of "[n,0]" where n is one of the following
// return codes:
//        0 – Send successful, no error
//        1 – Connection was closed so we couldn’t read enough
//        2 – Couldn’t parse the message
//        3 – Auth section of message was invalid
//        4 – Payload type was invalid
//        5 – Protocol type was invalid
//        6 – An internal error occurred
//        7 – Metadata section of message was formatted incorrectly
//        8 – Topic contained invalid characters or was too long
//
//  After returning the response code the Hologram server will close the connection
//
//  Return true if response and/or close received from Hologram server.
//  Otherwise, return false so the modem and client can be restarted.
bool checkForResponseFromHologram()
{
  int loopCount = 0;
  boolean bNextCharIsResponseCode = false;

  // Use a do while loop to restrict the amount of time we wait for a response and/or close from the Hologram server
  do
  {
    // If the server's disconnected AND there is no more server response data available,
    // stop the client and break out of the for loop
    if (!client.connected() && !client.available())
    {
      Serial.println();
      Serial.println("disconnecting.");
      client.stop();
      clientConnected = false;
      return true;
    }

    // If there are incoming bytes available from the server,
    // read them and print them.
    while (client.available()) 
    {
      char c = client.read();
      Serial.print(c);
      if (bNextCharIsResponseCode)
      {
        if ((c >= '0') && (c <= '8'))
        {
          Serial.println(HOLOGRAM_RESPONSE_ARRAY[c - '0']);
        } else 
        {
          Serial.print("Unrecognized Response: ");
          Serial.println(c);
        }

        bNextCharIsResponseCode = false;
      } else if (c == '[')
      {
        bNextCharIsResponseCode = true;
      }
    }

    loopCount++;
    delay(100);
  } while (loopCount < 600);

  // Did not receive response and/or close from Hologram server.  Return false so modem and client can be restarted.
  Serial.println();
  Serial.println("No response/close from Hologram.");
  client.stop();
  clientConnected = false;
  return false;
}
Rocketct commented 6 years ago

Hi @Nels52 i had test the sketch, actually i never get the error and the GSM work properly, how is going your test? in this days was released a new version of the Library (1.3.0) could you test with this one and let us know the results?

Nels52 commented 6 years ago

Hi @Rocketct. I have figured out a way to recreate the issue:

  1. Use the script above with GSM, GPRS, and GSMClient instances operating in asynchronous mode.
  2. Run the script and let it send one message successfully. Make sure that the server you are using disconnects after it sends a response just like Hologram does.
  3. Before the next message is sent to the server disconnect the antenna.
  4. Watch the connection sequence fail as shown in the trace below.
  5. Reconnect the antenna and watch GSM and GPRS initialize successfully.
  6. The GSMClient connect sequence will return errors because the GSMClient state was left in a residual state from the failed connection attempt when the antenna was disconnected.

Here is an annotated trace with my recreation of the issue:


// Here is an example of a good send sequence to the Hologram server. Note that after the // Hologram server sends a response it disconnects.


13:51:55.370 -> connecting... AT+USOCR=6

13:51:55.474 -> +USOCR: 0 13:51:55.474 -> 13:51:55.474 -> OK AT+USOCO=0,"cloudsocket.hologram.io",9999

13:51:58.903 -> OK 13:51:58.903 -> Connect after 3500 ms 13:51:58.903 -> connected 13:51:58.903 -> Report Temperature: 68 F 13:51:58.903 -> AT+USOWR=0,45,"7B226B223A22536339425E5D2E70222C2264223A2236382046222C2274223A2254454D5045524154555245227D"

13:51:58.903 -> +USOWR: 0,45 13:51:58.903 -> 13:51:58.903 -> OK 13:51:58.903 -> AT+USOWR=0,2,"0D0A"

13:51:58.903 -> +USOWR: 0,2 13:51:58.903 -> 13:51:58.903 -> OK 13:52:00.015 -> +UUSORD: 0,5 13:52:00.015 -> AT+USORD=0,1

13:52:00.015 -> +USORD: 0,1,"5B" 13:52:00.015 -> 13:52:00.015 -> OK 13:52:00.015 -> [ 13:52:00.116 -> +UUSORD: 0,4 13:52:00.116 -> AT+USORD=0,1

13:52:00.116 -> +USORD: 0,1,"30" 13:52:00.116 -> 13:52:00.116 -> OK 13:52:00.116 -> 0Send successful, no error 13:52:00.116 -> 13:52:00.116 -> +UUSORD: 0,3 13:52:00.217 -> AT+USORD=0,1

13:52:00.217 -> +USORD: 0,1,"2C" 13:52:00.253 -> 13:52:00.253 -> OK 13:52:00.253 -> , 13:52:00.336 -> +UUSORD: 0,2 13:52:00.336 -> AT+USORD=0,1

13:52:00.336 -> +USORD: 0,1,"30" 13:52:00.336 -> 13:52:00.336 -> OK 13:52:00.336 -> 0 13:52:00.436 -> +UUSORD: 0,1 13:52:00.436 -> AT+USORD=0,1

13:52:00.436 -> +USORD: 0,1,"5D" 13:52:00.436 -> 13:52:00.436 -> OK 13:52:00.436 -> ] 13:52:00.748 -> +UUSOCL: 0 13:52:00.748 -> 13:52:00.748 -> disconnecting.


// At this point disconnect the antenna. This will cause the next connection attempt to the Hologram // server to fail. In the case shown below the AT+USOCO=... command hangs and the GSMClient is // now stuck in the CLIENT_STATE_WAIT_CONNECT_RESPONSE state. // The script uses the asynchronous mode operation for my GSM, GPRS, and GSMClient instances. // The script sits in a loop invoking the GSMClient ready() method to check the status every 100 ms. // The loop "times out" after 600 iterations and restarts GSM with the begin() method and GPRS with // attachGPRS() after GSM begin() is successful.


14:41:54.029 -> connecting... AT+USOCR=6

14:41:54.129 -> +USOCR: 0 14:41:54.129 -> 14:41:54.129 -> OK AT+USOCO=0,"cloudsocket.hologram.io",9999

14:42:54.046 -> Connection Timed OUT loopCount = 600 14:42:54.046 -> Connection failed


// The scripts restarts GSM with begin() here. You will see AT+CREG command returns without // establishing a connection to the network because the antenna is still disconnected.


14:42:54.046 -> Restarting Web client 14:42:54.046 -> startWebClient HomeMonitorV3 Build 10-10-2018 AT

14:42:58.060 -> OK 14:42:58.060 -> AT+UPSV=3

14:42:58.060 -> OK AT+CPIN?

14:43:00.180 -> +CPIN: READY 14:43:00.180 -> 14:43:00.180 -> OK AT+CMGF=1

14:43:00.351 -> OK AT+UDCONF=1,1

14:43:00.567 -> OK AT+CTZU=1

14:43:00.775 -> OK 14:43:00.878 -> +UMWI: 0,1 14:43:00.878 -> 14:43:00.878 -> +UMWI: 0,2 14:43:00.878 -> 14:43:00.878 -> +UMWI: 0,3 14:43:00.878 -> 14:43:00.878 -> +UMWI: 0,4 AT+UDTMFD=1,2

14:43:00.979 -> OK AT+CREG?

14:43:01.187 -> +CREG: 0,0 14:43:01.187 -> 14:43:01.187 -> OK AT+CREG?

14:43:01.360 -> +CREG: 0,0 14:43:01.360 -> 14:43:01.360 -> OK AT+CREG?

14:43:01.566 -> +CREG: 0,0 14:43:01.566 -> 14:43:01.566 -> OK AT+CREG?

14:43:01.776 -> +CREG: 0,0 14:43:01.776 -> 14:43:01.776 -> OK


// The script reinvokes GSM begin() after 600 iterations of GSM ready() calls if we don't connect to the // network. This continues until GSM begin() is successful.


GSM Ready status timed OUT after 60000 ms 14:44:00.342 -> Restarting Web client 14:44:00.342 -> startWebClient HomeMonitorV3 Build 10-10-2018 AT

14:44:04.376 -> OK 14:44:04.376 -> AT+UPSV=3

14:44:04.376 -> OK AT+CPIN?

14:44:06.492 -> +CPIN: READY 14:44:06.492 -> 14:44:06.492 -> OK AT+CMGF=1

14:44:06.701 -> OK AT+UDCONF=1,1

14:44:06.876 -> OK AT+CTZU=1

14:44:07.083 -> OK

14:44:07.187 -> +UMWI: 0,1 14:44:07.187 -> 14:44:07.187 -> +UMWI: 0,2 4:44:07.187 -> 14:44:07.187 -> +UMWI: 0,3 14:44:07.187 -> 14:44:07.187 -> +UMWI: 0,4 AT+UDTMFD=1,2

14:44:07.292 -> OK AT+CREG?

14:44:07.501 -> +CREG: 0,0 14:44:07.501 -> 14:44:07.501 -> OK AT+CREG?

14:44:07.676 -> +CREG: 0,0 14:44:07.676 -> 14:44:07.676 -> OK AT+CREG?

14:44:07.884 -> +CREG: 0,0 14:44:07.884 -> 14:44:07.884 -> OK


// Reconnect the antenna so that GSM begin() can succeed.


14:46:48.181 -> Restarting Web client 14:46:48.181 -> startWebClient HomeMonitorV3 Build 10-10-2018 AT

14:46:52.200 -> OK 14:46:52.200 -> AT+UPSV=3

14:46:52.200 -> OK AT+CPIN?

14:46:54.318 -> +CPIN: READY 14:46:54.318 -> 14:46:54.318 -> OK AT+CMGF=1

14:46:54.490 -> OK AT+UDCONF=1,1

14:46:54.700 -> OK AT+CTZU=1

14:46:54.905 -> OK 14:46:55.009 -> +UMWI: 0,1 14:46:55.009 -> 14:46:55.009 -> +UMWI: 0,2 14:46:55.009 -> 14:46:55.009 -> +UMWI: 0,3 14:46:55.009 -> 14:46:55.009 -> +UMWI: 0,4 AT+UDTMFD=1,2

14:46:55.114 -> OK AT+CREG?

14:46:55.321 -> +CREG: 0,0 14:46:55.321 -> 14:46:55.321 -> OK AT+CREG?

14:46:55.529 -> +CREG: 0,0 14:46:55.529 -> 14:46:55.529 -> OK AT+CREG?

14:46:55.701 -> +CREG: 0,0 14:46:55.701 -> 14:46:55.701 -> OK AT+CREG?

14:46:55.909 -> +CREG: 0,0 14:46:55.909 -> 14:46:55.909 -> OK AT+CREG?

14:46:56.118 -> +CREG: 0,0 14:46:56.118 -> 14:46:56.118 -> OK AT+CREG?

14:46:56.326 -> +CREG: 0,0 14:46:56.326 -> 14:46:56.326 -> OK AT+CREG?

14:46:56.500 -> +CREG: 0,0 14:46:56.533 -> 14:46:56.533 -> OK AT+CREG?

14:46:56.707 -> +CREG: 0,0 14:46:56.707 -> 14:46:56.707 -> OK AT+CREG?

14:46:56.913 -> +CREG: 0,0 14:46:56.913 -> 14:46:56.913 -> OK AT+CREG?

14:46:57.121 -> +CREG: 0,0 14:46:57.121 -> 14:46:57.121 -> OK AT+CREG?

14:46:57.326 -> +CREG: 0,0 14:46:57.326 -> 14:46:57.326 -> OK AT+CREG?

14:46:57.533 -> +CREG: 0,0 14:46:57.533 -> 14:46:57.533 -> OK AT+CREG?

14:46:57.706 -> +CREG: 0,0 14:46:57.706 -> 14:46:57.706 -> OK AT+CREG?

14:46:57.914 -> +CREG: 0,0 14:46:57.914 -> 14:46:57.914 -> OK AT+CREG?

14:46:58.124 -> +CREG: 0,0 14:46:58.124 -> 14:46:58.124 -> OK AT+CREG?

14:46:58.332 -> +CREG: 0,0 14:46:58.332 -> 14:46:58.332 -> OK AT+CREG?

14:46:58.539 -> +CREG: 0,0 14:46:58.539 -> 14:46:58.539 -> OK AT+CREG?

14:46:58.712 -> +CREG: 0,0 14:46:58.712 -> 14:46:58.712 -> OK AT+CREG?

14:46:58.919 -> +CREG: 0,5 14:46:58.919 -> 14:46:58.919 -> OK AT+UCALLSTAT=1

14:46:59.127 -> OK GSM registered successfully after 5000 ms AT+CGATT=1

14:46:59.334 -> OK AT+UPSD=0,1,"hologram"

14:46:59.540 -> OK AT+UPSD=0,6,3

14:46:59.746 -> OK AT+UPSD=0,2," "

14:46:59.921 -> OK AT+UPSD=0,3," "

14:47:00.131 -> OK AT+UPSD=0,7,"0.0.0.0"

14:47:00.338 -> OK AT+UPSDA=0,3

14:47:03.456 -> OK AT+UPSND=0,8

14:47:03.631 -> +UPSND: 0,8,1 14:47:03.631 -> 14:47:03.631 -> OK 14:47:03.631 -> Attached to APN 14:47:03.631 -> Unexpected client connect status: 1


// At this point you will see a slightly different error sequence because your GSMClient will still be in the // CLIENT_STATE_WAIT_CONNECT_RESPONSE state. My special version of the library has the changes // in the GSMClient connect() method that I described in the original issue description at the top of this // thread.


14:47:03.631 -> AT+USOCL=0

14:47:03.666 -> ERROR 14:47:03.666 -> connecting... AT+USOCR=6

14:47:03.735 -> +USOCR: 0 14:47:03.735 -> OK AT+USOCO=0,"cloudsocket.hologram.io",9999

14:47:04.948 -> OK 14:47:04.948 -> Connect after 1300 ms 14:47:04.948 -> connected 14:47:04.948 -> Report Temperature: 70 F AT+USOWR=0,41,"7B226B223A22536339425E5D2E70222C2264223A2237302046222C2274223A2252455354415254227D"

14:47:04.983 -> +USOWR: 0,41 14:47:04.983 -> 14:47:04.983 -> OK 14:47:04.983 -> AT+USOWR=0,2,"0D0A"

14:47:04.983 -> +USOWR: 0,2 14:47:04.983 -> 14:47:04.983 -> OK 14:47:05.777 -> +UUSORD: 0,5 14:47:05.777 -> AT+USORD=0,1

14:47:05.777 -> +USORD: 0,1,"5B" 14:47:05.777 -> 14:47:05.777 -> OK 14:47:05.777 -> [ 14:47:05.882 -> +UUSORD: 0,4 14:47:05.882 -> AT+USORD=0,1

14:47:05.882 -> +USORD: 0,1,"30" 14:47:05.882 -> 14:47:05.882 -> OK 14:47:05.882 -> 0Send successful, no error 14:47:05.882 -> 14:47:05.882 -> +UUSORD: 0,3 14:47:05.986 -> AT+USORD=0,1

14:47:05.986 -> +USORD: 0,1,"2C" 14:47:05.986 -> 14:47:05.986 -> OK 14:47:05.986 -> , 14:47:06.089 -> +UUSORD: 0,2 14:47:06.089 -> AT+USORD=0,1

14:47:06.089 -> +USORD: 0,1,"30" 14:47:06.124 -> 14:47:06.124 -> OK 14:47:06.124 -> 0 14:47:06.193 -> +UUSORD: 0,1 AT+USORD=0,1

14:47:06.228 -> +USORD: 0,1,"5D" 14:47:06.228 -> 14:47:06.228 -> OK 14:47:06.228 -> ] 14:47:06.503 -> +UUSOCL: 0 14:47:06.503 -> 14:47:06.503 -> disconnecting.

Let me know if you have any questions. Regards.

Rocketct commented 6 years ago

@Nels52 which version of the library are you using? ok i'll try to reproduce the issue using your suggestions, question are you able to print the _state and _socket value in the GSMClient.cpp?

Nels52 commented 6 years ago

Hi @Rocketct. I am using the 1.2.1 version of the library with the modification to the GSMClient connect() method described in the first entry of this thread.

Also, I didn't modify the library to print the GSMClient _state variable, however, from the GSMClient code I just figure that if the AT+USOCR=6 hangs the GSMClient state machine is stuck in the CLIENT_STATE_WAIT_CREATE_SOCKET_RESPONSE state. Similarly, if the AT+USOCO=... command hangs the GSMClient is stuck in the CLIENT_STATE_WAIT_CONNECT_RESPONSE state.

The _socket value is also residual and meaningless after the GSM begin() and GPRS attachGPRS() methods have executed because the modem has been reset which cleans up all socket connections. In the trace above you will see at 14:47:03.631 where my script issued a GSMClient stop() with the residual _socket value that was no longer valid due to the GSM begin(). This results in a ERROR return because the _socket value is no longer valid. However, the stop() method at least resets the _socket value to -1 and the ERROR return from AT+USOCL=0 command is harmless.

My basic issue is that I had to make the modification to the GSMClient connect() method because I couldn't see any other way to reset the GSMClient state machine after resetting the modem with a GSM begin(). There may be a better way of resetting the GSMClient state machine, for example, the GSMClient stop() method, however, I just found it was easier with the GSMClient connect() method since it has to be invoked whenever sending a message to the server.

Hope this helps.

Rocketct commented 6 years ago

Hi @Nels52, yes i understand the error, however i suggest you to update to the 1.3.0 where was implemented many important change that could resolve the problem, could you try this one and let me know if the state of state machine of the client follow to be not updated?

Nels52 commented 6 years ago

Hi @Rocketct. I will download the latest library and give it a try. It looks like it has a method to retrieve the current client state so I will incorporate that in my script. Regards

Nels52 commented 6 years ago

Hi @Rocketct I installed MKRGSM library 1.3.0 and reproduced the issue by disconnecting the antenna before my script was preparing to send a message to the server. I seem the same error, i.e. the GSMClient was left in the CLIENT_STATE_WAIT_CONNECT_RESPONSE state after the GSM begin() and GPRS attachGPRS() complete successfully. My script eventually recovers because it reinitializes GSM and GPRS each time an unexpected result is returned from the GSMClient connect() method call and eventually the GSMClient state is driven back to CLIENT_STATE_CREATE_SOCKET.

I inserted a Serial print of the GSMClient state just after the following logic in the GSMClient connect() method:

if (_socket != -1) { stop(); }

Summary of trace events:

Debug trace output.:

`13:21:28.534 -> connecting... 13:21:28.534 -> GSMClient state: 0 AT+USOCR=6

13:21:28.638 -> +USOCR: 0 13:21:28.638 -> 13:21:28.638 -> OK AT+USOCO=0,"cloudsocket.hologram.io",9999

13:22:28.530 -> Connection Timed OUT loopCount = 600 13:22:28.530 -> Connection failed 13:22:28.530 -> Restarting Web client 13:22:28.530 -> startWebClient HomeMonitorV4 Build 10-26-2018 AT

13:22:32.689 -> OK 13:22:32.689 -> AT+UPSV=3

13:22:32.689 -> OK AT+CPIN?

13:22:34.799 -> +CPIN: READY 13:22:34.799 -> 13:22:34.799 -> OK AT+CMGF=1

13:22:35.009 -> OK AT+UDCONF=1,1

13:22:35.215 -> OK AT+CTZU=1

13:22:35.421 -> OK

13:22:35.491 -> +UMWI: 0,1 13:22:35.491 -> 13:22:35.491 -> +UMWI: 0,2 13:22:35.491 -> 13:22:35.491 -> +UMWI: 0,3 13:22:35.491 -> 13:22:35.491 -> +UMWI: 0,4 AT+UDTMFD=1,2

13:22:35.629 -> OK AT+CREG?

13:22:35.835 -> +CREG: 0,0 13:22:35.835 -> 13:22:35.835 -> OK AT+CREG?

13:22:36.042 -> +CREG: 0,0 13:22:36.042 -> 13:22:36.042 -> OK AT+CREG?

13:22:36.215 -> +CREG: 0,0 13:22:36.215 -> 13:22:36.215 -> OK AT+CREG?

13:22:36.424 -> +CREG: 0,0 13:22:36.424 -> 13:22:36.424 -> OK AT+CREG?

13:22:36.629 -> +CREG: 0,0 13:22:36.629 -> 13:22:36.629 -> OK AT+CREG?

13:22:36.837 -> +CREG: 0,0 13:22:36.837 -> 13:22:36.837 -> OK AT+CREG?

13:22:37.045 -> +CREG: 0,0 13:22:37.045 -> 13:22:37.045 -> OK AT+CREG?

13:22:37.219 -> +CREG: 0,0 13:22:37.219 -> 13:22:37.219 -> OK AT+CREG?

13:22:37.427 -> +CREG: 0,0 13:22:37.427 -> 13:22:37.427 -> OK AT+CREG?

13:22:37.632 -> +CREG: 0,0 13:22:37.632 -> 13:22:37.632 -> OK AT+CREG?

13:22:37.842 -> +CREG: 0,0 13:22:37.842 -> 13:22:37.842 -> OK AT+CREG?

13:22:38.050 -> +CREG: 0,0 13:22:38.050 -> 13:22:38.050 -> OK AT+CREG?

13:22:38.224 -> +CREG: 0,0 13:22:38.224 -> 13:22:38.224 -> OK AT+CREG?

13:22:38.430 -> +CREG: 0,0 13:22:38.430 -> 13:22:38.430 -> OK AT+CREG?

13:22:38.637 -> +CREG: 0,0 13:22:38.637 -> 13:22:38.637 -> OK AT+CREG?

13:22:38.845 -> +CREG: 0,0 13:22:38.845 -> 13:22:38.845 -> OK AT+CREG?

13:22:39.054 -> +CREG: 0,0 13:22:39.054 -> 13:22:39.054 -> OK AT+CREG?

13:22:39.261 -> +CREG: 0,0 13:22:39.261 -> 13:22:39.261 -> OK AT+CREG?

13:22:39.433 -> +CREG: 0,0 13:22:39.433 -> 13:22:39.433 -> OK AT+CREG?

13:22:39.640 -> +CREG: 0,0 13:22:39.640 -> 13:22:39.640 -> OK AT+CREG?

13:22:39.848 -> +CREG: 0,0 13:22:39.848 -> 13:22:39.848 -> OK AT+CREG?

13:22:40.053 -> +CREG: 0,0 13:22:40.053 -> 13:22:40.053 -> OK AT+CREG?

13:22:40.262 -> +CREG: 0,0 13:22:40.262 -> 13:22:40.262 -> OK AT+CREG?

13:22:40.436 -> +CREG: 0,0 13:22:40.436 -> 13:22:40.436 -> OK AT+CREG?

13:22:40.644 -> +CREG: 0,0 13:22:40.644 -> 13:22:40.644 -> OK AT+CREG?

13:22:40.854 -> +CREG: 0,0 13:22:40.854 -> 13:22:40.854 -> OK AT+CREG?

13:22:41.061 -> +CREG: 0,0 13:22:41.061 -> 13:22:41.061 -> OK AT+CREG?

13:22:41.269 -> +CREG: 0,0 13:22:41.269 -> 13:22:41.269 -> OK AT+CREG?

13:22:41.444 -> +CREG: 0,0 13:22:41.444 -> 13:22:41.444 -> OK AT+CREG?

13:22:41.651 -> +CREG: 0,0 13:22:41.651 -> 13:22:41.651 -> OK AT+CREG?

13:22:41.858 -> +CREG: 0,5 13:22:41.858 -> 13:22:41.858 -> OK AT+UCALLSTAT=1

13:22:42.065 -> OK GSM registered successfully after 7400 ms AT+CGATT=1

13:22:42.273 -> OK AT+UPSD=0,1,"hologram"

13:22:42.480 -> OK AT+UPSD=0,6,3

13:22:42.652 -> OK AT+UPSD=0,2," "

13:22:42.861 -> OK AT+UPSD=0,3," "

13:22:43.069 -> OK AT+UPSD=0,7,"0.0.0.0"

13:22:43.278 -> OK AT+UPSDA=0,3

13:22:46.371 -> OK AT+UPSND=0,8

13:22:46.578 -> +UPSND: 0,8,1 13:22:46.578 -> 13:22:46.578 -> OK 13:22:46.578 -> Attached to APN AT+USORD=0,512

13:22:46.612 -> ERROR 13:22:46.612 -> AT+USOCL=0

13:22:46.612 -> ERROR 13:22:46.612 -> connecting... 13:22:46.612 -> GSMClient state: 8 13:22:46.612 -> GSMClient unexpected AT command outstanding 13:22:46.612 -> Connection failed 13:22:46.612 -> Restarting Web client 13:22:46.612 -> startWebClient HomeMonitorV4 Build 10-26-2018 AT

13:22:50.796 -> OK 13:22:50.796 -> AT+UPSV=3

13:22:50.796 -> OK AT+CPIN?

13:22:52.909 -> +CPIN: READY 13:22:52.909 -> 13:22:52.909 -> OK AT+CMGF=1

13:22:53.112 -> OK AT+UDCONF=1,1

13:22:53.321 -> OK AT+CTZU=1

13:22:53.496 -> OK

13:22:53.604 -> +UMWI: 0,1 13:22:53.604 -> 13:22:53.604 -> +UMWI: 0,2 13:22:53.604 -> 13:22:53.604 -> +UMWI: 0,3 13:22:53.604 -> 13:22:53.604 -> +UMWI: 0,4 AT+UDTMFD=1,2

13:22:53.741 -> OK AT+CREG?

13:22:53.950 -> +CREG: 0,0 13:22:53.950 -> 13:22:53.950 -> OK AT+CREG?

13:22:54.123 -> +CREG: 0,0 13:22:54.123 -> 13:22:54.123 -> OK AT+CREG?

13:22:54.332 -> +CREG: 0,0 13:22:54.332 -> 13:22:54.332 -> OK AT+CREG?

13:22:54.538 -> +CREG: 0,0 13:22:54.538 -> 13:22:54.538 -> OK AT+CREG?

13:22:54.745 -> +CREG: 0,0 13:22:54.745 -> 13:22:54.745 -> OK AT+CREG?

13:22:54.954 -> +CREG: 0,0 13:22:54.954 -> 13:22:54.954 -> OK AT+CREG?

13:22:55.126 -> +CREG: 0,0 13:22:55.126 -> 13:22:55.126 -> OK AT+CREG?

13:22:55.334 -> +CREG: 0,0 13:22:55.334 -> 13:22:55.334 -> OK AT+CREG?

13:22:55.541 -> +CREG: 0,0 13:22:55.541 -> 13:22:55.541 -> OK AT+CREG?

13:22:55.748 -> +CREG: 0,0 13:22:55.748 -> 13:22:55.748 -> OK AT+CREG?

13:22:55.957 -> +CREG: 0,0 13:22:55.957 -> 13:22:55.957 -> OK AT+CREG?

13:22:56.128 -> +CREG: 0,0 13:22:56.128 -> 13:22:56.128 -> OK AT+CREG?

13:22:56.337 -> +CREG: 0,0 13:22:56.337 -> 13:22:56.337 -> OK AT+CREG?

13:22:56.546 -> +CREG: 0,0 13:22:56.546 -> 13:22:56.546 -> OK AT+CREG?

13:22:56.753 -> +CREG: 0,0 13:22:56.753 -> 13:22:56.753 -> OK AT+CREG?

13:22:56.962 -> +CREG: 0,0 13:22:56.962 -> 13:22:56.962 -> OK AT+CREG?

13:22:57.136 -> +CREG: 0,0 13:22:57.136 -> 13:22:57.136 -> OK AT+CREG?

13:22:57.344 -> +CREG: 0,0 13:22:57.344 -> 13:22:57.344 -> OK AT+CREG?

13:22:57.553 -> +CREG: 0,0 13:22:57.553 -> 13:22:57.553 -> OK AT+CREG?

13:22:57.761 -> +CREG: 0,0 13:22:57.761 -> 13:22:57.761 -> OK AT+CREG?

13:22:57.968 -> +CREG: 0,5 13:22:57.968 -> 13:22:57.968 -> OK AT+UCALLSTAT=1

13:22:58.142 -> OK GSM registered successfully after 5400 ms AT+CGATT=1

13:22:58.350 -> OK AT+UPSD=0,1,"hologram"

13:22:58.559 -> OK AT+UPSD=0,6,3

13:22:58.768 -> OK AT+UPSD=0,2," "

13:22:58.976 -> OK AT+UPSD=0,3," "

13:22:59.148 -> OK AT+UPSD=0,7,"0.0.0.0"

13:22:59.357 -> OK AT+UPSDA=0,3

13:23:02.557 -> OK AT+UPSND=0,8

13:23:02.765 -> +UPSND: 0,8,1 13:23:02.765 -> 13:23:02.765 -> OK 13:23:02.765 -> Attached to APN 13:23:02.765 -> connecting... 13:23:02.765 -> GSMClient state: 9 GSMClient unexpected AT command outstanding 13:23:02.799 -> Connection failed 13:23:02.799 -> Restarting Web client 13:23:02.799 -> startWebClient HomeMonitorV4 Build 10-26-2018 AT

13:23:06.946 -> OK AT+UPSV=3

13:23:06.980 -> OK AT+CPIN?

13:23:09.063 -> +CPIN: READY 13:23:09.063 -> 13:23:09.063 -> OK AT+CMGF=1

13:23:09.267 -> OK AT+UDCONF=1,1

13:23:09.475 -> OK AT+CTZU=1

13:23:09.683 -> OK

13:23:09.786 -> +UMWI: 0,1 13:23:09.786 -> 13:23:09.786 -> +UMWI: 0,2 13:23:09.786 -> 13:23:09.786 -> +UMWI: 0,3 13:23:09.786 -> 13:23:09.786 -> +UMWI: 0,4 AT+UDTMFD=1,2

13:23:09.890 -> OK AT+CREG?

13:23:10.100 -> +CREG: 0,0 13:23:10.100 -> 13:23:10.100 -> OK AT+CREG?

13:23:10.308 -> +CREG: 0,0 13:23:10.308 -> 13:23:10.308 -> OK AT+CREG?

13:23:10.483 -> +CREG: 0,0 13:23:10.483 -> 13:23:10.483 -> OK AT+CREG?

13:23:10.689 -> +CREG: 0,0 13:23:10.689 -> 13:23:10.689 -> OK AT+CREG?

13:23:10.897 -> +CREG: 0,0 13:23:10.897 -> 13:23:10.897 -> OK AT+CREG?

13:23:11.106 -> +CREG: 0,0 13:23:11.106 -> 13:23:11.106 -> OK AT+CREG?

13:23:11.314 -> +CREG: 0,0 13:23:11.314 -> 13:23:11.314 -> OK AT+CREG?

13:23:11.488 -> +CREG: 0,0 13:23:11.488 -> 13:23:11.488 -> OK AT+CREG?

13:23:11.696 -> +CREG: 0,0 13:23:11.696 -> 13:23:11.696 -> OK AT+CREG?

13:23:11.903 -> +CREG: 0,0 13:23:11.903 -> 13:23:11.903 -> OK AT+CREG?

13:23:12.110 -> +CREG: 0,0 13:23:12.110 -> 13:23:12.110 -> OK AT+CREG?

13:23:12.316 -> +CREG: 0,0 13:23:12.316 -> 13:23:12.316 -> OK AT+CREG?

13:23:12.492 -> +CREG: 0,0 13:23:12.492 -> 13:23:12.492 -> OK AT+CREG?

13:23:12.700 -> +CREG: 0,0 13:23:12.700 -> 13:23:12.700 -> OK AT+CREG?

13:23:12.906 -> +CREG: 0,0 13:23:12.906 -> 13:23:12.906 -> OK AT+CREG?

13:23:13.116 -> +CREG: 0,0 13:23:13.116 -> 13:23:13.116 -> OK AT+CREG?

13:23:13.323 -> +CREG: 0,0 13:23:13.323 -> 13:23:13.323 -> OK AT+CREG?

13:23:13.497 -> +CREG: 0,0 13:23:13.497 -> 13:23:13.497 -> OK AT+CREG?

13:23:13.705 -> +CREG: 0,0 13:23:13.705 -> 13:23:13.705 -> OK AT+CREG?

13:23:13.908 -> +CREG: 0,0 13:23:13.908 -> 13:23:13.908 -> OK AT+CREG?

13:23:14.114 -> +CREG: 0,5 13:23:14.114 -> 13:23:14.114 -> OK AT+UCALLSTAT=1

13:23:14.322 -> OK GSM registered successfully after 5400 ms AT+CGATT=1

13:23:14.531 -> OK AT+UPSD=0,1,"hologram"

13:23:14.738 -> OK AT+UPSD=0,6,3

13:23:14.913 -> OK AT+UPSD=0,2," "

13:23:15.120 -> OK AT+UPSD=0,3," "

13:23:15.330 -> OK AT+UPSD=0,7,"0.0.0.0"

13:23:15.539 -> OK AT+UPSDA=0,3

13:23:18.730 -> OK AT+UPSND=0,8

13:23:18.939 -> +UPSND: 0,8,1 13:23:18.939 -> 13:23:18.939 -> OK 13:23:18.939 -> Attached to APN 13:23:18.939 -> connecting... 13:23:18.939 -> GSMClient state: 10 AT+USOCR=6

13:23:19.043 -> +USOCR: 0 13:23:19.043 -> 13:23:19.043 -> OK AT+USOCO=0,"cloudsocket.hologram.io",9999

13:23:20.045 -> OK 13:23:20.045 -> Connect after 1100 ms 13:23:20.045 -> connected 13:23:20.045 -> Report Temperature: 69 F AT+USOWR=0,41,"7B226B223A22536339425E5D2E70222C2264223A2236392046222C2274223A2252455354415254227D"

13:23:20.113 -> +USOWR: 0,41 13:23:20.113 -> 13:23:20.113 -> OK 13:23:20.113 -> AT+USOWR=0,2,"0D0A"

13:23:20.113 -> +USOWR: 0,2 13:23:20.113 -> 13:23:20.113 -> OK AT+USORD=0,512

13:23:20.148 -> +USORD: 0,0,"" 13:23:20.148 -> 13:23:20.148 -> OK AT+USORD=0,512

13:23:20.182 -> +USORD: 0,0,"" 13:23:20.182 -> 13:23:20.182 -> OK AT+USORD=0,512

13:23:20.287 -> +USORD: 0,0,"" 13:23:20.287 -> 13:23:20.287 -> OK 13:23:20.287 -> AT+USORD=0,512

13:23:20.287 -> +USORD: 0,0,"" 13:23:20.320 -> 13:23:20.320 -> OK AT+USORD=0,512

13:23:20.392 -> +USORD: 0,0,"" 13:23:20.425 -> 13:23:20.425 -> OK 13:23:20.425 -> AT+USORD=0,512

13:23:20.425 -> +USORD: 0,0,"" 13:23:20.425 -> 13:23:20.425 -> OK AT+USORD=0,512

13:23:20.531 -> +USORD: 0,0,"" 13:23:20.531 -> 13:23:20.531 -> OK AT+USORD=0,512

13:23:20.565 -> +USORD: 0,0,"" 13:23:20.565 -> 13:23:20.565 -> OK AT+USORD=0,512

13:23:20.667 -> +USORD: 0,0,"" 13:23:20.667 -> 13:23:20.667 -> OK AT+USORD=0,512

13:23:20.701 -> +USORD: 0,0,"" 13:23:20.701 -> 13:23:20.701 -> OK AT+USORD=0,512

13:23:20.805 -> +USORD: 0,0,"" 13:23:20.805 -> 13:23:20.805 -> OK 13:23:20.805 -> AT+USORD=0,512

13:23:20.839 -> +USORD: 0,0,"" 13:23:20.839 -> 13:23:20.839 -> OK AT+USORD=0,512

13:23:20.944 -> +USORD: 0,0,"" 13:23:20.944 -> 13:23:20.944 -> OK 13:23:20.944 -> AT+USORD=0,512

13:23:20.944 -> +USORD: 0,0,"" 13:23:20.944 -> 13:23:20.944 -> OK AT+USORD=0,512

13:23:21.048 -> +USORD: 0,0,"" 13:23:21.048 -> 13:23:21.048 -> OK AT+USORD=0,512

13:23:21.082 -> +USORD: 0,0,"" 13:23:21.082 -> 13:23:21.082 -> OK AT+USORD=0,512

13:23:21.186 -> +USORD: 0,0,"" 13:23:21.186 -> 13:23:21.186 -> OK AT+USORD=0,512

13:23:21.219 -> +USORD: 0,0,"" 13:23:21.219 -> 13:23:21.219 -> OK

13:23:21.324 -> +UUSORD: 0,5 13:23:21.324 -> AT+USORD=0,512

13:23:21.324 -> +USORD: 0,5,"5B302C305D" 13:23:21.324 -> OK 13:23:21.358 -> [0Send successful, no error 13:23:21.358 -> ,0]AT+USORD=0,512

13:23:21.598 -> ERROR

13:23:21.633 -> +UUSOCL: 0 13:23:21.633 -> AT+USOCL=0

13:23:21.633 -> ERROR

13:23:21.737 -> disconnecting. `

Rocketct commented 6 years ago

hi @Nels52 thank you for the reply, at least i have reproduced the issue, then the main problem is the following function:

// Connect to the APN
bool connectClient()
{
  int connectStatus;
  int loopCount;

  connectStatus = client.connect(server, port);
  if (connectStatus == 0)
  {
    // If the GSMClient state machine has a residual state keep driving its state machine until it
    // returns to the CLIENT_STATE_IDLE state.
    if (restartClient)
    { 
      Serial.println("GSMClient state machine out of sync");
      loopCount = 0;
      do
      {
        connectStatus = client.ready();
        loopCount++;
        delay(100);
      } while ((connectStatus == 0) && (loopCount < 100));

      Serial.print("Last Connect status: ");
      Serial.println(connectStatus);

      // If loopCount threshold was reached return failure
      if (loopCount >= 100)
      {
        return false;  
      }
    } else {
      Serial.println("GSMClient state machine out of sync - NO restart pending");
      return false;
    }

    // Call connect again to set GSMClient state to CLIENT_STATE_CREATE_SOCKET
    connectStatus = client.connect(server, port);
    Serial.print("Second Connect status: ");
    Serial.println(connectStatus);
  }

  // Stay in a while loop and wait for connection to complete or 60 second timeout
  loopCount = 0;
  while (loopCount < 600)
  {
    connectStatus = client.ready();

    // If command in progress delay 100 ms, increment count and check again
    if (connectStatus == 0) {
      loopCount++;
      delay(100);
    } else if (connectStatus == 1) {
      // AT Command has completed. Return codes:
      //                           1 - success
      //                           2 - error
      //                           3 - no carrier
      Serial.print("Connect after ");
      Serial.print(loopCount * 100);
      Serial.println(" ms");
      return true;
    } else {
      Serial.print("Connect failed: ");
      Serial.println(connectStatus);
      return false;
    }
  }

  // Connection timed out.
  Serial.println();
  Serial.print("Connection Timed OUT loopCount = ");
  Serial.println(loopCount);
  return false;
}

if the time out occurs nothing is done for reset the _state variable in the GSMClient class, leaving the state machine in an undefined state, one of CLIENT_STATE_WAIT_CONNECT_RESPONSE CLIENT_STATE_CREATE_SOCKET, after the restart as you say, due to the fact that this _state is a class variable, it restart again from this point and will get the error, actually i was able to avoid that the issue happen simply calling a client.stop() after Serial.print("Connection Timed OUT loopCount = "); your solution work because you never check the status of the state machine calling MODEM.ready, however with @sandeepmistry we are working in a elegant way to recognize this situation actually you can find it here https://github.com/sandeepmistry/MKRGSM/tree/connect-async-fail-fix this allow to avoid the unexpected status when the connection API is called.

Nels52 commented 6 years ago

Hi @Rocketct Thanks for looking at this. I looked at the changes to GSMClient::connect() in the MKRGSM/tree referenced above and I will just incorporate them in the 1.3.0 library I am running. They should allow me to navigate the GSMClient state machine in asynchronuous mode using the GSMClient connect() and ready() methods. I agree with the idea of the GSMClient state machine operation (as well as GSM and GPRS state machine operations) being as opaque as possible.

Rocketct commented 6 years ago

Hi @Nels52 at least the easy solution was update the _state in GSMClient::stop() we made a new PR https://github.com/arduino-libraries/MKRGSM/pull/58 and seems that it works could you test it and let me know if ok?

Nels52 commented 6 years ago

Hi @Rocketct Tested with the change to GSMClient::stop() and it worked fine. Makes sense to put change in stop() since that terminates the socket.

Rocketct commented 6 years ago

@Nels52 i have closed the issue in favor of https://github.com/arduino-libraries/MKRGSM/pull/58 let me know if ok?

Nels52 commented 6 years ago

Hi @Rocketct Closing this issue with #58 is fine. In fact, initializing _state in GSMClient::stop() is a better solution.

Nels52 commented 6 years ago

Hi @Rocketct I have run across a situation where the change to GSMClient::stop() fails to address an AT command hang during the connection sequence. Specifically, if the AT+USOCR= hangs while attempting to create a connection the socket is left at -1 and the GSMClient state is left at CLIENT_STATE_WAIT_CREATE_SOCKET_RESPONSE. When stop() is called to clean up the failed connection attempt the state is not reset to CLIENT_STATE_IDLE because the socket is -1. I have moved the _state = CLIENT_STATE_IDLE statement to the top of the stop() method before the socket check and that solves the problem. I don't believe this has any negative impact on the use of the GSMClient::stop() method.

sandeepmistry commented 6 years ago

@Nels52 could you please open a pull request for your suggestion above?

Nels52 commented 6 years ago

Hi @sandeepmistry I am not sure how to open a pull request. Do I fork a branch off the master or do I create a new repository? How do I download the new fork or repository to my computer? Thanks.

sandeepmistry commented 6 years ago

Hi @Nels52,

You need to fork the repo and then clone it using git, and push changes to a new branch. https://help.github.com/articles/creating-a-pull-request-from-a-fork/

If you're not familiar with Github, you can also try to go to the file in Github and click the edit (pencil) icon: https://github.com/arduino-libraries/MKRGSM/blob/master/src/GSMClient.cpp

Nels52 commented 6 years ago

Hi @Rocketct Thanks for your attention to this issue.