• 10 dec 2017: forum version update. In case of issues use this topic.
  • 30 nov 2017: pilight moved servers. In case of issues use this topic.
Hello There, Guest! Login Register


Thread Rating:
  • 0 Vote(s) - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
no callback on some http requests
#1
I noticed that several of the http (get) calls done by my extended wunderground protocol do no call back. The requests are done on fixed intervals (obeying the wunderground rules). I have put in some logging, both right after the http_get content in the main thread and at the beginning of the callback function.

For every request you should see a line telling that api.wunderground got called (main thread), followed by a line with the http code of the result (callback). As you can see in the logging snippet below, quite often there is indeed a line telling that api.wunderground has been called, but no line showing the returncode of the call. So it seems that the http library "randomly" is forgetting to callback when it finishes.

pilight-daemon -D is not showing any errors.

Ping tells me that api.wunderground.com is using IP4

If I do exactly the same request via wget, it always returns the epected result.

As far as I can see, http.c  itself has no dead ends anymore, so it looks like the request gets queued, but the actual handling of the request fails somewhere without reporting an error.

Now there is one one fact that may be relevant in this case: the size result of the http request is varying around 48 Kb.

Could there be some memory allocation/buffer overflow issue around that response size causing the callback to fail?
As said, pilight-daemon -D is not reporting any errors, so it might be an unhandled exception somewhere.

Because the size of the response varies a bit depending on weather conditions, that could explain why it works one time and fails the other time. 



Code:
root@pilight-master:/home/pi# cat /var/log/pilight.log | grep wunderground
[Jan 21 10:31:52:941523] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:36:52:955111] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:36:53:656646] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 10:41:52:969206] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:46:52:983221] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:46:53:423078] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 10:51:52:997112] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:51:53:554662] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 10:56:53:10895] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 10:56:53:509470] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 11:01:53:24411] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:01:53:642201] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 11:06:53:38263] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:06:53:490132] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 11:11:53:53264] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[ Jan 21 11:16:53:67614] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:16:53:984197] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 11:21:53:82363] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:21:53:533870] pilight-daemon: INFO: Got response 200 from wunderground
[ Jan 21 11:26:53:96918] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:26:53:564209] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:31:53:110912] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:31:53:521723] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:36:53:124248] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[ Jan 21 11:36:54:16161] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:41:53:138709] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:41:53:716271] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:46:53:152274] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:46:53:661352] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:51:53:166354] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 11:51:53:660660] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 11:56:53:180388] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:01:53:193720] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:06:53:207658] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:11:53:221686] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:11:53:766561] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 12:16:53:237277] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:21:53:252530] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:26:53:266467] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:31:53:279800] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:36:53:294016] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:36:53:757901] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 12:41:53:316946] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:41:53:807800] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 12:46:53:330789] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:51:53:345537] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 12:51:53:832111] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 12:56:53:359543] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:01:53:373337] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:06:53:387526] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:06:53:825275] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 13:11:53:401289] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:16:53:415295] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:16:53:830441] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 13:21:53:428644] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:21:53:875375] pilight-daemon: INFO: Got response 200 from wunderground
[Jan 21 13:26:53:442190] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:31:53:457132] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxxxxxxxxxxxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jan 21 13:31:53:928934] pilight-daemon: INFO: Got response 200 from wunderground
root@pilight-master:/home/pi#
 
Reply
#2
pilight version used?
 
Reply
#3
V7 development
 
Reply
#4
I want to revive this thread now that I have pilight 8.1 (staging) sucessfully running.

The issue described in this thread does still exist in version 8.1.

In short, some http requests (e.e. for Weather Underground) seem to "hang" and do never callback. I guess that this means that the tread processing the request either stops without callback or "hangs" waiting for a response.

Possibly this happens when the webpage being called can be found, but does not respond or does not complete its response. Imho there should be some time out mechanism handling such a situation, performing a callback with an error code (408?).

I wish I could create such an improvement myself, but the http library is too complex for me.
 
Reply
#5
Can you find the last commit in which this was working?
 
Reply
#6
And done.
 
Reply
#7
Thanks! I tested and found one issue with this fix:

The time out as such is working and code 408 is returned to the callback, but the userdata is not being returned. A NULL pointer is being returned instead.

Then, there seems to be a different case where there is no callback. I need to do more testing to find  a clue.
 
Reply
#8
As I wrote in my previous post there seems to be another issue where there is no callback.

In order to get an idea of what is going on in the http library while processing a request I started off with adding some logging at the top of most of the functions in http.c. I was lucky, because fairly soon an http request did not result in a callback.

At that moment the log shows a different behaviour then when the request works normally. Below a snippet of the log. The name of the function being called is shown between parentheses. As you can see the process_chunk() function is being called a large number of times. After that there is a client_close() and a client_remove(). No callback.

In cases where the same http request works good, process_chunk() is not called at all.

I hope this information is helpful.

Code:
[Jun 11 14:52:56:620343] pilight-daemon: INFO: (http_process)Http request=http://api.wunderground.com/api/xxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jun 11 14:52:56:620454] pilight-daemon: INFO: (prepare_request)Http request=http://api.wunderground.com/api/xxxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jun 11 14:52:56:633139] pilight-daemon: INFO: (http_client_add)Http request
[Jun 11 14:52:56:635595] pilight-daemon: INFO: wunderful called wunderground: http://api.wunderground.com/api/xxxxx/conditions/hourly/alerts/q/nl/haarlem.json
[Jun 11 14:52:57:494977] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:495421] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:495658] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:495854] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:496056] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:496259] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:496446] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:496738] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:496952] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:497152] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:497343] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:497541] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:497740] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:497934] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:498133] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:498334] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:498531] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:518116] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:518467] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:518732] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:518982] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:519189] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:519389] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:519580] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:519867] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:520388] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:520623] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:520815] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:521043] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:521245] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:521432] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:521625] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:521845] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:522047] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:522345] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:522550] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:522853] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:523058] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:523254] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:523446] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:523662] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:523858] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:524064] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:524269] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:524485] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:524689] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:524888] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:525075] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:525292] pilight-daemon: INFO: (process_chunk)Http request
[Jun 11 14:52:57:525494] pilight-daemon: INFO: (http_client_close)Http request
[Jun 11 14:52:57:525900] pilight-daemon: INFO: (http_client_remove)Http request
 
Reply
#9
Both requests / issues are fixed in rewrite. Will port to staging atm.
 
Reply
#10
Great, thanks again.

I can see quite a lot of time outs during some periods. Probably this is when there is heavy traffic on my network or internet being slow at times. With some sites is is occurring more often than with others, apparently because they need more time to prepare the response, or are running on a slow webserver.

Could it be an idea to add an optional "timeout", parameter to the http_get_content() and http_post_content() functions, so the user can "tune" the time out per request? The current fixed time out then could be the default.

Edit: I just realized that c doesn't allow optional function arguments   Confused
 
Reply
  


Possibly Related Threads...
Thread Author Replies Views Last Post
  ][solved]Segfault when retrieving big chunked http message Niek 21 5,589 11-29-2018, 03:17 PM
Last Post: curlymo
  http code 301 causes segfault Niek 3 3,276 08-14-2018, 06:57 PM
Last Post: curlymo
  http library doesn't properly handle big response Niek 39 6,365 07-17-2018, 07:26 PM
Last Post: curlymo
  [Solved] callback not executing when dns lookup fails Niek 1 606 10-08-2017, 11:44 AM
Last Post: curlymo

Forum Jump:


Browsing: 1 Guest(s)