WiFi not recovering from wait for available TCP send buffer

[GregTerrell]

While developing a solution based on the Azure IoT Hub I detected a problem where the WIFI driver would appear locked and the WINC activity light would stay on solid. For testing purposes I switch to use the remote_monitorning example project (from Microsoft in the Azure-Samples/iot-hub-c-m0wifi-getstartedkit github repository). For reference, I was using a Adafruit Feather M0 WIFI development board. The issue typically took 5-8 hours of running in order to appear, but occasionally happened shortly after test start.

The issue was initiated by the azure-iot-arduino library’s event send function. When an event is sent to iothub, azure-iot-arduino performs 18 sends to complete sending of the event via http (consisting of the http request, the headers and body [this can be improved, see workaround below] ). After 16 (of the 18) sends, the WINC code hif_send() (in m2m_hif.c) will typically start to loop waiting for a dma_addr != 0. The loop exits on a send callback receipt or 1000 requests for a dma_addr. So effectively this should implement a TCP sliding window of 16 frames. If the hif_send() times out (for-loop 1000 dma_addr requests), the layer above (WiFiClient::write() in WiFiClient.cpp) tries to send again (infinite loop) waiting for a buffer aka dma_addr. I found that once the buffer wait starts, it will require about 160-180 loops to start receiving send callbacks at open buffers for sending. I my test the events where 10 seconds apart, so all 16 send buffers would be available at the next event.

All good, most of the time. But, it seems under some condition (usually hours into the test) the send callback for any of the 16 outstanding TCP sends is never processed, a needed buffer is never freed and consequently the send window is never re-opened. The WINC appears locked up with a solid activity light as the WiFi code endlessly loops waiting for a buffer.

Does this appear to be a WINC firmware\code issue to report to Atmel (if so, how does one report this to Atmel)? The WIFI code at this point is pure Atmel reference based on their Atmel-42420-WINC1500-Software-Design-Guide_UserGuide document.

Workaround (implemented in azure-iot-hub):
Within the azure-iot-hub library (adapter\httpapi_compact.c, SendHeadsToXIO() )… consolidate sending separate TCP sends for each header and the following CRLF into a send of single string containing the header text and the terminating CRLF. This reduces the number of TCP sends for an event posting from 18 to 11 (this could be reduced to 10 with further refactoring). This keeps the WINC from ever hitting the 16 buffer limit. Prior to implementing this workaround, I could never exceed 8 hours of run time before lockup; my test has now been executing for 40 hours.

The workaround above seems to have fixed my use case (now running for 36 hours, never made it past 8 hours before workaround), but other applications sending more frequently are likely to fail without such an easily implemented workaround.

Thanks,
Greg

[sandeepmistry]

Hi @GregTerrell,

Thanks for letting us know, do you you think you can supply a minimal sketch that can be used to reproduce the problem?

While working on #77, I might have run into this condition in f205d69.

In any case, if there's a simple sketch that can reproduce this condition that would be great.

[GregTerrell]

I will see what I can do. I was testing with Azure IotHub client and remote_monitoring. But now that I know exactly how the failure happened, maybe I can create a node.js server and a brief Arduino sketch. It would be late this week or this weekend at the earliest.

[GregTerrell]

This went up in priority, when I discovered other sections of our application send more headers and hit the 16 outstanding sends quickly. I have uploaded a test configuration that can exercise the issue, there is a sketch and a node.js file. There are differences between the exact event sequences between the attached test jig (below) and testing against the Azure and the remote_monitoring example, but the test below can causes the failure within a couple minutes (see embedded comment). There a perceivable latency differences between the Node.js host and IotHub sends. Note: in my testing I have debugging enabled in the Atmel code; the marker showing the prerequisite for the failure are the Failed to alloc rx size console messages.

(APP)(DBG)[hif_send][424]Failed to alloc rx size
(APP)(DBG)[hif_send][424]Failed to alloc rx size
(APP)(DBG)[hif_send][424]Failed to alloc rx size

Additionally, I have a print macro added to the write() block in WiFiClient.cpp to console echo the number of socket.c sends() required to push the frame on the wire. The example below shows 2 attempts (1 for the failed alloc, 1 suceeded); the output is suppressed for attempts=1.

(APP)(DBG)[hif_send][424]Failed to alloc rx size
(APP)(DBG)[m2m_ip_cb][433]send callback sock=0, sessionID=1
(APP)(DBG)[m2m_ip_cb][433]send callback sock=0, sessionID=1
(LOOUQ)(DBG)[write][216][WiFiClient.cpp] write COMPLETED: send attempts=2

size_t WiFiClient::write(const uint8_t *buf, size_t size)
{
	sint16 err;

	if (_socket < 0 || size == 0) {
		setWriteError();
		return 0;
	}

	// Network led ON (rev A then rev B).
	m2m_periph_gpio_set_val(M2M_PERIPH_GPIO16, 0);
	m2m_periph_gpio_set_val(M2M_PERIPH_GPIO5, 0);

	m2m_wifi_handle_events(NULL);
	int attempts = 1;

	while ((err = send(_socket, (void *)buf, size, 0)) < 0) {
		// Exit on fatal error, retry if buffer not ready.
		if (err != SOCK_ERR_BUFFER_FULL) {
			setWriteError();
			m2m_periph_gpio_set_val(M2M_PERIPH_GPIO16, 1);
			m2m_periph_gpio_set_val(M2M_PERIPH_GPIO5, 1);
			return 0;
		}

		if (attempts % 1000 == 0) {
			LOOUQ_DBG("[WiFiClient.cpp] writing socket=%d, size=%d, sends@:%d", _socket, size, attempts);
		} 
		m2m_wifi_handle_events(NULL);
		attempts ++;
	}
	
	// Network led OFF (rev A then rev B).
	m2m_periph_gpio_set_val(M2M_PERIPH_GPIO16, 1);
	m2m_periph_gpio_set_val(M2M_PERIPH_GPIO5, 1);

	if (attempts > 1) {
		LOOUQ_DBG("[WiFiClient.cpp] write COMPLETED: send attempts=%d", attempts);
	}
	return size;
}

[GregTerrell]

Test Sketch

// targeting Feather M0
#include <WiFi101.h>
static WiFiClient client;              // for WiFi101  

static const char ssid[] = "LOOUQ";
static const char pass[] = "grouperT3ch";
char server[] = "192.168.10.75"; // server IP
int port = 8081;

#define BUFF_SIZE (1024)
char buf[BUFF_SIZE];
  
void setup() {
  // setup serial and wifi
  delay(10000);                                      // wait for FeatherM0 serial start
  Serial.begin(9600);
  Serial.println("Serial interface started.");
  Serial.println("Initializing Feather M0 WINC");
  pinMode(2, OUTPUT);                             // Enable Adafruit FeatherM0 chip, set pins for FeatherM0: CS=8, IRQ=7, RST=4, EN=2
  digitalWrite(2, HIGH);
  WiFi.setPins(8, 7, 4, 2);
  int status = WL_IDLE_STATUS;     // the Wifi radio's status
  while ( status != WL_CONNECTED) {
    Serial.print("Attempting to connect to WPA SSID: ");
    Serial.println(ssid);
    // Connect to WPA/WPA2 network:
    status = WiFi.begin(ssid, pass);
    // wait 5 seconds for connection:
    delay(5000);
  }
  Serial.println("Connected to WiFi");
  delay(2000);

  Serial.print("Connecting to ");
  Serial.print(server);
  Serial.print("  port: ");
  Serial.println(port);
  
  if (client.connect(server, port)) {
    Serial.print("Connected...");
    Serial.println(server);

    int testCnt = 0;
    while(1) {
      
      sendRequest(testCnt);

      /* with the read block below commented, "Failed to alloc rx size" events will
       * appear within the first 10 test cycles and progress to full failure by test
       * cycle 20-30
       * if uncommented, runs can fail in 2 minutes or 20 hours
      */
//      while (client.available()) {
//        char c = client.read();
//        Serial.write(c);
//      }
//      if (!client.connected()) {
//        Serial.println();
//        Serial.println("disconnecting from server.");
//        client.stop();
//      }

      testCnt ++;
      Serial.print("Test cycle: ");
      Serial.println(testCnt);
      delay(1000);
    }
  }
  else {
    Serial.println("Connection failed!");
  }  
}

void loop() {
}

void sendRequest(int testCnt) {
  // send request: request verb, headers (>13), CRLF delim, body
  client.println("POST http://192.168.10.75:8081/ HTTP/1.1");

  client.println("iothub-to: /devices/featherm0-2/messages/events");
  client.println("Authorization: SharedAccessSignature sr=preview.azure-devices.net/devices/featherm0-2&sig=opkb%%3d&se=1479415635&skn=");
  client.println("Accept: application/json");
  client.println("Connection: Keep-Alive");
  client.println("User-Agent: iothubclient/1.0.1");
  client.println("Content-Type: application/octet-stream");
  client.println("iothub-app-iotOS-version: v-1.0");
  client.println("iothub-app-message-type: telemetry");
  client.println("iothub-app-event-class: user");
  client.println("iothub-app-event-name: TempPressHumid");
  client.println("iothub-app-display-value: Temperature=73.40");
  client.println("iothub-messageid: featherm0-2-16139");
  client.println("iothub-app-header0: TempPressHumid");
  client.println("iothub-app-header1: TempPressHumid");
  client.println("iothub-app-header2: TempPressHumid");
  client.println("iothub-app-header3: TempPressHumid");
  client.println("iothub-app-header4: TempPressHumid");
  client.println("iothub-app-header5: TempPressHumid");
  client.println("iothub-app-header6: TempPressHumid");
  client.println("iothub-app-header7: TempPressHumid");
  client.println("iothub-app-header8: TempPressHumid");
  client.println("iothub-app-header9: TempPressHumid");
  client.println("iothub-correlationid:");
  snprintf(buf, sizeof(buf), "Test-Count: %d", testCnt);
  client.println(buf);
  client.println("Host: loouq-iotos-preview.azure-devices.net");
  client.println("Content-Length: 112");
  
  client.write("\r\n",(size_t)2);
  client.println("{\"DEVICEID\":\"featherm0-2\", \"Telemetry\":{\"Temperature\":73.400002, \"BarPressure\":28.877970, \"Humidity\":27.944336}}");
}

[GregTerrell]

Test Node.js

var http = require('http');

http.createServer(function (request, response) {
    console.log();
    console.log("request recvd: method=%s, url=%s", request.method, request.url);

    request.on('error', function(err) {
        console.error(err);
    });

    var headers = request.headers;
    var hdrCnt = 0;
    for(var hdr in headers) {
        ++ hdrCnt;
        console.log("  Header[%d]=%s:%s", hdrCnt, hdr, headers[hdr]);
    }
    if (request.method == 'POST') {
        var jsonString = '';
        request.on('data', function (data) {
            jsonString += data;
        });
        request.on('end', function () {
            console.log(JSON.parse(jsonString));
        });
    }
    console.log("\r\n");

    // Every request gets the same "Hello Connect" response.
    response.writeHead(200, {"Content-Type": "text/plain"});
    response.end("Received IotRequest");

}).listen(8081);
console.log("Listening on port 8081");

[sandeepmistry]

Thanks, I'm able to reproduce with the code you provided with my Mac and a MKR1000. It fails for me on count 21.

[sandeepmistry]

If I add the following:

while (client.available()) {
   client.read();
}

to the end of sendRequest in the sketch it no longer hangs (count was at over 230).

There's an outstanding item with the WINC1500 firmware/ASF code (sort of related to #32), where not reading received data from a socket blocks all operations. With the sketch you supplied I think around count 16 or 21 the receive buffer will fill up an block all SPI communications with the WINC1500 causing the behaviour we are seeing.

Could you please try adding that snippet to the end of sendRequest and seeing if that also makes things better?

After this, the original issue you are reporting might still exist, just need to find a another simple sketch to reproduce it ...

[sandeepmistry]

I just saw your comment in the sketch:

      /* with the read block below commented, "Failed to alloc rx size" events will
       * appear within the first 10 test cycles and progress to full failure by test
       * cycle 20-30
       * if uncommented, runs can fail in 2 minutes or 20 hours
      */
//      while (client.available()) {
//        char c = client.read();
//        Serial.write(c);
//      }
//      if (!client.connected()) {
//        Serial.println();
//        Serial.println("disconnecting from server.");
//        client.stop();
//      }

I'd still be interest in testing without printing the response to Serial to see if it might be USB related.

[GregTerrell]

So just add the...

while (client.available()) {
   client.read();
}

to empty the read buffer?

I can start a test to run overnight.

[sandeepmistry]

@GregTerrell correct, thanks.

I'm wondering if the issues you are seeing could be related to #80 (comment) as well. For that issue, "lots of ARP request cause failure" - this was also seemed random.

Let's see how your overnight tests go, then we can decide if we should open a support ticket with Atmel support (link is in #80 (comment)).

[GregTerrell]

The test last night ran for about 8 hours without issue, the tests with Azure could not make it that long (about 6.5 hours was the longest). I restarted this AM without the 2sec delay between iterations and turned off M2M debug (common\include)... still running without any sign of degrading in buffer acquisition.

The differences between my test setup and the Azure code are...

-The Azure test always paused at the 17th send in the HTTP transaction, pausing until a send callback was received; the test doesn't stall there (this was visible with the M2M debugging output).
-The Session variable stays a 1 (Azure it incremented)

Apparently this is not a very good test jig. I'll go back to the drawing board and think about what source changes could better exercise the issue.

@sandeepmistry Thanks