POST request using ESP32 to Fauxmo works when running Fauxmo with -vvv but not -vv
Opened this issue · 26 comments
- Issues not following the template may be closed for that reason alone.
- Operating system and version: Raspberry Pi Bookworm
- Python version: 3.11
- Fauxmo version (
fauxmo --version): v0.8.0 - Echo device type (e.g. Echo, Echo Plus, Dot): Echo
- Echo Firmware Version:
My Issue
I built a request sent via an ESP32 to Fauxmo on my locl network.
The request WORKS when I run Fauxmo in triple V (-vvv) mode but not when I run Fauxmo with two: (-vv)
In more detail the request is recognized in both instances, but the data of the request is not seen with the -vv.
Maybe there is a delay or timing issue?
In -vvv mode Fauxmo read the whole request, but when in -vv the udp read gets stopped?
WHYT
I tried adding more debug "warning" points in protocols.py dumping the "msg" variable.
With "-vvv" I get the whole message as sent with the POST request data.
With "-vv" I get the same headers etc. but not the POST request data.
Please make sure you've taken these steps before submitting a new issue:
- [X ] Try to reproduce the issue with Fauxmo installed in a
venv - [ X] Ensure you're running a supported version of Python
- Requires Python >= 3.2 for Fauxmo < 0.3.0
- Requires Python >= 3.4.4 for Fauxmo >= 0.3.0
- Requires Python >= 3.6.0 for Fauxmo >= 0.4.0
- [X ] Run Fauxmo in debug mode (
-vvv) and include relevant output (see comments) - Include your Fauxmo
config.json(not needed) - [ X] Search the existing (including closed) issues
- [ X] Please use codeblocks around your debug output and config
Sorry you're having trouble. I'm not sure that I understand your question or what is going on.
In more detail the request is recognized in both instances, but the data of the request is not seen with the -vv.
It sounds like you're describing the intended behavior.
There is no difference in behavior based on whether you use -vvv or some other logging level; adding extra -vs just increases the verbosity of the logging output.
I understand what you are describing. That's what I expected.
I placed a logger.warning() to get this in protocols.py data_received() at the elif msg.startswith("POST /upnp/control/basicevent1 HTTP/1.1") I did this to see the full msg contents.
When I run in -vv mode I get from the debug output all but the Contents:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.99.181:49915
User-Agent: ESP32HTTPClient [these 3 lines are inserted]
Connection: keep-alive Set by sendHeader depensing on setReuse
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Content-Length: 298
With no content showing.
When I run with -vvv I get Contents. Nothing else changed except going from -vv to -vvv:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.99.181:49915
User-Agent: ESP32HTTPClient
Connection: keep-alive
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Content-Length: 298
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:SetBinaryState></s:Body></s:Envelope>
So as you can see I get the full 298 character content that was sent following the POST...Content-Length section.
Nothing changes on the sender side either. So I am guessing maybe the -vvv somehow slows the read of the UDP request enough so it gets the full request with the Contents before moving on. I'm not familiar with the asyncio process and how it effects timing.
Thanks for the quick reply!
I'm sorry, I'm still not sure that I understand what your question is, or what behavior you're seeing that is unexpected.
Can you give me an example?
- What do you say?
- What do you expect to happen?
- What actually happens?
Also, you haven't included your config or debug logs as requested, which makes it much harder for me to understand what's going on.
Thank so much. Trying to get you what I am referring to.
First, Fauxmo works fine with Alexa, so that is not an issue. It works as expected.
I expect the Fauxmo to respond to an HTTP POST. It works with Curl on Windows and now am trying from a microcontroller.
This issue happens when I am trying to get it to respond to a HTTP POST sent from an ESP32 microcontroller.
The POST headers and contents I showed above with the issue being it doesn't work with "-v or -vv" but it does with "-vvv"
Using "-v" The systemctl output is:
fauxmo:199 WARNING Unable to complete command
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.99.181:49915
User-Agent: ESP32HTTPClient [these 3 lines are inserted]
Connection: keep-alive Set by sendHeader depensing on setReuse
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Content-Length: 298
The config.json:
{ "FAUXMO": { "ip_address": "auto" }, "PLUGINS": { "CommandLinePlugin": { "timeout": 5, "DEVICES": [ { "name": "Study", "port": 49915, "on_cmd": "/home/pi/Documents/Commands/iq_study.sh 1", "off_cmd": "/home/pi/Documents/Commands/iq_study.sh 2", "initial_state": "off", "use_fake_state": true }, ...
I am not sure where to get the debug logs other than the systemctl output and when I run fauxmo manually the outpur from there.
Interesting.
To make sure I understand:
- You have fauxmo set up and working as expected via Alexa
- You are able to simulate a
POST(as if it were from Alexa) to fauxmo from Windows and trigger a command - You are able to simulate a
POST(as if it were from Alexa) to fauxmo from a ESP32 and trigger a command, but only if you have debug logging enabled on the fauxmo
Does this sound correct? If so, that is indeed an odd issue, and I don't have any great ideas.
- What library are you using to issue the
POSTrequest from the ESP32? - Can you set up a fake fauxmo with e.g.
ncatand inspect the contents of thePOSTrequest?
Out of curiosity, what is your use case for having an ESP32 issue commands to Fauxmo?
Is this an intermittent problem? Or does it fail every time without verbose logging and succeed every time with verbose logging?
I am not sure where to get the debug logs other than the systemctl output
Yes, your journald output is the next step.
Yes you understand correctly: all the 3 instances are correct.
I am using the Espressif library 3.0.0 (the latest) with HTTPclient POST call.
Re Ncat, I' not sure how to do that but can look into it.
I did get a log from the ESP32 side and when it doesn't work with "-vv" I get a "connection closed" error.
It's not intermittent - it doesn't work all the time with "-vv", and works all the time with fauxmo "-vvv"
Use case: Trying to setup a remote button system to initiate a fauxmo events using the ESP32. I wish there was a more simple REST way to do it since it's all on the same local network.
My guess as to the issue: with "-vvv" the UPD read stays open longer but with "-vv" the port closes faster so fauxmo doesn't get the final "data" section of the request. My pyhon for fauxmo is 3.11. I was thinking I could put some sort of delay in the UDP read, but I'm not sure where / how to do that.
Same results on debug showing in the journal as the debug.
Interesting setup.
I'm not sure how to help. I don't know what to think about your speculation about the UDP read staying open longer -- I would be surprised to discover that it changed behavior this way, and I don't think that part of the exchange is occurring on UDP. Be sure to review the protocol_notes.
There are a few versions of netcat (nc, ncat, netcat), and I can never remember the nuances between them, but you can use it to open / listen to a port and see what data is being sent.
I think something like nc -l -u -p 2345 should set it up in -listening mode, for -udp on -port 2345. If I run that on one terminal, then run echo foo | nc -u localhost 2345 on another terminal, I can see foo appear on the listening side.
Update on sending a POST to Fauxmo:
What I tested to see if the POST message comes through:
A Curl from windows and another Raspberry Pi works.
I did the netcat on the Fauxmo Raspberry Pi and saw the full message.
I created a simple python server on the Fauxmo Raspberry Pi using same port and got the whole message.
What did not work:
I created a simple asyncio server on the Fauxmo Raspberry Pi and that did NOT get the whole message.
I tried posting from another arduino (UNO) which is slower than the ESP32 and I got LESS of the message from asyncio, so it seems speed of sending matters.
Conclusion:
Somehow asyncio has less "patience" on getting the full POST message and closes the connection early.
I need to move my project from ESP32 to a Raspberry Pi so the Fauxmo asyncio can get the whole message in time.
Interesting, thanks for following up. Can you post your code for the "simple asyncio server"?
Here is the code:
port = 49915
myIP = '192.168.XX.XXX'
localhost = '127.0.0.1'
import asyncio
class EchoServerProtocol(asyncio.Protocol):
def connection_made(self, transport):
peername = transport.get_extra_info('peername')
print('connection_made: Connection from {}'.format(peername))
self.transport = transport
def data_received(self, data):
#print(f"data_received: self_eof_received: {self.eof_received()}") # comes back "None"
message = data.decode()
#self.transport.resume_reading() #CL tried - doesn't help
#print('Data received: {!r}'.format(message))
print(f"Data received: \n{message}\n")
if "SetBinaryState" in message: # Special filter to see just the ESP32, normally see ALL requests
print(f"SetBinaryState Data received: ************************ \n{data}\n")
if 1==1 and "SetBinaryState" in message: # Skip echo if 1==2
#print('Echo back: {!r}'.format(message))
print(f"SetBinaryState found: Sending: \n{message}\n")
self.transport.write(data)
print('Close the client socket')
self.transport.close()
async def main():
# Get a reference to the event loop as we plan to use
# low-level APIs.
print("Starting V1 Fauxmo version: asyncio server")
loop = asyncio.get_running_loop()
server = await loop.create_server(
lambda: EchoServerProtocol(),
myIP, port)
print(f"Main: Server and port: {myIP}, {port}\n")
async with server:
await server.serve_forever()
asyncio.run(main())
I also tried the "await" approach using reader.read():
port = 49915
myIP = '192.168.XXX.XXX'
localhost = '127.0.0.1'
import asyncio
async def handle_echo(reader, writer):
data = await reader.read(4000) #This was 100 and "()" does not work at all
message = data.decode()
addr = writer.get_extra_info('peername')
#print('Data received: {!r}'.format(message))
print(f"Data received: \n{message}\n")
if "SetBinaryState" in message: # Special filter to see just the ESP32, normally see ALL requests
print(f"SetBinaryState Data received: ************************ \n{data}\n")
print(f"SetBinaryState found: decode() version: \n{message}\n")
"""
print(f"Send: {message!r}")
writer.write(data)
await writer.drain()
print("Close the writer connection")
writer.close()
await writer.wait_closed()
"""
async def main():
print("Starting V2: asyncio with reader.read server")
server = await asyncio.start_server(
handle_echo, myIP, port)
addrs = ', '.join(str(sock.getsockname()) for sock in server.sockets)
print(f'Serving on {addrs}')
async with server:
await server.serve_forever()
asyncio.run(main())
Missing a bit -- pi3 is undefined. Is that supposed to be myIP?
Not sure if you're familiar with wireshark and/or tcpdump, but they might be helpful as well.
What happens if you add a connection_lost handler? Seems like I have one for the UDP part of the exchange but not the TCP part where you're seeing the issues -- perhaps adding one to your test server would show you if there is some interruption in the connection?
I fixed the code so it has myIP. I was making it generic when I posted the reply and missed that - thanks :)
Will try your suggestions.
Since netcat gets the whole message, I don't think there is any issues with the message getting to the destination IP.
Addendum: I ran my simple test simple server on a Windows machine (much faster than the RPi. Same result - a truncated message.
Any updates? Were you able to try the connection_lost handler?
No success...
I had this in my test code and it didn't get there:
def connection_lost(self, exc: Exception | None) -> None:
"""Handle lost connections.
Args:
exc: Exception type
"""
if exc:
logger.warning(f"SSDPServer closed with exception: {exc}")
Could you host a full copy of your ESP32 code for me somewhere? I have a few of them sitting around and may be able to test locally, as I'm not sure how I can help you debug this further remotely.
Here is a generic version of the code (ZIP file) (needs a SSID, PW and IP/PORT for testing). I used an Adafruit QT Py ESP32 with a neopixel for status. Let me know you got his OK.
Thanks for the firmware. I've simplified a bit to work on a generic ESP32 and can confirm -- it works intermittently with -vvv (like 1/10 times) but not without. I'm sure you're right that this has something to do with timing.
Curiously the fauxmo logs do not report the message body when it fails:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.0.113:48686
User-Agent: ESP32HTTPClient
Connection: keep-alive
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Accept: */*
Content-Length: 299
But include the body when it succeeds:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.0.113:48686
User-Agent: ESP32HTTPClient
Connection: keep-alive
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Accept: */*
Content-Length: 299
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/ "s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:SetBinaryState></s:Body></s:Envelope>
I'm not sure why that would be.
Yes, that is the issue.
It seems that the Python process gives up too early and I tried to see if there was some way to wait for the message body, but nothing worked. At least you could see firsthand what I was experiencing. Not your code but the Python process being impatient I beleive.
By removing all delays from the ESP32 code it is able to turn on a switch without any -v flags, but it takes many tries (I moved the http.POST call into the main loop).
Trying to find documentation on this library is tough. I found for example the HTTPC_ERROR_CONNECTION_LOST -5 constant defined at https://github.com/espressif/arduino-esp32/blob/master/libraries/HTTPClient/src/HTTPClient.h . Have you found any other official documentation for this library?
That's the disconnect error I see too. That is the best doc I could find. I also see it working (mostly) with "-vvv".
Again, my guess it has something to do with the Python asyncio and how it doesn't wait long enough and not the fauxmo code.
Been a while but I do recall testing variations of the fauxmo code in "protocols.py" to see if there was a way to wait longer. No luck.
Well, I got totally nerd sniped by this and spent way too much time tinkering with the ESP32 over the last few days. I think I have a probable solution, but I'm not planning to implement it myself at this time as it requires a number of changes and is a niche / unsupported use-case that hasn't presented an issue over the last ~7 years of using Fauxmo. I wanted to lay out my general ideas in case someone wanted to make an attempt at implementing this.
It seems that the request from the ESP32 is (usually) getting split into two separate calls to Fauxmo::data_received; the first contains the headers, the second has the POST body. It occasionally all gets read into a single request, in which case it works. Increasing logging verbosity seems to be slowing down the asyncio loop enough that the full request is available to read in a single call. (At least this is my working theory.)
It may be possible to optimize HTTPClient.cpp to speed up its requests and allow the full request to be read in a single call, but I'm no expert here.
The better / correct way to do this would be to improve Fauxmo's http parsing; it currently doesn't parse things at all, just kind of looks at a request to see if it "seems" like a POST request to turn something on / off (or do something else). If it looks like this is the case, it performs the action and closes the connection.
The improvement here would require several changes to the Fauxmo protocol / class. It seems like a single Fauxmo instance is used per connection, so some state to track the full request would probably resolve the issue. I'm no expert here, but this is how I think it should work:
- the request should be attempted to be parsed as verb + http headers
- if successful, the
Content-Lengthheader should be parsed and stored as an attribute - the request "body" should be read; if the length matches
Content-Length, it should be processed and the connection closed (and probably some kind of200response send back to the device) - if the full content length isn't reached, the data (as bytes) should be stored as an attribute for further processing, as should the verb and anything required to parse this as the start of a valid Fauxmo http request
- if successful, the
- if not successfully parsed as headers, it should be presumed to be the rest of the message body
- in this case the data should be appended to the stored data attribute and again content-length compared, if the full content length is reached then go ahead with processing
At least this is the best idea I've had so far. If implemented, I would insist on keeping fauxmo free of external dependencies; python has some stdlib utility classes / functions that would help, such as email.message_from_bytes vs subclassing http.server.BaseHTTPRequestHandler (https://stackoverflow.com/a/5955949/1588795).
I'll leave this issue open for a couple weeks to see if there is interest; if not will plan to close as unplanned.
YAY! I got it to work and there is NO required code change for Fauxmo.
n8henrie you got me thinking that there was something weird with how the ESP32 http library sends data (headers then body of the POST later) - thank you!
So I changed the code (sent above) so that after the regular headers are setup with http.addHeader(), I created another header with the intended POST body string http.addHeader(" ",postData);.
and for the POST I simply made it send a space character: int httpResponseCode = http.POST(" ");
So essentially the POST information is all headers and a simple space in the body.
This gets around the seemingly two-part send from ESP32 http POST which causes the Python asyncio to close and Fauxmo has no problem receiving the full command.
It's a kludge but I'm glad it does not involve anything more than the ESP32 code change.
Ha! How clever! It's no more of a kludge than fauxmo's "parsing" of the http request. Well done.