Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TCPClient on Electron not receiving all of the data for small files #896

Closed
technobly opened this issue Mar 9, 2016 · 24 comments

Comments

@technobly
Copy link
Member

commented Mar 9, 2016

Issue status

  • Fixed on U260
  • Fixed on G350

As reported here in the community:
https://community.particle.io/t/electron-tcpclient-weirdness/20771

Test code, press 'y' to read an 8 byte file. Typically the header is not even completely printed in the serial console, let alone the 8 bytes of data. That said, when looking at the logs we do see that all of the data is read, but the system is doing some strange things. See logs below:

Code

#include "application.h"

// ALL_LEVEL, TRACE_LEVEL, DEBUG_LEVEL, INFO_LEVEL, WARN_LEVEL, ERROR_LEVEL, PANIC_LEVEL, NO_LOG_LEVEL
SerialDebugOutput debugOutput(9600, ALL_LEVEL);

SYSTEM_MODE(AUTOMATIC);

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

/* This function loops forever --------------------------------------------*/
void loop()
{
    if (Serial.available() > 0)
    {
        char c = Serial.read();
        Serial.printf("Hey, you said \'%c\', so I'm gunna: ", c);
        if (c == 't') {
            uint32_t startTime = millis();
            uint32_t endTime = 0;
            Serial.printlnf("Read a text file\r\n[ START TIME ]: %.2f seconds", startTime/1000.0);
            TCPClient client;
            char host[] = "www.textfiles.com";

            Serial.println("connecting...");

            if (client.connect(host, 80))
            {
                Serial.println("connected");
                /* SMALL FILE */
                client.println("GET /100/hack7.txt HTTP/1.0"); // 3988 bytes
                /* LARGE FILE */
                // client.println("GET /100/phrack.29.phk HTTP/1.0"); // 235777 bytes
                client.println("Host: www.textfiles.com");
                client.println("Content-Length: 0");
                client.println();
            }
            else
            {
                Serial.println("connection failed");
            }

            while (client.available() || client.connected())
            {
              if (client.available())
              {
                char c = client.read();
                Serial.print(c);
              }

              if (!client.connected())
              {
                Serial.println();
                Serial.println("disconnecting.");
                client.stop();
              }
            }
            endTime = millis();
            Serial.printlnf("[ END / TOTAL TIME ]: %.2f / %.2f seconds", endTime/1000.0, ((endTime-startTime)/1000.0));
        }
        else if (c == 'y') {
            uint32_t startTime = millis();
            uint32_t endTime = 0;
            Serial.printlnf("Read a text file\r\n[ START TIME ]: %.2f seconds", startTime/1000.0);
            TCPClient client;
            char host[] = "www.technobly.com";

            Serial.println("connecting...");

            if (client.connect(host, 80))
            {
                Serial.println("connected");
                client.println("GET /test.txt HTTP/1.0"); // 8 bytes
                client.println("Host: www.technobly.com");
                client.println("Content-Length: 0");
                client.println();
            }
            else
            {
                Serial.println("connection failed");
            }

            while (client.available() || client.connected())
            {
              if (client.available())
              {
                char c = client.read();
                Serial.print(c);
              }

              if (!client.connected())
              {
                Serial.println();
                Serial.println("disconnecting.");
              }
            }
            client.stop();
            client.flush();
            endTime = millis();
            Serial.printlnf("[ END / TOTAL TIME ]: %.2f / %.2f seconds", endTime/1000.0, ((endTime-startTime)/1000.0));
        }
        else {
            Serial.println("ignore you because you're not speaking my language!");
        }
        while (Serial.available()) Serial.read(); // Flush the input buffer
    }

}

Output without Logs

Hey, you said 'y', so I'm gunna: Read a text file
[ START TIME ]: 68.19 seconds
connecting...
connected
HTTP/1.1 200 OK
Date: Wed, 09 Mar 2016 21:31:41 GMT
Server: Apache
Last-Modified: Wed, 09 Mar 2016 21:19:09 GMT
ETag: "d0a9a
disconnecting.
[ END / TOTAL TIME ]: 75.24 / 7.05 seconds

Output with Logs

As you can see, when connecting to read the test.txt file, there are 116 bytes available to read... however the system tries to read 128 bytes. In doing so 116 bytes are read just fine... ALL of the data. But then the system tries to read 128-116=12 more bytes, and errors! There is no more data to read. The TCP buffer is 128 bytes. It appears that maybe the system doesn't know that there is only 116 bytes to read in the first place? And that the error may be causing data corruption in the TCPClient library??

Hey, you said 'y', so I'm gunna: Read a text file
[ START TIME ]: 80.29 seconds
connecting...
0000080300:DEBUG: virtual void TCPClient::stop() (192):_sock -1 closesocket
    80.308 AT send      33 "AT+UDNSRN=0,\"www.technobly.com\"\r\n"
    82.056 AT read  +   27 "\r\n+UDNSRN: \"74.208.28.90\"\r\n"
    82.072 AT read OK    6 "\r\nOK\r\n"
0000082076:DEBUG: virtual void TCPClient::stop() (192):_sock -1 closesocket
socketSocket(TCP)
    82.086 AT send      12 "AT+USOCR=6\r\n"
    82.100 AT read  +   13 "\r\n+USOCR: 1\r\n"
    82.115 AT read OK    6 "\r\nOK\r\n"
Socket 1: handle 1 was created
0000082122:DEBUG: virtual int TCPClient::connect(IPAddress, uint16_t, network_interface_t) (80):socket=1
0000082133:DEBUG: virtual int TCPClient::connect(IPAddress, uint16_t, network_interface_t) (98):_sock 1 connect
socketConnect(1,port:80)
    82.147 AT send      30 "AT+USOCO=1,\"74.208.28.90\",80\r\n"
    84.624 AT read OK    6 "\r\nOK\r\n"
0000084628:DEBUG: virtual int TCPClient::connect(IPAddress, uint16_t, network_interface_t) (100):_sock 1 connected=1
connected
    84.641 AT send      15 "AT+USOWR=1,22\r\n"
    84.656 AT read  >    3 "\r\n@"
    84.709 AT send      22 "GET /test.txt HTTP/1.0"
    84.854 AT read  +   16 "\r\n+USOWR: 1,22\r\n"
    84.869 AT read OK    6 "\r\nOK\r\n"
    84.873 AT send      14 "AT+USOWR=1,1\r\n"
    84.888 AT read  >    3 "\r\n@"
    84.941 AT send       1 "\r"
    85.074 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    85.089 AT read OK    6 "\r\nOK\r\n"
    85.093 AT send      14 "AT+USOWR=1,1\r\n"
    85.108 AT read  >    3 "\r\n@"
    85.161 AT send       1 "\n"
    85.294 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    85.309 AT read OK    6 "\r\nOK\r\n"
    85.313 AT send      15 "AT+USOWR=1,23\r\n"
    85.328 AT read  >    3 "\r\n@"
    85.381 AT send      23 "Host: www.technobly.com"
    85.526 AT read  +   16 "\r\n+USOWR: 1,23\r\n"
    85.541 AT read OK    6 "\r\nOK\r\n"
    85.545 AT send      14 "AT+USOWR=1,1\r\n"
    85.560 AT read  >    3 "\r\n@"
    85.613 AT send       1 "\r"
    85.746 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    85.761 AT read OK    6 "\r\nOK\r\n"
    85.765 AT send      14 "AT+USOWR=1,1\r\n"
    85.780 AT read  >    3 "\r\n@"
    85.833 AT send       1 "\n"
    85.966 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    85.981 AT read OK    6 "\r\nOK\r\n"
    85.985 AT send      15 "AT+USOWR=1,17\r\n"
    86.000 AT read  >    3 "\r\n@"
    86.053 AT send      17 "Content-Length: 0"
    86.188 AT read  +   16 "\r\n+USOWR: 1,17\r\n"
    86.203 AT read OK    6 "\r\nOK\r\n"
    86.207 AT send      14 "AT+USOWR=1,1\r\n"
    86.222 AT read  >    3 "\r\n@"
    86.275 AT send       1 "\r"
    86.408 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    86.423 AT read OK    6 "\r\nOK\r\n"
    86.427 AT send      14 "AT+USOWR=1,1\r\n"
    86.442 AT read  >    3 "\r\n@"
    86.495 AT send       1 "\n"
    86.628 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    86.643 AT read OK    6 "\r\nOK\r\n"
    86.647 AT send      14 "AT+USOWR=1,1\r\n"
    86.662 AT read  >    3 "\r\n@"
    86.715 AT send       1 "\r"
    86.848 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    86.863 AT read OK    6 "\r\nOK\r\n"
    86.867 AT send      14 "AT+USOWR=1,1\r\n"
    86.882 AT read  >    3 "\r\n@"
    86.935 AT send       1 "\n"
    87.068 AT read  +   15 "\r\n+USOWR: 1,1\r\n"
    87.083 AT read OK    6 "\r\nOK\r\n"
    87.837 AT read  +   18 "\r\n+UUSORD: 1,244\r\n"
Socket 1: handle 1 has 244 bytes pending
socketRecv: _cbUSORD
    87.859 AT send      16 "AT+USORD=1,128\r\n"
    87.884 AT read  +  146 "\r\n+USORD: 1,128,\"HTTP/1.1 200 OK\r\nDate: Wed, 09 Mar 2016 21:47:27 GMT\r\nServer: Apache\r\nLast-Modified: Wed, 09 Mar 2016 21:19:09 GMT\r\nETag: \"d0a9a\""
    87.914 AT read OK    6 "\r\nOK\r\n"
0000087918:DEBUG: virtual int TCPClient::available() (145):recv(=128)
HTTP/1.1 200 OK
Date: Wed, 09 Mar 2016 21:47:27 GMT
Server: Apache
Last-Modified: Wed, 09 Mar 2016 21:19:09 GMT
ETag: "d0a9a    87.939 AT read  +   18 "\r\n+UUSORD: 1,116\r\n"
Socket 1: handle 1 has 116 bytes pending
socketRecv: _cbUSORD
    87.961 AT send      16 "AT+USORD=1,128\r\n"
    87.986 AT read  +  134 "\r\n+USORD: 1,116,\"d-8-52da43fac4c1a\"\r\nAccept-Ranges: bytes\r\nContent-Length: 8\r\nConnection: close\r\nContent-Type: text/plain\r\n\r\ndeadbeef\""
    88.015 AT read OK    6 "\r\nOK\r\n"
socketRecv: _cbUSORD
    88.021 AT send      15 "AT+USORD=1,12\r\n"
    88.236 AT read ERR  37 "\r\n+CME ERROR: operation not allowed\r\n"
    88.243 AT read  +   14 "\r\n+UUSOCL: 1\r\n"
Socket 1: handle 1 closed by remote host
0000088263:DEBUG: virtual uint8_t TCPClient::connected() (209):caling Stop No more Data and in CLOSE_WAIT
0000088273:DEBUG: virtual void TCPClient::stop() (192):_sock 1 closesocket
socketFree(1)

disconnecting.
0000088285:DEBUG: virtual void TCPClient::stop() (192):_sock -1 closesocket
[ END / TOTAL TIME ]: 88.29 / 8.00 seconds

@technobly technobly added the bug label Mar 9, 2016

@technobly technobly added this to the 0.5.x milestone Mar 9, 2016

@m-mcgowan

This comment has been minimized.

Copy link
Contributor

commented Mar 9, 2016

Most socket APIs have a read method that lets you pass in a buffer and the API will read as much as is available, up to that amount, but potentially less. But here the modem is expecting the exact amount of data to be retrieved, so before the _chUSORD call, the code will need to check how much data is available and limit the amount read to that.

m-mcgowan added a commit that referenced this issue Mar 9, 2016
@m-mcgowan

This comment has been minimized.

Copy link
Contributor

commented Mar 9, 2016

The proposed fix above is untested - I thought it would be quicker that you did it since you have the test fixture already setup.

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 9, 2016

@m-mcgowan your fix is working well! I didn't remember there was a while(len) loop in the socketRecv() function... which is where the extra remainders of reads were coming from (i.e. 128-116=12 bytes from above logs)... resulting in an error (-1) being returned instead of the byte count (cnt).

m-mcgowan added a commit that referenced this issue Mar 11, 2016
@asterix555

This comment has been minimized.

Copy link

commented Mar 12, 2016

Hi,

I merged the commit, compiled a firmware, modified build/version.mk and flashed system-part1.bin, system-part2.bin and test.bin and verified using particle serial inspect. The version number increased, but the result isn't as expected,..

[ START TIME ]: 91.74 seconds
connecting...
connected
HTTP/1.1 200 OK
Date: Sat, 12 Mar 2016 11:57:50 GMT
Server: Apache
Last-Modified: Wed, 09 Mar 2016 21:19:09 GMT
ETag: "d0a9a[ END / TOTAL TIME ]: 95.92 / 4.18 seconds

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 17, 2016

@asterix555 you should only need to:

git fetch
git checkout feature/electron_tcp_socket

...to test this fix. Can you try again and make sure you see the fix in the last commit before compiling?

commit 32a436177f022101eb334b4e3abcdc45f7500660
    suggested fix for #896 (untested)
@asterix555

This comment has been minimized.

Copy link

commented Mar 17, 2016

hi,
the commit is in my code. I did a make PLATFORM=electron clean before and increased version.mk to 0.4.9e and verified, that this firmware is correctly flashed. After flashing system-part1&2.bin 3 times in listening mode it increased.

I also tried to flash OTA, same result.

$ git status
On branch feature/electron_tcp_socket
Your branch is up-to-date with 'origin/feature/electron_tcp_socket'.

Check Firmware:

system firmware version: 0.4.9e

Result:

Hey, you said 'y', so I'm gunna: Read a text file
[ START TIME ]: 7.58 seconds
connecting...
connected
HTTP/1.1 200 OK
Date: Thu, 17 Mar 2016 05:54:29 GMT
Server: Apache
Last-Modified: Wed, 09 Mar 2016 21:19:09 GMT
ETag: "d0a9a[ END / TOTAL TIME ]: 14.35 / 6.77 seconds
@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 17, 2016

Thanks for the quick reply @asterix555 ! So were you just modifying version.mk to make sure the flash memory was updated?

I'll test this again in the morning (1AM now)... it was working fine for me when I initially tested. What type of Electron do you have? U260/U270/G350?

@technobly technobly self-assigned this Mar 17, 2016

@asterix555

This comment has been minimized.

Copy link

commented Mar 17, 2016

Hi,
it's the G350. Thank you so far and good night!

@entone

This comment has been minimized.

Copy link

commented Mar 17, 2016

using the feature/electron_tcp_socket branch fixed my issue. thanks!

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 18, 2016

Confirmed again it's working on a U260, but just now trying on a G350 I'm getting the old response where it doesn't show the full message even though it's definitely receiving it. Just like @asterix555 's output... will investigate.

U260 Logs (Working after 32a4361)
G350 Logs (Not Working after 32a4361)

@asterix555

This comment has been minimized.

Copy link

commented Mar 25, 2016

Hi, let me know if you have any code for testing,.. regards

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 25, 2016

@entone are you using a G350 or U260/U270?

@entone

This comment has been minimized.

Copy link

commented Mar 25, 2016

U260

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 25, 2016

Ok cool, thanks @entone. So far @asterix555 I have no fix for G350's, and it's something I will be looking at fixing in the near future.

@doom369

This comment has been minimized.

Copy link

commented Mar 29, 2016

@technobly hello, did you have a chance to look through the issue?

@technobly

This comment has been minimized.

Copy link
Member Author

commented Mar 29, 2016

Not yet @doom369, but it is on my list of things to look into ;-) I'll update here when I have more info.

@doom369

This comment has been minimized.

Copy link

commented Mar 29, 2016

Ok, Thanks.

@vshymanskyy

This comment has been minimized.

Copy link

commented Mar 30, 2016

@technobly , Blynk is probably blocked by this issue: blynkkk/blynk-library#104
I have SARA-U270...

@technobly technobly referenced this issue Apr 14, 2016
6 of 7 tasks complete
@technobly

This comment has been minimized.

Copy link
Member Author

commented Apr 14, 2016

@asterix555 @doom369 @vshymanskyy please give #962 a test on your G350's. Should be working for you now with large and small files.

@asterix555

This comment has been minimized.

Copy link

commented Apr 14, 2016

Thank you.
I'm abroad now and can test it only after end of april...

@yarrumretep

This comment has been minimized.

Copy link

commented Apr 14, 2016

@technobly - when do you think these changes will be bundled into a formal release and/or merged to master?

@m-mcgowan m-mcgowan closed this in 44e6c1b Apr 14, 2016

m-mcgowan added a commit that referenced this issue Apr 14, 2016
@technobly

This comment has been minimized.

Copy link
Member Author

commented Apr 14, 2016

@yarrumretep working on it now... check Build tomorrow (Friday) :)

@technobly

This comment has been minimized.

Copy link
Member Author

commented Apr 16, 2016

Build rollout pushed to early next week... hopefully Monday. Binaries are out here though for system part updates: https://github.com/spark/firmware/releases/tag/v0.5.0-rc.2

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
7 participants
You can’t perform that action at this time.