earlephilhower / arduino-pico

Raspberry Pi Pico Arduino core, for all RP2040 and RP2350 boards
GNU Lesser General Public License v2.1
1.96k stars 406 forks source link

http.getString() in HTTPClient returns empty string after a successful http.GET(), if the content-length is below a threshold. #2296

Closed seanboyce closed 1 month ago

seanboyce commented 1 month ago

I have experienced some puzzling behavior with http.getString(). I encounter this problem with at least HTTP GET and POST operations.

Using a standard Pi Pico W, Arduino IDE 2.3.2 as an AppImage under Linux, the latest version of HTTPClient as of 2024-07-25, and the example here : HTTPClient/examples/BasicHttpClient/BasicHttpClient.ino

Changing only the WiFi SSID / password and the target URL:

  1. If I keep the default URL, it functions correctly.
  2. If I change the default URL to point at a webserver on my local network (example: "http://192.168.1.7:8000/code/12-d7-03-ad-f2") that returns a small amount of raw text, the response code is 200 OK, the value of the content-length header is correct, http.getString() apparently succeeds, but returns an empty string. In my case the content-length was around 224 bytes, and I have plenty of free memory.
  3. If I add a bunch of dummy content so the webserver sends some thousands of characters of text back, it works as expected with no other changes -- http.getString() returns a String containing the exact text. I have not worked out the exact threshold where it begins to work (time consuming for me to work out -- if it is helpful though, I will do it)

The webserver is FastAPI.

Some things I've tried:

Postman and a web browser display the correct response in all cases. I correctly define content-length in the response header. On the webserver end, I can see the request correctly coming in from the Pi Pico W, and that it responds correctly as well in all cases. The getString() function returns an empty string 100% of the time when the content is a small length, and returns the correct string 100% of the time when it is some arbitrary long length.

An example of an expected response would be a string equal to:

19-68-97-237-30-1-23-70-115-0-152-103-227-173-234-122-141-113-204-138-74-248-224-161-149-192-45-233-184-86-245-48-160-1-9-66-47-93-130-54-92-62-98-9-119-115-17-55-4-129-222-28-110-166-184-60-236-248-250-225-3-82-67-114

Code provided below is only for convenience as it is just the example script with the modifications described above:

/**
   BasicHTTPClient.ino

   Created on: 24.05.2015

*/

#include <Arduino.h>
#include <WiFi.h>
#include <HTTPClient.h>

#ifndef STASSID
#define STASSID "MYSSID"
#define STAPSK "MYPASSWORD"
#endif

const char *ssid = STASSID;
const char *pass = STAPSK;

WiFiMulti WiFiMulti;

void setup() {

  Serial.begin(115200);
  // Serial.setDebugOutput(true);

  Serial.println();
  Serial.println();
  Serial.println();

  for (uint8_t t = 4; t > 0; t--) {
    Serial.printf("[SETUP] WAIT %d...\n", t);
    Serial.flush();
    delay(1000);
  }

  WiFiMulti.addAP(ssid, pass);
}

void loop() {
  // wait for WiFi connection
  if ((WiFiMulti.run() == WL_CONNECTED)) {

    HTTPClient http;

    Serial.print("[HTTP] begin...\n");
    if (http.begin("http://192.168.1.7:8000/code/12-d7-03-ad-f2")) {  // HTTP

      Serial.print("[HTTP] GET...\n");
      // start connection and send HTTP header
      int httpCode = http.GET();

      // httpCode will be negative on error
      if (httpCode > 0) {
        // HTTP header has been send and Server response header has been handled
        Serial.printf("[HTTP] GET... code: %d\n", httpCode);

        // file found at server
        if (httpCode == HTTP_CODE_OK || httpCode == HTTP_CODE_MOVED_PERMANENTLY) {
          String payload = http.getString();
          Serial.println(payload);
        }
      } else {
        Serial.printf("[HTTP] GET... failed, error: %s\n", http.errorToString(httpCode).c_str());
      }

      http.end();
    } else {
      Serial.printf("[HTTP} Unable to connect\n");
    }
  }

  delay(10000);
}
Serial Output:

[HTTP] GET... code: 200

[HTTP] begin...
[HTTP] GET...
[HTTP] GET... code: 200

[HTTP] begin...
[HTTP] GET...
[HTTP] GET... code: 200
earlephilhower commented 1 month ago

I don't have access to your web server, so the simplest way to look at things would be to get a wireshark dump of the webserver's comms. Can you grab a full GET...response cycle and post it? That way it's trivial to see if there's something odd with the format (i.e. header fields, chunked transmission, etc.) and think through what's happening on the Pico.

You can also get useful info to post here by enabling Debug Port->Serial and Debug Level->All. There'll be tons of cruft, but I believe the HTTPClient is pretty chatty about what it is doing.

seanboyce commented 1 month ago

Ah thanks, I didn't know about the debug level function! Here's what I get from a GET request that does not work:

[HTTP] GET... code: 200

:ur 1 :dsrcv 0 :close :del [HTTP] begin... [HTTP] GET... :ref 1 :wr 128 0 :wrc 128 128 0 :wr 48 0 :wrc 48 48 0 :ack 128 :ack 48 :rn 182 :c0 1, 182 [HTTP] GET... code: 200

:ur 1 :dsrcv 0 :close :del

Then here's what I get from a request that succeeds by responding with longer content (actual content removed for brevity):

[HTTP] begin... [HTTP] GET... :ref 1 :wr 128 0 :wrc 128 128 0 :wr 48 0 :wrc 48 48 0 :ack 128 :ack 48 :rn 183 :rch 183, 1460 :rch 1643, 1460 :c 1, 183, 3103 [HTTP] GET... code: 200 :rch 2920, 659 :c 1, 1460, 3579 :c 1, 1460, 2119 :c0 1, 659 {"message":"<165-158-44-25-33-82-149-189-36-187-35-231-163-248-104-47-252-4-120-32-145-88-109-96-19-1-186-211-172-30-219-226-172-59-35-102-17-140-245-208-177-8-126-131-161-32-78-26-10-43-51-151-38-229-4-168-236-249-116-10-170-235-79-86>","ignore":"Content here removed for brevity. It's just Lorem Ipsum over and over."} :ur 1 :dsrcv 0 :close :del

On wireshark, in both cases, I see the HTTP GET request coming in from the Pi normally. In both cases, I see the response being sent back. In both cases, the response contains the content -- however I get some unexpected packets afterward in the fail case.

One thing I note, is that the successful attempt has enough content so that the content is split across two or more packets -- whereas the failed attempt fits in a single packet. This smells a little like a clue -- if I have a chance later today I will attempt with a different webserver (e.g. plain Apache) and see if the behavior is different.

In case useful, I've attached the wireshark logs for the communication between my server and the Pi Pico. I've removed extraneous packets. Github doesn't support the upload of pcapng files, so I've compressed them in an archive.

packetLogs.zip

Edit: You may note custom headers in the packets. I've tested with and without these, they are not the source of the problem. Just part of potential workaround, transmitting my data in a header is more elegant than adding ~1460 extra characters then dropping them from the response :)

earlephilhower commented 1 month ago

Thanks. The packet logs will be interesting to look at tomorrow my time, it's late here now. The debug logs also tell the story of what the WiFiClient is doing and it's obviously not sending anything in the failing case (but I need to re-read the code to grok the exact meanings of the : messages...been a long while).

Very brief glance I see the headers come in their own (fragmented and reassembled packet) and then the data comes in 1 or more separate ones. Definitely something to start with.

earlephilhower commented 1 month ago

Looking again thru the debug logs I noticed there were no actual HTTPClient logs. Looks like I forgot to update a debug macro and it was always disabled. If you could apply #2300 (1-file, 3-line fix you can edit manually if needed) and re-run with Debug Level->All, Debug Port->Serial, and paste that output. It should have lines like


....
[HTTP-Client][handleHeaderResponse] RX: 'Server: gunicorn/19.9.0'
[HTTP-Client][handleHeaderResponse] RX: 'Access-Control-Allow-Origin: *'
[HTTP-Client][handleHeaderResponse] RX: 'Access-Control-Allow-Credentials: true'
:c 1, 239, 9832
[HTTP-Client][handleHeaderResponse] RX: ''
[HTTP-Client][handleHeaderResponse] code: 200
[HTTP-Client][handleHeaderResponse] size: 9593
[HTTP] GET... code: 200
....
seanboyce commented 1 month ago

Sure! I manually patched in the fix, and now get more detail.

Here is the output for a working example, with long content length:

[HTTP] begin... [HTTP-Client][begin] url: http://192.168.1.7:8000/code/A5-9E-2C-19-21-52 [HTTP-Client][begin] host: 192.168.1.7 port: 8000 url: /code/A5-9E-2C-19-21-52 [HTTP] GET... [HTTP-Client][sendRequest] type: 'GET' redirCount: 0 :ref 1 [HTTP-Client] connected to 192.168.1.7:8000 [HTTP-Client] sending request header

GET /code/A5-9E-2C-19-21-52 HTTP/1.1 Host: 192.168.1.7:8000 User-Agent: Pico Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0 Connection: keep-alive Content-Length: 0

:wr 128 0 :wrc 128 128 0 :wr 48 0 :wrc 48 48 0 :ack 128 :ack 48 :rn 208 :rch 208, 1460 :rch 1668, 1460 [HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK ' [HTTP-Client][handleHeaderResponse] RX: 'date: Fri, 26 Jul 2024 07:57:10 GMT ' [HTTP-Client][handleHeaderResponse] RX: 'server: uvicorn ' [HTTP-Client][handleHeaderResponse] RX: 'custom_headers_test: field for data I might need later ' [HTTP-Client][handleHeaderResponse] RX: 'content-language: en-US ' [HTTP-Client][handleHeaderResponse] RX: 'content-length: 3579 ' [HTTP-Client][handleHeaderResponse] RX: 'content-type: application/json ' :c 1, 208, 3128 [HTTP-Client][handleHeaderResponse] RX: ' ' [HTTP-Client][handleHeaderResponse] code: 200 [HTTP-Client][handleHeaderResponse] size: 3579 [HTTP] GET... code: 200 :c 1, 1460, 2920 :c0 1, 1460 {"message":"<165-158-44-25-33-82-149-189-36-187-35-231-163-248-104-47-252-4-120-32-145-88-109-96-19-1-186-211-172-30-219-226-172-59-35-102-17-140-245-208-177-8-126-131-161-32-78-26-10-43-51-151-38-229-4-168-236-249-116-10-170-235-79-86>","ignore":"A really long string goes here"} [HTTP-Client][end] tcp keep open for reuse :ur 1 :dsrcv 0 :close :del

And below is an example of what I get with the ordinary, short content length (251 bytes in this case). I see it correctly gets the content length, returns HTTP code 200, but then does not display any content! This exactly matches the behavior I'm experiencing in code.

[HTTP] begin... [HTTP-Client][begin] url: http://192.168.1.7:8000/code/A5-9E-2C-19-21-52 [HTTP-Client][begin] host: 192.168.1.7 port: 8000 url: /code/A5-9E-2C-19-21-52 [HTTP] GET... [HTTP-Client][sendRequest] type: 'GET' redirCount: 0 :ref 1 [HTTP-Client] connected to 192.168.1.7:8000 [HTTP-Client] sending request header

GET /code/A5-9E-2C-19-21-52 HTTP/1.1 Host: 192.168.1.7:8000 User-Agent: Pico Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0 Connection: keep-alive Content-Length: 0

:wr 128 0 :wrc 128 128 0 :wr 48 0 :wrc 48 48 0 :ack 128 :ack 48 :rn 207 [HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK ' [HTTP-Client][handleHeaderResponse] RX: 'date: Fri, 26 Jul 2024 08:02:52 GMT ' [HTTP-Client][handleHeaderResponse] RX: 'server: uvicorn ' [HTTP-Client][handleHeaderResponse] RX: 'custom_headers_test: field for data I might need later ' [HTTP-Client][handleHeaderResponse] RX: 'content-language: en-US ' [HTTP-Client][handleHeaderResponse] RX: 'content-length: 251 ' [HTTP-Client][handleHeaderResponse] RX: 'content-type: application/json ' :c0 1, 207 [HTTP-Client][handleHeaderResponse] RX: ' ' [HTTP-Client][handleHeaderResponse] code: 200 [HTTP-Client][handleHeaderResponse] size: 251 [HTTP] GET... code: 200

[HTTP-Client][end] tcp keep open for reuse :ur 1 :dsrcv 0 :close :del

earlephilhower commented 1 month ago

Thanks for the update. There seems to be something specific to your web server. I've got an Apache instance on my server where I posted a simple JSON file, 251 bytes total size. No issues:

[HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK'
[HTTP-Client][handleHeaderResponse] RX: 'Date: Fri, 26 Jul 2024 15:33:31 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'Server: Apache/2.4.41 (Ubuntu)'
[HTTP-Client][handleHeaderResponse] RX: 'Last-Modified: Fri, 26 Jul 2024 15:32:16 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'ETag: "fb-61e28375c7bbb"'
[HTTP-Client][handleHeaderResponse] RX: 'Accept-Ranges: bytes'
[HTTP-Client][handleHeaderResponse] RX: 'Content-Length: 251'
[HTTP-Client][handleHeaderResponse] RX: 'Keep-Alive: timeout=5, max=100'
[HTTP-Client][handleHeaderResponse] RX: 'Connection: Keep-Alive'
[HTTP-Client][handleHeaderResponse] RX: 'Content-Type: application/json'
[HTTP-Client][handleHeaderResponse] RX: ''
[HTTP-Client][handleHeaderResponse] code: 200
[HTTP-Client][handleHeaderResponse] size: 251
[HTTP] GET... code: 200
:c0 1, 542
[HTTP-Client][end] tcp keep open for reuse
{"t":"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}

[HTTP-Client][end] tcp keep open for reuse
:ur 1
:dsrcv 0

Quick wireshark grab shows the header and content sent at once w/Apache: image

I'll take a look thru the logic to see if I can see where this is disconnecting in your case. In the meantime, is it possible to reduce the fastapi.py script you're running into something trivial that you could post. Looks like I can just pip install fastcgi which would let me single step w/GDB thru the code locally. Just have it returned a fixed JSON that causes the non-response and we'd have a good testbed.

earlephilhower commented 1 month ago

I just installed FastAPI and ran their dummy sample from their home page. It returns a JSON file of something like 30 bytes and always works here. So, I think I'll need a .PY from you to trace locally....can't make it fail...

[HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK'
[HTTP-Client][handleHeaderResponse] RX: 'date: Fri, 26 Jul 2024 16:09:27 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'server: uvicorn'
[HTTP-Client][handleHeaderResponse] RX: 'content-length: 29'
[HTTP-Client][handleHeaderResponse] RX: 'content-type: application/json'
[HTTP-Client][handleHeaderResponse] RX: ''
[HTTP-Client][handleHeaderResponse] code: 200
[HTTP-Client][handleHeaderResponse] size: 29
[HTTP] GET... code: 200
:c0 1, 154
[HTTP-Client][end] tcp keep open for reuse
{"item_id":5,"q":"somequery"}
[HTTP-Client][end] tcp keep open for reuse
:ur 1
:dsrcv 0
:close
:del
seanboyce commented 1 month ago

OK, that's fascinating! It does sound like something is unusual with my webserver. However, even when I reduce it down to the most basic case, it still fails in the same way (but only on the Pico, on all other platforms it works OK):

from fastapi import Depends, FastAPI, HTTPException, Request, Response, status
from fastapi.responses import HTMLResponse,JSONResponse

app = FastAPI()

@app.get("/test", response_class=HTMLResponse)
async def test_pico(request: Request):
    data = "test"
    return data

In case it matters, I launch the server with:

uvicorn apitest.main:app --host 0.0.0.0 --port 8000 --reload

In the console, FastAPI returns no errors -- only " INFO: 192.168.1.5:56670 - "GET /test HTTP/1.1" 200 OK" which is exactly as expected.

The simpler test case did let me identify the exact content length required for success -- exactly 1460 characters, which is exactly equal to the TCP maximum segment size. Anything greater will split into 2 packets, and everything works normally! I will do some digging on my end. If I uncover something I will post it here.

seanboyce commented 1 month ago

OK I have found something very interesting. By trial and error, I've found that by manually setting the content-length header server-side, I can force it work. The content-length must be at least the length of the response data + 3. For example, the string "test" must be content-length 7 or more. The webserver will return warnings, but it will comply and send the content-length this way. See below:

from fastapi import Depends, FastAPI, HTTPException, Request, Response, status
from fastapi.responses import HTMLResponse,JSONResponse

app = FastAPI()

#working case
@app.get("/test", response_class=HTMLResponse)
async def test_pico(request: Request):
    content="test"
    content_length = len(content) + 3
    headers = {"Content-Length": str(content_length)}
    return JSONResponse(content=content, headers=headers)

#fail case
@app.get("/fail", response_class=HTMLResponse)
async def fail_pico(request: Request):
    content="test"
    #this will provide content length = 4, which will fail! Content length must be equal to at least string length + 3!
    return JSONResponse(content=content, headers=headers)
earlephilhower commented 1 month ago

I think the difference is that you've got an async callback which is going to change the network operation a lot, whereas the example FastAPI uses (and Apache and other web servers) does the CGI/etc. synchronously. That's something to look at. The way it goes to sleep may make the Pico think there is no more data available(i.e. a short read...it was hoping for 200 content bytes but got 0)

earlephilhower commented 1 month ago

(Oh and FYI GH uses Markdown, not HTML, so 4-bacticks (````) are what start or stop a code section)

earlephilhower commented 1 month ago

Sorry, still unable to reproduce your problem. I ran your script:

earle@amd:~/Arduino/hardware/pico/rp2040$ cat /tmp/go1.py 
from fastapi import Depends, FastAPI, HTTPException, Request, Response, status
from fastapi.responses import HTMLResponse,JSONResponse

app = FastAPI()

@app.get("/test", response_class=HTMLResponse)
async def test_pico(request: Request):
    data = "test"
    return data

With the following command line

earle@amd:~/Arduino/hardware/pico/rp2040$ /home/earle/.local/bin/fastapi run /tmp/go1.py --host 0.0.0.0 --port 8921
INFO     Using path /tmp/go1.py                                                                                                                                                                                                                                                                                                                                                                                                                                                              
INFO     Resolved absolute path /tmp/go1.py                                                                                                                                                                                                                                                                                                                                                                                                                                                  
INFO     Searching for package file structure from directories with __init__.py files                                                                                                                                                                                                                                                                                                                                                                                                        
INFO     Importing from /tmp                                                                                                                                                                                                                                                                                                                                                                                                                                                                 

 ╭─ Python module file ─╮                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
 │                      │                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
 │  🐍 go1.py           │                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
 │                      │                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
 ╰──────────────────────╯                                                                                                                                                                                                                                                                                                                                                                                                                                                                    

INFO     Importing module go1                                                                                                                                                                                                                                                                                                                                                                                                                                                                
INFO     Found importable FastAPI app                                                                                                                                                                                                                                                                                                                                                                                                                                                        

 ╭─ Importable FastAPI app ─╮                                                                                                                                                                                                                                                                                                                                                                                                                                                                
 │                          │                                                                                                                                                                                                                                                                                                                                                                                                                                                                
 │  from go1 import app     │                                                                                                                                                                                                                                                                                                                                                                                                                                                                
 │                          │                                                                                                                                                                                                                                                                                                                                                                                                                                                                
 ╰──────────────────────────╯                                                                                                                                                                                                                                                                                                                                                                                                                                                                

INFO     Using import string go1:app                                                                                                                                                                                                                                                                                                                                                                                                                                                         

 ╭─────────── FastAPI CLI - Production mode ───────────╮                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │                                                     │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │  Serving at: http://0.0.0.0:8921                    │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │                                                     │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │  API docs: http://0.0.0.0:8921/docs                 │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │                                                     │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │  Running in production mode, for development use:   │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │                                                     │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │  fastapi dev                                        │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 │                                                     │                                                                                                                                                                                                                                                                                                                                                                                                                                     
 ╰─────────────────────────────────────────────────────╯                                                                                                                                                                                                                                                                                                                                                                                                                                     

INFO:     Started server process [3658966]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:8921 (Press CTRL+C to quit)
INFO:     192.168.1.138:55162 - "GET /test HTTP/1.1" 200 OK

I'm running the example INO you posted, only renamed the IP/port/filename to match. And I'm always getting a proper response:

-----
GET /test HTTP/1.1
Host: 192.168.1.8:8921
User-Agent: Pico
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Connection: keep-alive
Content-Length: 0

-----
:wr 128 0
:wrc 128 128 0
:wr 30 0
:wrc 30 30 0
:ack 128
:ack 30
:rn 136
[HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK'
[HTTP-Client][handleHeaderResponse] RX: 'date: Sat, 27 Jul 2024 05:11:25 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'server: uvicorn'
[HTTP-Client][handleHeaderResponse] RX: 'content-length: 4'
[HTTP-Client][handleHeaderResponse] RX: 'content-type: text/html; charset=utf-8'
[HTTP-Client][handleHeaderResponse] RX: ''
[HTTP-Client][handleHeaderResponse] code: 200
[HTTP-Client][handleHeaderResponse] size: 4
[HTTP] GET... code: 200
:c0 1, 136
[HTTP-Client][end] tcp keep open for reuse
test
[HTTP-Client][end] tcp keep open for reuse
:ur 1
:dsrcv 0
:close
:del

I uses PIP on Ubuntu 20.04 to install the FastAPI version, maybe that's different here...

earle@amd:~/Arduino/hardware/pico/rp2040$ /home/earle/.local/bin/fastapi --version
FastAPI CLI version: 0.0.4
seanboyce commented 1 month ago

OK I tried just hosting a static index.html on my machine that only contains the text "test", and served it on port 80 with apache2. The issue persists. So it's not a problem unique to FastAPI.

I also tried removing the 'async' from the fastAPI example, but no difference.

Given how well it works on your end (and with the same code!), I think we can conclude this is a problem with my setup -- although I'm at a loss as to exactly what it is. I will likely just push the code onto a VPS with a fresh environment. I bet it will just work.

I appreciate your help very much! If you want to mark this as closed, and I figure out exactly what caused this later on, I will raise a separate item if I uncover something materially interesting.

(ah, FOUR backticks! Another content-length issue on my part, haha. I tried with too few.)

earlephilhower commented 1 month ago

Yeah, sorry but I really don't have anything to go on here. If you do get anything, do let us know!