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

empty http responses (ESPEasy 2.0 on SONOFF basic) #1066

Closed
pljakobs opened this issue Mar 12, 2018 · 29 comments
Closed

empty http responses (ESPEasy 2.0 on SONOFF basic) #1066

pljakobs opened this issue Mar 12, 2018 · 29 comments

Comments

@pljakobs
Copy link

pljakobs commented Mar 12, 2018

Steps to reproduce

Build the current 2.0 branch for 1024kB/DOUT and flash to a SONOFF basic (integrated ESP8266 relay)
on any linux system go
'''wget -O - http:///control?cmd=status,gpio,12'''
watch an empty reply probably 7 out of 8 times
problem is reproducible after reboots, soft and hard on two different SONOFF boards

Expected behavior

Should respond with a json structure describing the state of gpio 12

Actual behavior

Empty response:

Hypertext Transfer Protocol
    HTTP/1.1 200 OK\r\n
    Content-Type: application/json\r\n
    Content-Length: 0\r\n
    Connection: close\r\n
    Access-Control-Allow-Origin: *\r\n
    \r\n
    [HTTP response 1/1]
    [Time since request: 0.009015000 seconds]
    [Request in frame: 126]

after that, the browser sends a fin ack and ESPEasy responds with a rst ack
from the ESPEasy log:

EVENT: Clock#Time=Mon,09:40
EVENT: Clock#Time=Mon,09:40 Processing time:90 milliSeconds
sendcontent free: 18184 chunk size:340
WD   : Uptime 34 ConnectFailures 0 FreeMem 18576
sendcontent free: 18184 chunk size:340
sendcontent free: 17736 chunk size:388
sendcontent free: 17736 chunk size:382
sendcontent free: 17736 chunk size:387
sendcontent free: 17736 chunk size:393
sendcontent free: 17736 chunk size:389
sendcontent free: 17488 chunk size:391
sendcontent free: 17536 chunk size:391
sendcontent free: 17520 chunk size:373
sendcontent free: 18088 chunk size:427
sendcontent free: 18064 chunk size:424
sendcontent free: 18072 chunk size:388
sendcontent free: 18040 chunk size:454
sendcontent free: 18088 chunk size:412
sendcontent free: 18112 chunk size:259
sendcontent free: 18112 chunk size:0
Ram usage: Webserver only: 344 including Core: 0
sendcontent free: 18184 chunk size:340
WD   : Uptime 35 ConnectFailures 0 FreeMem 18328
sendcontent free: 18184 chunk size:340
EVENT: Clock#Time=Mon,09:41
EVENT: Clock#Time=Mon,09:41 Processing time:91 milliSeconds
sendcontent free: 18184 chunk size:340
WD   : Uptime 35 ConnectFailures 0 FreeMem 18576
sendcontent free: 18184 chunk size:340

System configuration

Hardware:

SONOFF Basic
Software or git version:
Built off a git pull from the v2.0 branch on Sunday, March 11th

System  
Build 20000
Git Build ""
Local time "2018-03-12 09:40:27"
Unit 11
Uptime 34
Free RAM 18216
Sensors  
0  
tasknr 1
TaskName "button"
Type "Switch input - Switch"
state 0
1  
tasknr 2
TaskName "relay"
Type "Switch input - Switch"
state 0
@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

Do you have any idea when this got 'broken'?
What version did work?

@pljakobs
Copy link
Author

pljakobs commented Mar 12, 2018

@TD-er it's my first try to use the current V2 branch on a sonoff. All the tutorials I found were based on the older 120 build. Funny thing is: it works once in every few attempts, I don't think I have a "good" response captured in the debug log, though.

I should say there seem to be some more issues, either with the flash chip or the wlan implementation, uploading the config.dat takes ~30 seconds

It's really odd, actually triggering the GPIOs via http works just fine, the web server responses are what is unpredictable.

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

The 'funny' thing is that we're using two kinds of 'webservices' to serve data.
The one from the commands is a streaming one. The same as the regular web pages.
This one sends 'Chunked-transfer' to save big on memory usage.
The "old" one is still (actually again) used on the url http://<hostname>/json
Could you try that one to see if curl accepts it?
Maybe there is an option in Curl to expect chunked transfers?

@pljakobs
Copy link
Author

ok, /json?cmd=status,gpio,12 works in 100% of the cases.

@pljakobs
Copy link
Author

looking at my debug data further up:
wireshark shows that "content length" is set to 0 but the ESP debug shows that the chunk size is in the 400 byte range, which would be consistent with the json payload.
I havn't looked at the code, but

  • is the chunk size printed after the chunk has been assembled in memory?
  • is the chunk size correctly put into the http header?
  • there is one line with "chunk size 0" - not sure what that was..

@pljakobs
Copy link
Author

I guess this is where it all happens:

void sendContentBlocking(String& data) {
  checkRAM(F("sendContentBlocking"));
  uint32_t freeBeforeSend = ESP.getFreeHeap();
  String log = String("sendcontent free: ") + freeBeforeSend + " chunk size:" + data.length();
  addLog(LOG_LEVEL_DEBUG_DEV, log);
  freeBeforeSend = ESP.getFreeHeap();
  if (TXBuffer.beforeTXRam > freeBeforeSend)
    TXBuffer.beforeTXRam = freeBeforeSend;
  TXBuffer.duringTXRam = freeBeforeSend;
#if defined(ESP8266) && defined(ARDUINO_ESP8266_RELEASE_2_3_0)
  String size = String(data.length(), HEX) + "\r\n";
  // do chunked transfer encoding ourselves (WebServer doesn't support it)
  WebServer.sendContent(size);
  if (data.length()) WebServer.sendContent(data);
  WebServer.sendContent("\r\n");
#else  // ESP8266 2.4.0rc2 and higher and the ESP32 webserver supports chunked http transfer
  unsigned int timeout = 0;
  if (freeBeforeSend < 5000) timeout = 100;
  if (freeBeforeSend < 4000) timeout = 1000;
  const uint32_t beginWait = millis();
  WebServer.sendContent(data);
  while ((ESP.getFreeHeap() < freeBeforeSend) &&
         !timeOutReached(beginWait + timeout)) {
    if (ESP.getFreeHeap() < TXBuffer.duringTXRam)
      TXBuffer.duringTXRam = ESP.getFreeHeap();
    ;
    TXBuffer.trackCoreMem();
    checkRAM(F("duringDataTX"));
    delay(1);
  }
#endif

  TXBuffer.sentBytes += data.length();
  data = "";
}

Looks like the debug output would happen whether there's enough free heap or not, although the resulting log shows that there clearly is enough heap.
Here's my PIO environment: I wonder, it states that there would be espressiv 1.5.0 and 1.6.0 environments availalbe, but I'm not sure if either defines ARDUINO_ESP8266_RELEASE_2_3_0?

Windows PowerShell
Copyright (C) Microsoft Corporation. Alle Rechte vorbehalten.

PS C:\Users\cn-0f27dt-f1167-1bi-\Documents\GitHub\ESPEasy> platformio update
Updating tool-scons                      @ 2.20501.4      [Up-to-date]
Updating tool-unity                      @ 1.20302.1      [Up-to-date]
UUpdating contrib-pysite                  @ 0.1.5
[Up-to-date]
Updating contrib-piohome                 @ 0.7.1          [0.8.1]
Uninstalling contrib-piohome @ 0.7.1:   [[OK]
CorePackageManager: Installing contrib-piohome @ 0.8.1
Downloading...
Unpacking...
contrib-piohome @ 0.8.1 has been successfully installed!
Updating tool-pioplus                    @ 0.14.4         [Up-to-date]


Platform Manager
================
Platform Espressif 8266
--------
Updating espressif8266                   @ 1.6.0          [Up-to-date]
Updating tool-esptool                    @ 1.409.0        [Up-to-date]
UUpdating toolchain-xtensa                @ 1.40802.0
[Up-to-date]

Platform Espressif 8266
--------
Updating espressif8266                   @ 1.5.0          [Fixed]
Updating tool-mkspiffs                   @ 1.102.0        [Up-to-date]
Updating tool-esptool                    @ 1.409.0        [Up-to-date]
Updating tool-espotapy                   @ 1.0.0          [Up-to-date]
Updating framework-arduinoespressif8266  @ 1.20300.1      [Up-to-date]
Updating toolchain-xtensa                @ 1.40802.0      [Up-to-date]

@Grovkillen
Copy link
Member

Regarding the Status command... It doesn't seem to work properly. If I use pulse commands etc the state is kept "1" even if the state is going back to "0" after the duration has ended.

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

I wonder, it states that there would be espressiv 1.5.0 and 1.6.0 environments availalbe, but I'm not sure if either defines ARDUINO_ESP8266_RELEASE_2_3_0?

Platform IO 1.5.0 uses Arduino ESP8266 core 2.3.0
Platform IO 1.6.0 uses Arduino ESP8266 core 2.4.0

The last one is not being used in the builds we make, since 2.4.0 gives some strange issues with respect to the internal LWIP library used. (although it is much faster)

@pljakobs
Copy link
Author

it seems that neither the command? nor the json? url triggers the sendContentBlocking code...
I can't say I understand this part of the code

void handle_control() {
  //TXBuffer.startStream(true); // true= json
 // sendHeadandTail(F("TmplStd"),_HEAD);

  String webrequest = WebServer.arg(F("cmd"));

  // in case of event, store to buffer and return...
  String command = parseString(webrequest, 1);
  if (command == F("event"))
  {
    eventBuffer = webrequest.substring(6);
    WebServer.send(200, "text/html", "OK");
    return;
  }

  struct EventStruct TempEvent;
  parseCommandString(&TempEvent, webrequest);
  TempEvent.Source = VALUE_SOURCE_HTTP;

  printToWeb = true;
  printWebString = "";

  String log = String("TempEvent: ") + TempEvent.Source + String(":") + TempEvent.ControllerIndex + String(" webrequest:") + webrequest;
  addLog(LOG_LEVEL_DEBUG_DEV, log);

  if (PluginCall(PLUGIN_WRITE, &TempEvent, webrequest));
  else if (remoteConfig(&TempEvent, webrequest));
  else
    TXBuffer += F("Unknown or restricted command!");
  log = String("Plugin response: ") + printWebString;
  addLog(LOG_LEVEL_DEBUG_DEV, log);
  TXBuffer +=  printWebString;

  if (printToWebJSON)
    WebServer.send(200, "application/json");
  else
    WebServer.send(200, "text/html");

  printWebString = "";
  printToWeb = false;
  printToWebJSON = false;
}

the debug output here is the expected json, however it seems to never make it to the web response.
I don't see sendContentBlocking being called, am I missing something obvious or is there a line missing like
WebServer.send(200, TXBuffer);

@pljakobs
Copy link
Author

oh interesting, I just managed to capture a "good" (well, not so, maybe) response, that is, a reply that is not empty:

14f
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}

HTTP/1.1 200 OK
Content-Type: application/json
Content-Length: 0
Connection: close
Access-Control-Allow-Origin: *

Two things:

  1. this is multiple responses wrapped into one
  2. this time, my debug lines in the handle_control routine did actually not show that the plugin was queried at all, but the sendContentBlocking code was.
    That would, in my mind, point to the bug really being that the TXBuffer is neither sent nor cleared by the handle_control routine, right?
    (sorry for my verbose troubleshooting here, I really don't know the structure of ESPEasy yet)

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

Can you check the info page in the Tools tab?
There is an entry stating the used core library.
Based on the "14f" at the top of your message, I suspect you're using core 2.4.0 instead of core 2.3.0

@pljakobs
Copy link
Author

Firmware
--
Build | 20000  - Mega (core 2_3_0)
GIT version |  
Plugins | 46 [Normal]

don't think so.

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

The thing is, the hex value at the start, is some indication of the chunk size.
So this is a chunked transfer issue.
For Chunked transfers, the header should not give a "Content-Length" entry, but apparently you see one.
I've set the expected size to "unknown" before sending, to suppress this header sent by the core library.
But if I remember correctly, that's only being dealt with when you do HTTP 1.1 transfers.
Maybe you're doing HTTP 1.0 transfers, which isn't checked for in ESPeasy? (chunked transfers are not part of HTTP 1.0)

@pljakobs
Copy link
Author

in the first post, I have a snippet from wireshark - at least the response header sais http 1.1

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

Can you change something in these two lines:

StreamingBuffer operator= (String& a) { flush(); return addString(a); }
StreamingBuffer operator= (const String& a) { flush(); return addString(a); }

Change flush(); into this->buf = "";

@pljakobs
Copy link
Author

pljakobs commented Mar 12, 2018

in the version that I have checked out, this looks like this:

  StreamingBuffer operator= (String& a)                 { this->buf=a;           checkFull();  return *this;  }
  StreamingBuffer operator= (const String& a)           { this->buf=a;           checkFull();  return *this;  }
  StreamingBuffer operator+= (long unsigned int  a)     { this->buf+=String(a);  checkFull();  return *this;  }
  StreamingBuffer operator+= (float a)                  { this->buf+=String(a);  checkFull();  return *this;  }
  StreamingBuffer operator+= (int a)                    { this->buf+=String(a);  checkFull();  return *this;  }
  StreamingBuffer operator+= (uint32_t a)               { this->buf+=String(a);  checkFull();  return *this;  }

and for completeness: this is the original request, so it's all http 1.1

Hypertext Transfer Protocol
    GET /control?cmd=status,gpio,12 HTTP/1.1\r\n
    Host: 192.168.29.220\r\n
    User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:58.0) Gecko/20100101 Firefox/58.0\r\n
    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\n
    Accept-Language: de,en-US;q=0.7,en;q=0.3\r\n
    Accept-Encoding: gzip, deflate\r\n
    Connection: keep-alive\r\n
    Upgrade-Insecure-Requests: 1\r\n
    Cache-Control: max-age=0\r\n
    \r\n
    [Full request URI: http://192.168.29.220/control?cmd=status,gpio,12]
    [HTTP request 1/1]
    [Response in frame: 127]

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

That flush part, I added yesterday, so it should be included in the latest builds. (saves the trouble of building yourself)
That's why I asked to somewhat revert that change.
The reason I added the flush is that I found it odd to throw away something in the send buffer. If it was there, it should be sent to the client instead of throwing it away if someone is using TX_buffer = instead of +=.

@pljakobs
Copy link
Author

ok, then I'll pull in upstream again and see if there's change.

@pljakobs
Copy link
Author

pljakobs commented Mar 12, 2018

right, pulled the upstream v2.0 branch again, the flush(); is now in, the result is unchanged.
I get a number of empty replies and then this:

190
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}
{
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0

HTTP/1.1 200 OK
Content-Type: application/json
Content-Length: 0
Connection: close
Access-Control-Allow-Origin: *

The behaviour is very predictable:
for the first five times I call this url, I get an empty response, on the sixth attempt, I get the rollup content of all six requests in one response. It would seem that calling this handler for some reason does just not send the html response until the chunk is full or so?
How is sending the package triggered?

edit2:

while (pos < length) {
      if (flush_step == 0) {
        sendContentBlocking(this->buf);
        flush_step = CHUNKED_BUFFER_SIZE;
      }
      this->buf += a[pos];
      ++pos;
      --flush_step;
    }

it would seem that this code portion is triggering the send, as it checks the buffer size.
pj

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

this code 0x190 (decimal 400) is the chunk size.
So I guess we're getting somewhere :)

It looks like the handler of this URL is not calling the endStream() (or how it's called).

@pljakobs
Copy link
Author

I have added TXBuffer.startStream() and TXBuffer.endStream() before at the start and end of the handler, respectively. That didn't fix it though. Let me give this another try.

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

What is the exact URL you're trying to get?

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

There is a proper startStream() and endStream() in void handle_controllers()
However, there is also a ifNotLoggedIn().
Do you have a password set?

@pljakobs
Copy link
Author

http://192.168.29.22/control?cmd=status,gpio,12

this is how I have changed the code now:

void handle_control() {
  //TXBuffer.startStream(true); // true= json
 // sendHeadandTail(F("TmplStd"),_HEAD);
  TXBuffer.startStream();
  String webrequest = WebServer.arg(F("cmd"));

  // in case of event, store to buffer and return...
  String command = parseString(webrequest, 1);
  if (command == F("event"))
  {
    eventBuffer = webrequest.substring(6);
    WebServer.send(200, "text/html", "OK");
    return;
  }

  struct EventStruct TempEvent;
  parseCommandString(&TempEvent, webrequest);
  TempEvent.Source = VALUE_SOURCE_HTTP;

  printToWeb = true;
  printWebString = "";


  if (PluginCall(PLUGIN_WRITE, &TempEvent, webrequest));
  else if (remoteConfig(&TempEvent, webrequest));
  else
    TXBuffer += F("Unknown or restricted command!");

  TXBuffer +=  printWebString;

  if (printToWebJSON)
    WebServer.send(200, "application/json");
  else
    WebServer.send(200, "text/html");
  String log = String("TXBuffer.buf: ") + String(TXBuffer.buf);
  addLog(LOG_LEVEL_DEBUG_DEV, log);
  TXBuffer.endStream();
  printWebString = "";
  printToWeb = false;
  printToWebJSON = false;
}

The result is still no json output, but I can see that TXBuffer.buf really does contain the json data (in log) and that a 67 character chunk is being sent. At least the log claims that

sendcontent free: 18344 chunk size:67
sendcontent free: 18344 chunk size:0
Ram usage: Webserver only: 0 including Core: 0
WD   : Uptime 1 ConnectFailures 0 FreeMem 18736
TXBuffer.buf: {
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}

sendcontent free: 18344 chunk size:67

sendcontent free: 18344 chunk size:0
Ram usage: Webserver only: 0 including Core: 0
TXBuffer.buf: {
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}

sendcontent free: 18344 chunk size:67
sendcontent free: 18344 chunk size:0
Ram usage: Webserver only: 0 including Core: 0
TXBuffer.buf: {
"log": "",
"plugin": 1,
"pin": 12,
"mode": "input",
"state": 0
}

sendcontent free: 18112 chunk size:67
sendcontent free: 18112 chunk size:0
Ram usage: Webserver only: 0 including Core: 0

on the wire, however, I can't see that and it doesn't arrive in my browser either.

@pljakobs
Copy link
Author

not handle_controllers, handle_control! I got confused by that, too ;-)

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

That function is messed-up.
Shouldn't look like that.
Move TXBuffer.endStream();
to the line just below the last line with TXBuffer.

@pljakobs
Copy link
Author

that Sir did the trick! So I had done the right thing but really WebServer.send() has to be called after the stream has been closed? I thought since it did contain the content header, it would have to come first.
I think this problem is solved! Thanks for your help! Great Support

@TD-er
Copy link
Member

TD-er commented Mar 12, 2018

Well your issue is solved, my task remains to find out how this function got messed up like this. :)

@pljakobs
Copy link
Author

pljakobs commented Mar 12, 2018

as said: in the current v2.0 branch, this is missing the startStream and endStream calls alltogether. I had just put it in the wrong place.
btw: next I might dig into an issue that I think I see with the MQTT controller not honoring the unit ID, but I need some more time for that. ;-)

TD-er added a commit to TD-er/ESPEasy that referenced this issue Mar 14, 2018
There wasn't a proper start/end for the streaming webserver.
See discussion on issue letscontrolit#1066
TD-er added a commit that referenced this issue Mar 15, 2018
[issue #1066] Fix Webserver handle_control
TD-er added a commit to TD-er/ESPEasy that referenced this issue Mar 15, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants