Thanks, got the Indy logging working.
Here is a cut-down version of the logfile produced (I have removed the binary file data after verifying that it starts and ends with the bytes at the beginning and end of the file).
Note that the lines are very long so will be wrapped in this display::
Code:
Stat Connected.
Sent 2018-05-02 20:30:17: GET /firmware HTTP/1.1<EOL>Host: 192.168.119.249<EOL>Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8<EOL>Referer: http://192.168.119.249/firmware<EOL>User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0<EOL>Authorization: Basic YWdpYWRtaW46YWdpdXNh<EOL><EOL>
Recv 2018-05-02 20:30:17: HTTP/1.1 200 OK<EOL>Content-Type: text/html<EOL>Content-Length: 385<EOL>Connection: close<EOL><EOL>
Recv 2018-05-02 20:30:17: <html><head><title>The ESP8266 updater</title></head><LF> <body><b>WiFi module firmware updater</b><LF> <br>Select firmware file, then click the Update button!<br><LF> <form method='POST' action='' enctype='multipart/form-data'><LF> <input type='file' name='update'><LF> <input type='submit' value='Update'><LF> </form><LF> </body></html>
Stat Disconnected.
Stat Connected.
Sent 2018-05-02 20:30:17: POST /firmware HTTP/1.0<EOL>Connection: keep-alive<EOL>Content-Type: multipart/form-data; boundary=--------050218203017201<EOL>Content-Length: 304674<EOL>Host: 192.168.119.249<EOL>Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8<EOL>Referer: http://192.168.119.249/firmware<EOL>User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0<EOL>Authorization: Basic YWdpYWRtaW46YWdpdXNh<EOL><EOL>
Sent 2018-05-02 20:30:17: ----------050218203017201<EOL>Content-Disposition: form-data; name="update"; filename="DHT_MONITOR.bin"<EOL>Content-Type: application/octet-stream<EOL>Content-Transfer-Encoding: binary<EOL><EOL>
<--- here is the binary file content, which I cut away --->
<EOL>----------050218203017201--<EOL>
Recv 2018-05-02 20:30:25: HTTP/1.0 200 OK<EOL>Content-Type: text/html<EOL>Content-Length: 56<EOL>Connection: close<EOL><EOL>
Recv 2018-05-02 20:30:25: Update error: ERROR[10]: Magic byte is wrong, not 0xE9<EOL>
Stat Disconnected.
An interesting item appears at the end. "Magic byte is wrong", whatever that means...
05-03-2018, 07:11 PM (This post was last modified: 08-24-2018, 12:02 AM by rlebeau.)
(05-02-2018, 06:42 PM)BosseB Wrote: Thanks, got the Indy logging working.
Here is a cut-down version of the logfile produced (I have removed the binary file data after verifying that it starts and ends with the bytes at the beginning and end of the file).
Off hand, I don't see anything that should be preventing the POST from succeeding.
The only real difference I see between the Indy log and the Firefox log you showed earlier is the lack of "Accept-Encoding", "Accept-Language"[/font], and "Upgrade-Insecure-Requests" headers on Indy's part, but those are optional and don't affect your ability to upload the firmware update file.
On a side note, you should not be specifying a Referer in the initial GET request that retrieves the webform HTML, only when submitting the webform. The Referer is the URL that is *automatically* requesting another URL. When submitting a webform, the Referer is the URL of the webform's HTML, which is submitting to the URL that the webform specifies. When first retrieving the webform HTML, the Referer is usually the user, so you don't need to specify a Referer in that GET request. This also doesn't affect your ability to upload the firmware update file, but it is just to match what a web browser would do.
Incidentally, since HTTP cookies are not involved, the initial GET is optional, you can probably remove it now.
(05-02-2018, 06:42 PM)BosseB Wrote: Note that the lines are very long so will be wrapped in this display::
TIdLogFile has a few properties to customize the log output. For instance, turning off timestamps by setting LogTime=False, and preserving line breaks by setting ReplaceCRLF=False.
(05-02-2018, 06:42 PM)BosseB Wrote: An interesting item appears at the end. "Magic byte is wrong", whatever that means...
That implies that the firmware update file itself is wrong or corrupted. There is likely a special byte inside of the file that the device is looking for to validate the file before modifying the firmware. You should compare the POST request params that you capture from Firefox with the POST request params that you capture from Indy, and make sure the actual "binary file content" of the firmware update file that is being POST'ed match exactly (they should).
to be after the initial GET operation.
Also changed the log properties as suggested.
Magic byte:
In both the FireFox and the Config App cases I am choosing the exact same file for transfer.
I checked the log for the start and end of the file transfer data and verified that these are the same as the binary start and end bytes of the file itself. Could not check the length of the data though.
The start byte of the binary file is actually the E9 (magic byte).
I agree that the feedback indicates that a byte is not arriving as it should, but I cannot understand how that can happen since the source file is the same in both cases. And the submitting form is simplicity itself, I can see nothing there that can affect how the file data are modified...
OTOH, the destination function inside the IoT device will do the following during/after receiving the data:
- Write the file data into flash memory at a scratch location
- Check an MD5 checksum to verify that the file is unaltered
- Check the validity of the firmware (I don't know how, maybe the magic byte...)
- If OK send back a response containing a success message and a reload command with a timeout of about 20 s
- Jump to a special reset function that will overwrite the active flash memory from the scratch area
- Reset the device to make it start with the new firmware
This finalization function seems to not execute and therefore the old firmware remains in flash memory and keeps running.
Should I add a final GET in order to retrieve the result data being sent back, or is that already part of the HTTP.Post function?
Later:
I opened the logfile and the binary flash file in HxD to check the contents.
The bin file starts with the E9 magic byte and it is 304464 bytes in size.
The bin file ends with this sequence: 0C FF 3F 00 00 00 CA
In the log file I find the E9 start byte in address $274 (628 decimal)
And the ending sequence is located with CA at address 4A814
So if I calculate the transferred file data length I get 4A814 +1 - 274 = 4A5A1 (or 304545 decimal)
This means that the data transferred are 81 bytes too many....
There seems to be inserted bytes within the file body.
05-03-2018, 11:09 PM (This post was last modified: 08-24-2018, 12:04 AM by rlebeau.)
(05-03-2018, 10:18 PM)BosseB Wrote: Magic byte:
In both the FireFox and the Config App cases I am choosing the exact same file for transfer.
Then it should be transferred as exactly the same bytes in both Firefox and TIdHTTP.
The ONLY other difference I can think of is if the IoT device is not correctly handling the "Content-Transfer-Encoding: binary" header that TIdHTTP sends for the file but Firefox does not send. You can instruct Indy not to send that header by clearing the TIdFormDataField.ContentTransfer property (AddFiles() defaults it to 'binary'), eg:
(05-03-2018, 10:18 PM)BosseB Wrote: I checked the log for the start and end of the file transfer data and verified that these are the same as the binary start and end bytes of the file itself.
I agree that the feedback indicates that a byte is not arriving as it should, but I cannot understand how that can happen since the source file is the same in both cases. And the submitting form is simplicity itself, I can see nothing there that can affect how the file data are modified...
The webform itself is not the issue. How the webform is formatted during transmission is. And there is something in TIdHTTP's formatting that the IoT device clearly does not like/handle correctly.
(05-03-2018, 10:18 PM)BosseB Wrote: OTOH, the destination function inside the IoT device will do the following during/after receiving the data:
Do you have access to the IoT device's source code for its HTTP server? Or any kind of debugging tool for analyzing how it is processing HTTP requests?
(05-03-2018, 10:18 PM)BosseB Wrote: Should I add a final GET in order to retrieve the result data being sent back
No. However, on a successful POST, the IoT device is sending back HTML that redirects a web browser back to the webform after 15 seconds. You can choose whether that is appropriate for your app or not.
(05-03-2018, 10:18 PM)BosseB Wrote: is that already part of the HTTP.Post function?
Yes, the result data is in the POST's response.
(05-03-2018, 10:18 PM)BosseB Wrote: I opened the logfile and the binary flash file in HxD to check the contents.
The bin file starts with the E9 magic byte and it is 304464 bytes in size.
The bin file ends with this sequence: 0C FF 3F 00 00 00 CA
In the log file I find the E9 start byte in address $274 (628 decimal)
And the ending sequence is located with CA at address 4A814
So if I calculate the transferred file data length I get 4A814 +1 - 274 = 4A5A1 (or 304545 decimal)
This means that the data transferred are 81 bytes too many....
Not necessarily. TIdMultipartFormDataStream transmits file data as-is, it doesn't modify the bytes in any way, or inject any extra bytes. You can use Wireshark to verify that (if you set the TIdFormDataField.ContentTransfer property to 'base64' or 'quoted-printable', it will encode the bytes accordingly, but it will not alter them, so the receiver should see the original bytes correctly after decoding).
However, Indy's logging could be translating $0D and $0A bytes into text, for instance. When it comes to binary data, what is logged may not be exactly what is transmitted. That is why I suggested setting the TIdLogFile.ReplaceCRLF property to false to avoid that.
(05-03-2018, 10:18 PM)BosseB Wrote: There seems to be inserted bytes within the file body.
You are just going to have to compare all 304545 bytes against the original 304464 bytes to check what is actually being changed. But, it would certainly make sense that if the file bytes are being messed up during transmission, the IoT device will fail verification and ignore the file.
(05-03-2018, 10:18 PM)BosseB Wrote: Or else these are protocol inserted bytes?
There are no "protocol inserted bytes" in file uploads via HTML webform.
Regarding the last test here is the function in the state it is now.
As you can see I had set the Log.ReplaceCRLF property to false:
Code:
function TConfigCommHandler.UploadFirmware(FileName: string; URL: string): boolean;
var
HTTP: TIdHTTP;
Src: TIdMultipartFormDataStream;
Log: TIdLogFile;
begin
Result := false;
if not FileExists(FileName) then exit;
HTTP := TIdHTTP.Create;
Log := TIdLogFile.Create;
try
Src := TIdMultipartFormDataStream.Create;
try
Src.AddFile('update', FileName);
Log.Filename := 'D:\Engineering\Projects\Subversion\PC\WiFiConfig\Docs\WiFi.log';
Log.LogTime := false;
Log.ReplaceCRLF := false;
Log.Active := true;
try
HTTP.Request.BasicAuthentication := true;
HTTP.Request.UserAgent := 'Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0';
HTTP.Request.Username := FUserName;
HTTP.Request.Password := FPassword;
HTTP.AllowCookies := true; //Added to try make the swrver accept update
HTTP.Intercept := Log;
HTTP.Request.Referer := URL;
HTTP.Post(URL, Src); //Send the update file
Result := true;
except
on E: Exception do
FLastError := 'Exception: ' + E.Message;
end;
finally
Src.Free;;
end;
finally
Log.Active := false;
Log.Free;
HTTP.Free;
end;
end;
I have made a copy of the logfile and using the HxD hex editor I have cut away all data preceding the start of the file transfer (where the magic byte E9 is located) and following the arrival of the last byte in the file.
Then I have used WinMerge to compare the original bin file with the edited version of the logfile.
What I find is 9 instances where the following byte pattern has been inserted, making up for the additional 81 bytes:
Code:
0D 0A 53 65 6E 74 20 3A 20
In plain text: "<CRLF>Sent : " (not including the quotes)
This pattern is found in the file at the following addresses:
$7F4D
$FF56
$17F5F
$1FF68
$27F71
$2FF7A
$37F83
$3FF8C
$47F95
Notice that these addresses are exactly $8009 (32777 decimal) bytes apart!
The inserted bytes are 9 so it seems like after every $8000 bytes sent the extra stuff is inserted.
The first packet insertion point is not at address $8000 but that is probably because I have edited out the leading part of the file when I tried to make the log the same as the source file.
In fact when I look at the unedited log I see more of these insertions leading up to the first one inside the file body.
Now the question is:
Are these items actually sent or are they artifacts of the TIdLogFile logging?
If they are actually sent then the file transfer is of course not going to work....
If I could find a way to export the file body content from a Wireshark logfile, then it would be possible to compare the data there. But I am totally lost in Wireshark due to the number of commands and options etc.
Just being able to export exactly the bytes sent by the PC to the IoT device would make it possible to then use a hex editor to find the start of the file transfer and verify if there is a difference between the FireFox and Indy transfers.
05-04-2018, 12:34 PM (This post was last modified: 05-04-2018, 12:36 PM by BosseB.)
Now I have had time to check how Wireshark can be used to extract transferred files.
So I could get the file out from the FireFox transfer's logfile:
The file is completely contained within the Wireshark log but it is preceded by the following text (note line breaks shown in < >:
I have made two successive transfers now, using FireFox and my Indy Conf app.
Attached is the two Wireshark pcap files and the resulting bin file exports.
I can only see one difference up until the point where the FireFox one succeeds and the Conf one fails and this is the Content-Transfer-Encoding item (which is only present in the Indy case).
Apart from this there are different timestamps enclosing the binary transfers of course, but that should not matter.
I attach a zip containgíng both the pcap log files and the exported bin files.
Maybe you can see anything I am missing?
I tried to find a way to block the Content-Transfer-Encoding item from being produced but failed....
Following the POST command, what is the correct way to retrieve the return string from the server.
According to my traces it should contain an error message (about the cause of the failure) if it fails and an OK message otherwise.
So I would like to set my Lasterror property and result accordingly so the main program can display what the cause of a failure was.
Right now I have this code, always returning true...:
Code:
HTTP.Request.ContentType := 'multipart/form-data;';
HTTP.Intercept := Log;
HTTP.Request.Referer := URL;
HTTP.Post(URL, Src); //Send the update file
Result := true; //Should check return message to set result code...
05-07-2018, 06:42 PM (This post was last modified: 08-24-2018, 12:07 AM by rlebeau.)
(05-04-2018, 06:15 AM)BosseB Wrote: I have made a copy of the logfile and using the HxD hex editor I have cut away all data preceding the start of the file transfer (where the magic byte E9 is located) and following the arrival of the last byte in the file.
Then I have used WinMerge to compare the original bin file with the edited version of the logfile.
What I find is 9 instances where the following byte pattern has been inserted, making up for the additional 81 bytes:
Code:
0D 0A 53 65 6E 74 20 3A 20
In plain text: "<CRLF>Sent : " (not including the quotes)
Then you didn't strip off everything that the log had added. The file get uploaded in chunks, what you are seeing is status text being written to the log file for each of those chunks. That text is not transmitted to the server, though.
(05-04-2018, 06:15 AM)BosseB Wrote: Notice that these addresses are exactly $8009 (32777 decimal) bytes apart!
The inserted bytes are 9 so it seems like after every $8000 bytes sent the extra stuff is inserted.
Sounds about right.
(05-04-2018, 06:15 AM)BosseB Wrote: Now the question is:
Are these items actually sent or are they artifacts of the TIdLogFile logging?
They are artifacts of the logging, they are not transmitted to the server.
If you switch from TIdLogFile to TIdLogStream and use a TFileStream for output, you won't see that status text written to the log file anymore.
(05-04-2018, 06:15 AM)BosseB Wrote: If I could find a way to export the file body content from a Wireshark logfile, then it would be possible to compare the data there. But I am totally lost in Wireshark due to the number of commands and options etc.
Wireshark is really not that hard to use. And there are TONS of tutorials on it.
In this case, once you have filtered the HTTP stream, you can select the POST message, and in the Packet Details pane, right-click on the file data and choose "Exported Selected Packet Bytes".
(05-04-2018, 06:15 AM)BosseB Wrote: Just being able to export exactly the bytes sent by the PC to the IoT device would make it possible to then use a hex editor to find the start of the file transfer and verify if there is a difference between the FireFox and Indy transfers.
That is exactly the type of thing that Wireshark is good for.
(05-04-2018, 12:34 PM)BosseB Wrote: It looks like the only difference is that Indy adds
Code:
Content-Transfer-Encoding: binary
just before the file data whereas FireFox does not.
As I already commented earlier, that should not affect the upload. But I did show you exactly how to remove that header if necessary.
Also, there is another difference - FireFox is using HTTP 1.1, whereas TIdHTTP is using HTTP 1.0 instead. That also should not affect the upload, but just in case, if you want TIdHTTP to use HTTP 1.1 then set the TIdHTTP.ProtocolVersion property to pv1_1, and enable the hoKeepOrigProtocol flag in the TIdHTTP.HTTPOptions property.
(05-04-2018, 05:16 PM)BosseB Wrote: I tried to find a way to block the Content-Transfer-Encoding item from being produced but failed....
(05-05-2018, 09:16 AM)BosseB Wrote: Following the POST command, what is the correct way to retrieve the return string from the server.
Your IoT device is not returning a proper HTTP error response code on failure, so you will have to parse the returned HTML instead. There are multiple overloaded versions of TIdHTTP.Post() - some that return the response body as a String, and some that fill an output TStream with the response body. Use one that returns a String, and then parse it as needed:
Code:
var
Response: String;
try
Response := HTTP.Post(URL, Src); //Send the update file
// parse Response as needed...
Result := ...;
except
// post error. Not happening in your case, but you should handle it nonetheless...
Result := False;
end
(05-04-2018, 12:34 PM)BosseB Wrote: It looks like the only difference is that Indy adds
Code:
Content-Transfer-Encoding: binary
just before the file data whereas FireFox does not.
(05-07-2018, 06:42 PM)rlebeau Wrote: As I already commented earlier, that should not affect the upload. But I did show you exactly how to remove that header if necessary.
As I showed you on May 3rd:
OK, I just added the final part of the Src.AddFile command as shown above.
And it resulted in a complete transfer and firmware update + IoT reboot!
So this was it!
Now working!
Thank you for your patience and advice!