TCPClient Connect Issues on Electron

I did some investigation of using the Electron to upload data by FTP. It can be done and it works quite well, though there are some slightly weird stuff going on, which I’ll explain in detail below.

I wrote a test program that uploads a file by FTP server every minute or so. It logs in (USER and PASS), changes the directory (CWD), requests passive mode (PASV), stores the file on the server (STOR), then quits (QUIT). The source is below.

I also have a separate monitor program that monitors the Electron serial, parsing the debug entries, and also has access to the FTP server directories, where it validates that files were uploaded successfully. It checks the file size and data to make sure it was uploaded correctly. That’s written in Java and is not included.

I ran it on 0.5.3 on a 3G Electron (U260).

Actually, it’s 0.5.3 DEBUG_BUILD=y so I also have logging information from inside the system firmware, in particular the messages about the inner workings inside the modem parser. This requires a gcc-arm local build environment but is very handy for this sort of thing.

For example, when I sent the QUIT command, this is what gets logged. Lots of good info here:

    493.225 AT send       6 "QUIT\r\n"
    493.355 AT read  +   15 "\r\n+USOWR: 1,6\r\n"
    493.365 AT read OK    6 "\r\nOK\r\n"
    493.715 AT read  +   17 "\r\n+UUSORD: 1,14\r\n"
 Socket 1: handle 1 has 14 bytes pending
 socketRecv: _cbUSORD
    493.735 AT send      15 "AT+USORD=1,14\r\n"
    493.745 AT read  +   31 "\r\n+USORD: 1,14,\"221 Goodbye.\r\n\""
    493.755 AT read OK    6 "\r\nOK\r\n"
 0000493765:DEBUG: virtual int TCPClient::available() (145):recv(=14)

Anyway, I ran the test for over an hour and attempted 70 connections, and all successfully uploaded the data. 52 worked perfectly. 18 (25 %) has the weird command connection problem described below, but the file was still uploaded correctly.

I also tested without the debug build, and it behaves the same way.

FTP is horrible

Just thought I’d mention FTP is:

  • Insecure. Passwords are sent clear-text.
  • Chatty. It takes many back-and-forth operations to do anything.
  • Requires multiple TCP connections for simple operations.
  • Has no way to tell whether uploaded or downloaded data is truncated.

Of course other protocols will have overhead as well, but sending my 1024 byte payload requires 2988 to 3081 bytes of cellular data. That’s not a great overhead ratio!

Also, because of the weird way that the state transitions interact with the command connection and data connection, you really have to implement it with at least two finite state machines. I used three. Otherwise, you can get into weird timing-related issues when stuff arrives in an order other than what you expected.

And the FTP RFC has ridiculous things like this:

                            1
      +---+   USER    +---+------------->+---+
      | B |---------->| W | 2       ---->| E |
      +---+           +---+------  |  -->+---+
                       | |       | | |
                     3 | | 4,5   | | |
         --------------   -----  | | |
        |                      | | | |
        |                      | | | |
        |                 ---------  |
        |               1|     | |   |
        V                |     | |   |
      +---+   PASS    +---+ 2  |  ------>+---+
      |   |---------->| W |------------->| S |
      +---+           +---+   ---------->+---+
                       | |   | |     |
                     3 | |4,5| |     |
         --------------   --------   |
        |                    | |  |  |
        |                    | |  |  |
        |                 -----------
        |             1,3|   | |  |
        V                |  2| |  |
      +---+   ACCT    +---+--  |   ----->+---+
      |   |---------->| W | 4,5 -------->| F |
      +---+           +---+------------->+---+

The code

Here’s my sample program.

This is a proof-of-concept to make sure FTP works.

I would not recommend using it as a basis for a production FTP client. Actually, I wouldn’t recommend using FTP at all.

[Updated: Fixed bug in continuation line handling as described below.]

#include "Particle.h"

// Adds debugging output over Serial USB
// ALL_LEVEL, TRACE_LEVEL, DEBUG_LEVEL, INFO_LEVEL, WARN_LEVEL, ERROR_LEVEL, PANIC_LEVEL, NO_LOG_LEVEL
SerialDebugOutput debugOutput(9600, ALL_LEVEL);

SYSTEM_THREAD(ENABLED);

const char *FTP_HOST = "server.example.com";
const int FTP_COMMAND_PORT = 21;
const char *FTP_USER = "username";
const char *FTP_PASSWORD = "secret";
const char *FTP_REMOTE_DIR = "reports";
const size_t RESPONSE_SIZE = 512;
const size_t SEND_DATA_SIZE = 1024;

const unsigned long INITIAL_WAIT_MS = 30000;
const unsigned long REPORT_PERIOD_MS = 60000;
const unsigned long COMMAND_TIMEOUT_MS = 30000;
const unsigned long SEND_TIMEOUT_MS = 60000;
const size_t MAX_TCP_WRITE = 512;

// Forward declarations
void cleanupAndWait();
void prepareSendData();
bool processResponse();
bool processCommandStateMachine(int code);
void processDataStateMachine();

typedef enum {
	INITIAL_WAIT_STATE,
	READY_WAIT_STATE,
	COMMAND_STATE,
	NEXT_REPORT_WAIT_STATE
} State;

typedef enum {
	BANNER_WAIT_STATE,
	USER_RESPONSE_WAIT_STATE,
	PASS_RESPONSE_WAIT_STATE,
	CWD_RESPONSE_WAIT_STATE,
	PASV_RESPONSE_WAIT_STATE,
	STOR_RESPONSE_WAIT_STATE,
	QUIT_RESPONSE_WAIT_STATE
} CommandState;

typedef enum {
	DATA_IDLE_STATE,
	DATA_CONNECT_STATE,
	DATA_SEND_WAIT_READY,
	DATA_SEND_STATE,
	DATA_CLEANUP_STATE,
} DataState;

State state = INITIAL_WAIT_STATE;
CommandState commandState;
DataState dataState;
TCPClient commandClient;
TCPClient dataClient;
unsigned long stateTime = 0;
char responseBuf[RESPONSE_SIZE + 1];
size_t responseOffset = 0;
bool firstLine = true;
IPAddress dataAddr;
int dataPort;
bool sendReady = false;
String sendFilename;
char sendBuf[SEND_DATA_SIZE];
size_t sendBufOffset = 0;
size_t sendSize;
unsigned long sendTime = 0;
unsigned long sendCompleteTime = 0;
bool continuation = false;

void setup() {
	Serial.begin(9600);
}

void loop() {
	switch(state) {
	case INITIAL_WAIT_STATE:
		if (millis() - stateTime >= INITIAL_WAIT_MS) {
			state = READY_WAIT_STATE;
		}
		break;

	case READY_WAIT_STATE:
		if (Particle.connected()) {
			Serial.printlnf("** connecting to %s:%d", FTP_HOST, FTP_COMMAND_PORT);

			if (!commandClient.connect(FTP_HOST, FTP_COMMAND_PORT)) {
				// Failed to connected
				Serial.println("failed to connect");
				state = NEXT_REPORT_WAIT_STATE;
				stateTime = millis();
				break;
			}

			// Successfully connected
			state = COMMAND_STATE;
			stateTime = millis();
			responseOffset = 0;
			commandState = BANNER_WAIT_STATE;
		}
		break;

	case COMMAND_STATE:
		// Handle receiving data from the command connection
		if (commandClient.connected()) {
			size_t bytesLeft = RESPONSE_SIZE - responseOffset;
			if (bytesLeft == 0) {
				Serial.println("server returned too large of a response");
				cleanupAndWait();
				break;
			}
			int bytesRead = commandClient.read((uint8_t *) &responseBuf[responseOffset], bytesLeft);
			if (bytesRead > 0) {
				// Additional data has arrived
				responseOffset += bytesRead;

				// Null-terminate buffer for strstr, note that buffer is one byte longer than
				// RESPONSE_SIZE to account for this.
				responseBuf[responseOffset] = 0;

				while(processResponse()) {
					// Handle all of the lines in the response buffer
				}
			}

			if (millis() - stateTime >= COMMAND_TIMEOUT_MS) {
				Serial.println("** timeout in command mode");
				cleanupAndWait();
			}
		}
		else {
			Serial.println("** server disconnected");
			cleanupAndWait();
		}
		break;

	case NEXT_REPORT_WAIT_STATE:
		if (millis() - stateTime >= REPORT_PERIOD_MS) {
			state = READY_WAIT_STATE;
		}
		break;
	}

	processDataStateMachine();
}

void prepareSendData() {

	size_t offset = 0;

	sendFilename = Time.format("%Y%m%dT%H%M%S") + ".txt";
	Serial.printlnf("** sending file: %s", sendFilename.c_str());

	// For testing purposes, we just create some basic information like the time and date, then
	// fill the buffer with sequential ASCII characters for error detection
	sendSize = SEND_DATA_SIZE;

	offset += snprintf(&sendBuf[offset], sendSize - offset, "created: %s\n", Time.format(TIME_FORMAT_DEFAULT).c_str());
	offset += snprintf(&sendBuf[offset], sendSize - offset, "millis: %lu\n", millis());
	offset += snprintf(&sendBuf[offset], sendSize - offset, "sendSize: %u\n", sendSize);

#if Wiring_Cellular
	CellularData cellularData;
	Cellular.getDataUsage(cellularData);
	offset += snprintf(&sendBuf[offset], sendSize - offset, "cellular usage: cid=%d, tx_session=%d, rx_session=%d\n",
			cellularData.cid, cellularData.tx_session, cellularData.rx_session);
#endif

	// Fill rest of the buffer with sequential ASCII data
	char ch = 32;
	for(; offset < (sendSize - 1); offset++) {
		sendBuf[offset] = ch++;
		if (ch >= 127) {
			ch = 32;
		}
	}

	// Make it end with a newline, makes validating easier
	sendBuf[sendSize - 1] = '\n';

	sendBufOffset = 0;
}

void cleanupAndWait() {
	Serial.println("cleanupAndWait");

	if (dataClient.connected()) {
		Serial.println("** closing data connection");
		dataClient.stop();
		dataState = DATA_IDLE_STATE;
	}

	commandClient.stop();
	state = NEXT_REPORT_WAIT_STATE;
	stateTime = millis();

	Serial.println("** ready for next send");
}

bool processResponse() {
	bool checkAgain = false;

	char *endOfLine = strstr(responseBuf, "\015\012");
	if (endOfLine) {
		size_t lineSizeWithEOL = endOfLine - responseBuf + 2;
		*endOfLine = 0;


		if (responseBuf[3] == ' ') {
			continuation = false;

			int code;
			if (sscanf(responseBuf, "%03d", &code) == 1) {
				Serial.printlnf("code %d", code);

				while(processCommandStateMachine(code)) {
					//
				}
			}
			else {
				Serial.printlnf("invalid line %s", responseBuf);
			}
		}
		else
		if (continuation) {
			Serial.printlnf("continuation %s", responseBuf);
		}
		else
		if (responseBuf[3] == '-') {
			Serial.printlnf("continuation start %s", responseBuf);
			continuation = true;
		}
		else {
			Serial.printlnf("unexpected line %s", responseBuf);
		}

		size_t bytesAfter = responseOffset - lineSizeWithEOL;
		if (bytesAfter > 0) {
			// There are possibly more lines in the buffer
			memmove(responseBuf, &responseBuf[lineSizeWithEOL], bytesAfter);
			responseOffset -= lineSizeWithEOL;
			checkAgain = true;
		}
		else {
			responseOffset = 0;
		}
	}

	return checkAgain;
}


bool processCommandStateMachine(int code) {
	bool checkAgain = false;

	switch(commandState) {
	case BANNER_WAIT_STATE:
		if (code == 220) {
			// Send USER command
			commandClient.printf("USER %s\015\012", FTP_USER);
			commandState = USER_RESPONSE_WAIT_STATE;
		}
		else {
			Serial.printlnf("failed to connect, error %s", responseBuf);
			cleanupAndWait();
		}
		break;

	case USER_RESPONSE_WAIT_STATE:
		if (code == 331) {
			// Send PASS command
			commandClient.printf("PASS %s\015\012", FTP_PASSWORD);
			commandState = PASS_RESPONSE_WAIT_STATE;
		}
		else {
			Serial.printlnf("failed to login, error %s", responseBuf);
			cleanupAndWait();
		}
		break;

	case PASS_RESPONSE_WAIT_STATE:
		if (code == 230) {
			Serial.println("logged in successfully!");
			commandClient.printf("CWD %s\015\012", FTP_REMOTE_DIR);
			commandState = CWD_RESPONSE_WAIT_STATE;
		}
		else {
			Serial.printlnf("failed to login, error ", responseBuf);
			cleanupAndWait();
		}
		break;

	case CWD_RESPONSE_WAIT_STATE:
		if (code == 250) {
			Serial.printlnf("directory set to %s", FTP_REMOTE_DIR);
			commandClient.printf("PASV\015\012");
			commandState = PASV_RESPONSE_WAIT_STATE;
		}
		else {
			Serial.printlnf("failed to change directory, error ", responseBuf);
			cleanupAndWait();
		}
		break;

	case PASV_RESPONSE_WAIT_STATE:
		if (code == 227) {
			int a[6];
			// Skip over result code and look for numbers
			char *cp = &responseBuf[4];
			while(*cp && (*cp < '0' || *cp > '9')) {
				cp++;
			}
			if (sscanf(cp, "%u,%u,%u,%u,%u,%u", &a[0], &a[1], &a[2], &a[3], &a[4], &a[5]) == 6) {

				dataAddr = IPAddress(a[0], a[1], a[2], a[3]);
				dataPort = (a[4] * 256) + a[5];
				// Serial.printlnf("data addr=%s port=%d", dataAddr.toString().c_str(), dataPort);

				prepareSendData();
				// Serial.printlnf("STOR %s", sendFilename.c_str());

				commandClient.printf("STOR %s\015\012", sendFilename.c_str());
				commandState = STOR_RESPONSE_WAIT_STATE;
				sendReady = false;
				dataState = DATA_CONNECT_STATE;
			}
			else {
				Serial.printlnf("failed to parse PASV response ", responseBuf);
				cleanupAndWait();
			}
		}
		else {
			Serial.printlnf("PASV command failure, error ", responseBuf);
			cleanupAndWait();
		}
		break;

	case STOR_RESPONSE_WAIT_STATE:
		if (code == 150) {
			Serial.printlnf("STOR got OK to send data, response %s", responseBuf);
			sendReady = true;
		}
		else {
			if (code == 226) {
				Serial.printlnf("** STOR successful, response %s", responseBuf);
			}
			else {
				Serial.printlnf("** STOR failed, error ", responseBuf);
				dataState = DATA_CLEANUP_STATE;
			}

			commandClient.printf("QUIT\015\012");
			commandState = QUIT_RESPONSE_WAIT_STATE;
		}
		break;

	case QUIT_RESPONSE_WAIT_STATE:
		if (code == 221) {
			Serial.printlnf("** QUIT successful, response %s", responseBuf);
		}
		cleanupAndWait();
		break;
	}

	return checkAgain;
}

void processDataStateMachine() {

	switch(dataState) {
	case DATA_IDLE_STATE:
		break;

	case DATA_CONNECT_STATE:
		Serial.printlnf("making data connection to addr=%s port=%d", dataAddr.toString().c_str(), dataPort);
		if (dataClient.connect(dataAddr, dataPort)) {
			Serial.println("data connection established");
			dataState = DATA_SEND_WAIT_READY;
			sendTime = millis();
		}
		else {
			Serial.println("** data connection failed");
			dataState = DATA_CLEANUP_STATE;
		}
		break;

	case DATA_SEND_WAIT_READY:
		if (sendReady) {
			dataState = DATA_SEND_STATE;
		}
		if (millis() - sendTime >= SEND_TIMEOUT_MS) {
			Serial.println("** data timeout waiting for 150 response");
			dataState = DATA_CLEANUP_STATE;
		}
		break;

	case DATA_SEND_STATE:
		if (dataClient.connected()) {
			if (sendBufOffset < sendSize) {
				size_t toWrite = sendSize - sendBufOffset;
				if (toWrite > MAX_TCP_WRITE) {
					toWrite = MAX_TCP_WRITE;
				}
				int result = dataClient.write((uint8_t *)&sendBuf[sendBufOffset], toWrite);
				if (result == -16) {
					// Buffer full, try again later (Photon only)
				}
				else
				if (result <= 0) {
					Serial.printlnf("error sending %d", result);
					dataState = DATA_CLEANUP_STATE;
				}
				else {
					sendBufOffset += result;
				}
			}
			else {
				// All data successfully sent
				unsigned long elapsed = millis() - sendTime;

				Serial.printlnf("** data sent successfully, %u bytes in %lu ms", sendSize, elapsed);
				dataState = DATA_CLEANUP_STATE;
			}

			// Discard any received data on the client connection to make sure the connection closes gracefully.
			// There shouldn't be any, just being safe.
			while(dataClient.available()) {
				dataClient.read();
			}
		}
		else {
			Serial.println("** data closed unexpectedly");
			dataState = DATA_CLEANUP_STATE;
		}

		if (millis() - sendTime >= SEND_TIMEOUT_MS) {
			Serial.println("** data timeout sending");
			dataState = DATA_CLEANUP_STATE;
		}
		break;

	case DATA_CLEANUP_STATE:
		dataClient.stop();
		dataState = DATA_IDLE_STATE;
		break;
	}
}


The Problem

While I successfully transferred 100 % of the file data, there was this oddity:

I successfully close the data connection using dataConnection.stop() which internally issues a AT+USOCL=2 and it seems to succeed. But then nothing happens.

Failure:

   846.092 AT send      16 "AT+USOWR=2,512\r\n"
   846.102 AT read  >    3 "\r\n@"
   846.152 AT send     512 ")*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~ !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~ !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~ !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~ !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~ !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLM"
   846.338 AT read  +   17 "\r\n+USOWR: 2,512\r\n"
   846.348 AT read OK    6 "\r\nOK\r\n"
data sent successfully, 1024 bytes in 1212 ms
0000846388:DEBUG: virtual void TCPClient::stop() (192):_sock 2 closesocket
socketClose(2)
   846.388 AT send      12 "AT+USOCL=2\r\n"
   846.658 AT read OK    6 "\r\nOK\r\n"
socketFree(2)
timeout in command mode
cleanupAndWait
0000870448:DEBUG: virtual void TCPClient::stop() (192):_sock 1 closesocket
socketClose(1)
   870.448 AT send      12 "AT+USOCL=1\r\n"
   872.729 AT read OK    6 "\r\nOK\r\n"
socketFree(1)

In a normal, successful transaction, the next thing that happens is that bytes arrive on the command connection +UUSORD: 1,24. This doesn’t happen in the failure scenario.

Success:

   774.411 AT read  +   17 "\r\n+USOWR: 2,512\r\n"
   774.421 AT read OK    6 "\r\nOK\r\n"
data sent successfully, 1024 bytes in 1312 ms
0000774461:DEBUG: virtual void TCPClient::stop() (192):_sock 2 closesocket
socketClose(2)
   774.461 AT send      12 "AT+USOCL=2\r\n"
   774.731 AT read OK    6 "\r\nOK\r\n"
socketFree(2)
   775.471 AT read  +   17 "\r\n+UUSORD: 1,24\r\n"
Socket 1: handle 1 has 24 bytes pending
socketRecv: _cbUSORD
   775.491 AT send      15 "AT+USORD=1,24\r\n"
   775.501 AT read  +   41 "\r\n+USORD: 1,24,\"226 Transfer complete.\r\n\""
   775.511 AT read OK    6 "\r\nOK\r\n"
0000775521:DEBUG: virtual int TCPClient::available() (145):recv(=24)
got line 226 Transfer complete.
got code 226
STOR successful, response 226 Transfer complete.

I don’t have a good way to determining for sure whether the server fails to send the command response or whether the Electron isn’t receiving it, but I’d vote for failure to receive.

  • If I try to send another command like QUIT on the command connection, there is no response.
  • I ran the test with a Photon and the same server, and it always works.
  • The file is correctly stored by the server and there’s a log entry that was uploaded in the FTP server log.

Anyway, there’s probably a bug somewhere, but it wasn’t hard to work around, and like I said, FTP is horrible.

Summary

It appears that you can send little back-and-forth transactions all you want, but it’s best to do it using state machines because you have to be careful about blocking the loop or weird timing issues specific to the FTP protocol.

There is some weirdness relating to closing the FTP data connection causing problems with the command connection, but this can be worked around and the data is still sent successfully.

4 Likes