Using HttpClient crashes Meadow

[doingnz]

Describe the bug Using HttpClient in Clima Hack Kit to get the time causes Meadow to crash or become unresponsive when a HTTP GET is responded to later. This will typically also crash VS2022 and makes debugging impossible.

To Reproduce Steps to reproduce the behavior:

1. Checkout the branch https://github.com/doingnz/Clima/tree/HttpClientGetTime which is the Clima Hack Kit with a Service to get and set the time using HttpClient (Fetching time turned off in yaml).
2. Build and deploy the application
3. Watch the output to confirm it is running and has set the time and Maple server is running and it is logging data. It will run indefinitely logging data without error (well at least a few rows added to the database)
4. Attempt to fetch data via http://192.168.2.112:5417/gettemperaturelogs
5. Watch the stdout and note the request is received and begins being processed.
6. Note stdout stops and no response received to http GET.
7. Attempting to stop the app from VS2022 may appear to be successful or VS2022 may crash.
8. Attempting to deploy the app and start a new debugging session will usually crash VS2022 early during the build/deploy steps unless Meadow is rebooted a very short time before the debug is started.
9. Comment out the single line that calls await DateTimeService.GetTimeAsync(Client); in private async void NetworkConnected(INetworkAdapter sender, NetworkConnectionEventArgs args) and debug the application to confirm Meadow and VS2022 work correctly.

Expected behavior Meadow should return JSON serialised temperature data in response to HTTP GET. Meadow should continue running. It should be possible to stop application in VS2022 and deploy/debug the application without VS2022 crashing

Screenshots None

Developer tools (please complete the following information as best as you can):

• Microsoft Windows [Version 10.0.22621.1265]
• Visual Studio Enterprise 2022 v17.4.5
• meadow v0.90.4

Meadow (please complete the following information as best as you can): Connecting to Meadow on COM6 Meadow by Wilderness Labs Board Information Model: F7Micro Hardware version: F7FeatherV2 Device name: MeadowF7

Hardware Information Processor type: STM32F777IIK6 ID: 22-00-26-00-11-51-36-30-33-33-37-33 Serial number: 335D335F3036 Coprocessor type: ESP32 MAC Address - WiFi: 94:B9:7E:91:F4:0C

Firmware Versions OS: 0.9.4.0 Mono: 0.9.4.0 Coprocessor: 0.9.4.0

Additional Context Note the "service" to get the time has the "using( HttpClient)" commented out and a static reference to the HttpClient is passed in. This change was an attempt to mitigate the problem based on discussion in discord #support and info here: https://www.aspnetmonsters.com/2016/08/2016-08-27-httpclientwrong/ My experience is that either approach causes the same issues.

[doingnz]

Occasionally you may find it necessary to close VS2022 if you find the "lock up" error continues even after commenting the line await DateTimeService.GetTimeAsync(Client); and saving the file. It feels as if VS2022 is using the older source to do the build with the line included and therefore the crashes continue when you do the HTTP GET. Noticed this "VS2022 bug" in other non Meadow contexts to where the code in the editor is correct, but the behaviour, and therefore the actual code being built and deployed is different (older buggy code.)

[adrianstevens]

Ok some good news, it seems to be stable on a Meadow F7 v1 board using the most recent pre-release OS and latest changes in Meadow.Core.

[doingnz]

I have retested on a V1 with rc-2.2 and it is much better. Tested several deploy/debug, including some that caused out of memory on Meadow, and none crashed VS2022. I was able to stop a crashed app and launch again.

Note that I still have failures when using HttpClient to fetch time. The first HTTP GET will always fail if I have called the async service and successfully set the date and time. In contrast, if the NTP as enabled in config is used to set the date and time, then I can do multiple HTTP GET for 100 or even 1000 rows and things works correctly and I receive the data in web browser. I tested using NTP and async , and async on its own and both fail. Only works if NTP in config used to set date and time.

Test #1 - time service and config
Meadow StdOut: Request received from 192.168.2.194:53503
Meadow StdOut: Received GET /gettemperaturedummy/100 - Invoking gettemperaturedummy
Meadow StdOut: LogMemory,       2023-03-27T13:20:12,     1009720,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-27T13:20:12,     1015608,"GetTemperatureLogs            ","logs",100,"DUMMY"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Meadow StdOut: LogMemory,       2023-03-27T13:20:13,     1028016,"GetTemperatureLogs            ","data",100,"DTO"
Loaded assembly: Anonymously Hosted DynamicMethods Assembly [External]
Meadow StdOut: Could not allocate 18112 bytes

Test #2 - time service and config
Meadow StdOut: Request received from 192.168.2.194:53556
Meadow StdOut: Received GET /gettemperaturedummy/100 - Invoking gettemperaturedummy
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Meadow StdOut: LogMemory,       2023-03-27T13:22:52,     1009144,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-27T13:22:52,     1015560,"GetTemperatureLogs            ","logs",100,"DUMMY"
Meadow StdOut: LogMemory,       2023-03-27T13:22:53,     1027968,"GetTemperatureLogs            ","data",100,"DTO"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Loaded assembly: Anonymously Hosted DynamicMethods Assembly [External]
Meadow StdOut: Could not allocate 1544 (1 * 1544) bytes

Test #3 - time via config
Meadow StdOut: Request received from 192.168.2.194:53581
Meadow StdOut: Received GET /gettemperaturedummy/100 - Invoking gettemperaturedummy
Meadow StdOut: LogMemory,       2023-03-27T13:25:28,      884400,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-27T13:25:28,      890376,"GetTemperatureLogs            ","logs",100,"DUMMY"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Meadow StdOut: LogMemory,       2023-03-27T13:25:29,      902696,"GetTemperatureLogs            ","data",100,"DTO"
Loaded assembly: Anonymously Hosted DynamicMethods Assembly [External]
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
... debug text continues.

Test #4 - time service
Meadow StdOut: Request received from 192.168.2.194:53621
Meadow StdOut: Received GET /gettemperaturedummy/100 - Invoking gettemperaturedummy
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Meadow StdOut: LogMemory,       2023-03-27T13:28:39,     1007528,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-27T13:28:40,     1013440,"GetTemperatureLogs            ","logs",100,"DUMMY"
Meadow StdOut: LogMemory,       2023-03-27T13:28:40,     1025848,"GetTemperatureLogs            ","data",100,"DTO"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Loaded assembly: Anonymously Hosted DynamicMethods Assembly [External]
Meadow StdOut: Could not allocate 1024 bytes

Test #5 - time config
Meadow StdOut: Received GET /gettemperaturedummy/1000 - Invoking gettemperaturedummy
Meadow StdOut: LogMemory,       2023-03-27T13:36:03,      939448,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-27T13:36:04,      992768,"GetTemperatureLogs            ","logs",1000,"DUMMY"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756
Meadow StdOut: LogMemory,       2023-03-27T13:36:07,     1117584,"GetTemperatureLogs            ","data",1000,"DTO"
Meadow StdOut: UDP Broadcast: Meadow::192.168.2.202, port: 17756

[doingnz]

Running the same test app as used in the previous comment on V2 and the behaviour is the same. With the call to the time service to set date & time, the next HTTP GET will trigger memory allocation error and meadow stops running the application (no more stdout). If NTP service in yaml used, then the app runs OK and multiple HTTP GET are possible.

This test app in these two tests is simplified as it is not full Clima Hack Kit with LCD and TEMP. Just rgb color cycle and code to respond to HTTP GET and the timer service that is optionally called.

[doingnz]

Retested with Clima HackKit on V2 and the behavior appears to be the same improved situation where VS2022 behaves and stops when Stop icon is pressed and the debug session can be re-started after out of memory error after HTTP GET. The same out of memory when the using the service to set the date and time and correct application behaviour when only NTP service is used.

[adrianstevens]

I've run your sample @doingnz with our latest prerelease OS and this appears to be fixed. The fix will ship with RC3 - coming soon.

[doingnz]

RC-3 is certainly better as VS2022 is not crashed.

However, there is still a problem that stops Meadow running the application after Meadow has a memory allocation error if we try use HttpClient to get the time.

I have updated the branch for changes introduced in RC-3 : https://github.com/doingnz/Clima/tree/HttpClientGetTime

The updated code in this branch has the edits for RC-3 to remove Device and to use the new method to set the clock, otherwise is unchanged.

When the application is run, it will output the IP address Meadow is using and it will confirm the date and time has been set. It will then start logging data. However, when a HTTP GET is used to attempt to fetch logged data, Meadow will hang after a message saying it failed to allocate memory. Interestingly with RC-3, the app appears to continue running a little longer ... i.e. the UDP notifications continue for a few more and the app will try save one more measurement after the memory allocation error before the application stops outputting anything. Possibly indication of a threading deadlock?

Note that no data is received by the web browser.

SetClock(04/07/2023 00:09:31);
Listening on http://192.168.2.112:5417/
GET : /gettemperaturelogs --> GetTemperatureLogs
GET : /gettemperaturepage/{page} --> GetTemperaturePage
requestHandlers.Count: 1
Starting up Maple HTTP Request listener.
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Saving (28.69775390625,04/07/2023 00:09:42)...
SaveReading: Saving temperature reading to DB
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
SaveReading: Successfully saved to database
UDP Broadcast: Meadow::192.168.2.112, port: 17756
SaveReading: Count=164 GetTotalMemory=1329392
done!
Request received from 192.168.2.194:52828
Received GET /gettemperaturelogs - Invoking gettemperaturelogs
GetAllReadings:  TotalCount=164 ...
GetReadings:  TotalCount=164 TotalPages=2 PageSize=100 CurrentPage=1
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Could not allocate 4096 bytes
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Saving (28.72998046875,04/07/2023 00:10:19)...
SaveReading: Saving temperature reading to DB
SaveReading: Successfully saved to database

Note in the above there is no 'done!' output after save. No further output.

If we comment out the call to the code that uses HttpClient to set the clock //await DateTimeService.GetTimeAsync(Client);, then the app will run as expected and successfully return data to the HTTP request repeatedly as shown here:

UDP Broadcast: Meadow::192.168.2.112, port: 17756
Saving (28.5205078125,04/07/2023 00:20:15)...
SaveReading: Saving temperature reading to DB
UDP Broadcast: Meadow::192.168.2.112, port: 17756
SaveReading: Successfully saved to database
SaveReading: Count=178 GetTotalMemory=1288528
UDP Broadcast: Meadow::192.168.2.112, port: 17756
done!
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Request received from 192.168.2.194:52945
Received GET /gettemperaturelogs - Invoking gettemperaturelogs
GetAllReadings:  TotalCount=178 ...
GetReadings:  TotalCount=178 TotalPages=2 PageSize=100 CurrentPage=1
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Request received from 192.168.2.194:52945
Received GET /favicon.ico - Invoking favicon.ico
No handler found
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Saving (28.3916015625,04/07/2023 00:20:49)...
SaveReading: Saving temperature reading to DB
UDP Broadcast: Meadow::192.168.2.112, port: 17756
SaveReading: Successfully saved to database
SaveReading: Count=179 GetTotalMemory=1300328
done!
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
Request received from 192.168.2.194:52950
Received GET /gettemperaturelogs - Invoking gettemperaturelogs
GetAllReadings:  TotalCount=179 ...
GetReadings:  TotalCount=179 TotalPages=2 PageSize=100 CurrentPage=1
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756
UDP Broadcast: Meadow::192.168.2.112, port: 17756

Something about the earlier use of HttepClient to get the time causes a memory allocation error and Meadow App stops Console output after a HTTP GET is received by the Maple server.

[bryancostanich]

Likely caused by #347. 🏴‍☠️

[bryancostanich]

more investigation makes this smell like the round-robin bug (#311), which we're also seeing in the button bug (#359).

[bryancostanich]

should no longer crash the tooling, however.

[doingnz]

Please also consider Foundation #745 when testing the threading fixes. The key issue in 745 is the handling of the TaskCancelled process which has a memory leak and possibly the round-robin issue. The design of handling the RGB led is a different issue that can only be addressed when the underpinning threading and cancel works well.

I have not see VS2022 crash for some time. :-)

[bryancostanich]

Worth retesting after we get the Round-Robin fixes into mainline, as this seems to be related to the same DateTime stuff.

[doingnz]

Let me know if there is a beta release you would like me to test before general release.

Let me know if the steps in the introduction of https://github.com/WildernessLabs/Meadow.Foundation/issues/745 are not clear.

Is as easy as make new Blinky, paste in the code to start up the three competing tasks, run the code and confirm the error occurs or does not.

Optionally try the suggested code change to Meadow.Foundataion to handle the exception and see if it still occurs.

This code is a stress test for the schedular as it is starting and cancelling Tasks as fast as it can. :-)

[bryancostanich]

@halyssonJr can you re-test this on a build with Round-Robin enabled, please? @alexischr will help you. We think that this was related to the DateTime B.S. that was fixed in RR.

[bryancostanich]

Sounds like this is fixed now. We tested with the new binaries, but it may have been fixed in the released stuff, too.

[halyssonJr]

I was able to reproduce this same issue using v1.8.0.0, we noticed still memory issues after requesting an endpoint to set the clock in this App, however, there is a workaround. The workaround was adding explicitly dispose of the objects and called the GC Method.

client.Dispose();
response.Dispose();
GC.Collect();
GC.WaitForPendingFinalizers();

Result

Meadow StdOut: SetClock(02/20/2024 02:23:42);
Meadow StdOut: Dispose and Finalizers
Meadow StdOut: Listening on http://192.168.4.8:5417/
Meadow StdOut: GET : /gettemperaturelogs --> GetTemperatureLogs
Meadow StdOut: requestHandlers.Count: 1
Meadow StdOut: Starting up Maple HTTP Request listener.
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.8, port: 17756
Meadow StdOut: Saving (34.0717948717947,02/19/2024 19:40:02)...
Meadow StdOut: done!
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.8, port: 17756

However, when I tried to request Maple Serve I had a memory issue. A few seconds after receiving the error message (allocation failed), the App tried to save the temperature log and stopped working.

Meadow StdOut: UDP Broadcast: Meadow::192.168.4.8, port: 17756
...
Meadow StdOut: Request received from 192.168.4.5:52430
Meadow StdOut: Received GET /gettemperaturelogs - Invoking gettemperaturelogs
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.8, port: 17756
Meadow StdOut: Could not allocate 39728 (1 * 39728) bytes
Meadow StdOut: Saving (34.7809523809522,02/19/2024 19:10:50)...
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.8, port: 17756

In my resume, I see progress in the current version 1.8.0.0 and also this issue is strongly related #276. We will be keeping a tracker for this memory issue.

@doingnz, thank you, your investigation gave us a direction to find out this memory issue.