tFpHttpClient does not timeout
lazarus / 21-General

----------------------------------------------------------------------
jollytall · 2023-11-22 20:26

I have a simple file download function:
Code: Pascal  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i function
DownloadPage(aWebAddress : string; aUserAgent : string; out aPage :
string) : boolean;  var    HttpClient : tFPHttpClient;  begin  result
:= false;  HttpClient := tFPHttpClient.Create(nil);  try    with
HttpClient do      begin      ConnectTimeout := 5000;     
AllowRedirect:=True;      AddHeader('Accept-Encoding','gzip,
deflate');      AddHeader('Connection','Kep-Alive');     
AddHeader('User-Agent',aUserAgent);      AddHeader('Accept','*/*');  
  aPage := Get(aWebAddress);      result := true;      end;  finally 
 HTTPClient.Free;    end;  end;
what I can call also as a function directly returning the page or
raising an exception:
Code: Pascal  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i function
DownloadPage(aWebAddress : string; aUserAgent : string; aRaise :
boolean = false) : string;  begin  if not DownloadPage(aWebAddress,
aUserAgent, result) and aRaise then    raise Exception.Create('Error
during page download');  end;
and that I call from my real program, as
Code: Pascal  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i   while
true do    begin    try      DownloadPage(PageUrl, '', S);     
ProcessPage(S);    except      on E:Exception do writeln('Download
failed');      end;    Sleep(10000);    end;
The last infinite loop runs every 10 seconds on a server that is up
during daylight and down at night (a solar panel inverter if you want
to know, why). During the day the loop runs as expected. When the
server switches off, it still runs as expected, properly timing out.
However after many attempts (last time I logged and it was 1111
loops!) the Get(aWebAddress) call as above never returns with a
timeout.
I cannot imagine any thing on my side. I can imagine either a random
error, but more likely a memory leak, or alike in the class and so it
fails after a while.

Has anyone seen something like this? Any comments are welcome. Thanks.

----------------------------------------------------------------------
WayneSherman · 2023-11-23 15:30

Quote from: jollytall on November 22, 2023, 09:26:07 pm...after many
attempts (last time I logged and it was 1111 loops!) the
Get(aWebAddress) call as above never returns with a timeout.
I cannot imagine any thing on my side. I can imagine either a random
error, but more likely a memory leak, or alike in the class and so it
fails after a while.
If you are running on Linux, you can use strace to troubleshoot:
https://man7.org/linux/man-pages/man1/strace.1.html
https://www.google.com/search?q=linux+strace+how+to+use

----------------------------------------------------------------------
jollytall · 2023-11-25 18:52

Thank you for the idea. I think it helped. It took me some time, as I
have only one shot a night...

So, whathappens:
Quote19:04:37 gettimeofday({tv_sec=1700935477, tv_usec=32477}, NULL) =
0
19:04:37 write(1, "b", 1)               = 1
19:04:37 munmap(0xb6450000, 32768)      = 0
19:04:37 write(1, "1", 1)               = 1
19:04:37 write(1, "2", 1)               = 1
19:04:37 write(1, "3", 1)               = 1
19:04:37 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6450000
19:04:37 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
19:04:37 getsockopt(4, SOL_SOCKET, SO_RCVTIMEO_OLD,
"\0\0\0\0\0\0\0\0", [8]) = 0
19:04:37 fcntl(4, F_GETFL)              = 0x2 (flags O_RDWR)
19:04:37 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19:04:37 connect(4, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("192.168.128.128")}, 16) = -1 EINPROGRESS
(Operation now in progress)
19:04:37 _newselect(5, NULL, [4], NULL, {tv_sec=5, tv_usec=0}) = 1
(out [4], left {tv_sec=2, tv_usec=11108})
19:04:40 getsockopt(4, SOL_SOCKET, SO_ERROR, [EHOSTUNREACH], [4]) = 0
19:04:40 fcntl(4, F_GETFL)              = 0x802 (flags
O_RDWR|O_NONBLOCK)
19:04:40 fcntl(4, F_SETFL, O_RDWR)      = 0
19:04:40 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb58bb000
19:04:40 close(4)                       = 0
19:04:40 gettimeofday({tv_sec=1700935480, tv_usec=62605}, NULL) = 0
19:04:40 write(1, "t at 25-11-23 19:04:40\n", 23) = 23
19:04:40 munmap(0xb58bb000, 32768)      = 0
19:04:40 gettimeofday({tv_sec=1700935480, tv_usec=70012}, NULL) = 0
19:04:40 gettimeofday({tv_sec=1700935480, tv_usec=72113}, NULL) = 0
19:04:40 gettimeofday({tv_sec=1700935480, tv_usec=73580}, NULL) = 0
19:04:40 gettimeofday({tv_sec=1700935480, tv_usec=76906}, NULL) = 0
19:04:40 nanosleep({tv_sec=6, tv_nsec=952000000}, 0xb688dba8) = 0

...

19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=44983}, NULL) = 0
19:05:17 write(1, "b", 1)               = 1
19:05:17 munmap(0xb6450000, 32768)      = 0
19:05:17 write(1, "1", 1)               = 1
19:05:17 write(1, "2", 1)               = 1
19:05:17 write(1, "3", 1)               = 1
19:05:17 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6450000
19:05:17 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
19:05:17 getsockopt(4, SOL_SOCKET, SO_RCVTIMEO_OLD,
"\0\0\0\0\0\0\0\0", [8]) = 0
19:05:17 fcntl(4, F_GETFL)              = 0x2 (flags O_RDWR)
19:05:17 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19:05:17 connect(4, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("192.168.128.128")}, 16) = -1 EINPROGRESS
(Operation now in progress)
19:05:17 _newselect(5, NULL, [4], NULL, {tv_sec=5, tv_usec=0}) = 1
(out [4], left {tv_sec=4, tv_usec=999977})
19:05:17 getsockopt(4, SOL_SOCKET, SO_ERROR, [ECONNREFUSED], [4]) = 0
19:05:17 fcntl(4, F_GETFL)              = 0x802 (flags
O_RDWR|O_NONBLOCK)
19:05:17 fcntl(4, F_SETFL, O_RDWR)      = 0
19:05:17 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb58bb000
19:05:17 close(4)                       = 0
19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=104522}, NULL) = 0
19:05:17 write(1, "t at 25-11-23 19:05:17\n", 23) = 23
19:05:17 munmap(0xb58bb000, 32768)      = 0
19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=111342}, NULL) = 0
19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=113510}, NULL) = 0
19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=115759}, NULL) = 0
19:05:17 gettimeofday({tv_sec=1700935517, tv_usec=117262}, NULL) = 0
19:05:17 nanosleep({tv_sec=9, tv_nsec=911000000}, 0xb688dba8) = 0

...

gettimeofday({tv_sec=1700935527, tv_usec=32566}, NULL) = 0
19:05:27 write(1, "b", 1)               = 1
19:05:27 munmap(0xb6420000, 32768)      = 0
19:05:27 write(1, "1", 1)               = 1
19:05:27 write(1, "2", 1)               = 1
19:05:27 write(1, "3", 1)               = 1
19:05:27 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6420000
19:05:27 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
19:05:27 getsockopt(4, SOL_SOCKET, SO_RCVTIMEO_OLD,
"\0\0\0\0\0\0\0\0", [8]) = 0
19:05:27 fcntl(4, F_GETFL)              = 0x2 (flags O_RDWR)
19:05:27 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19:05:27 connect(4, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("192.168.128.128")}, 16) = -1 EINPROGRESS
(Operation now in progress)
19:05:27 _newselect(5, NULL, [4], NULL, {tv_sec=5, tv_usec=0}) = 1
(out [4], left {tv_sec=4, tv_usec=999927})
19:05:27 getsockopt(4, SOL_SOCKET, SO_ERROR, [ 0], [4]) = 0
19:05:27 fcntl(4, F_GETFL)              = 0x802 (flags
O_RDWR|O_NONBLOCK)
19:05:27 fcntl(4, F_SETFL, O_RDWR)      = 0
19:05:27 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb58bb000
19:05:27 mmap2(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb58b3000
19:05:27 sendto(4, "GET /solar_api/v1/GetInverterRea"..., 213, 0,
NULL, 0) = 213
19:05:27 mmap2(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5873000
19:05:27 recvfrom(4,

The first block shows how I expected it to work, i.e. host
unreachable. It happens many-many times.
Then for some strange reason, the host became reachable, but
connection was refused. I can imagine that the moon rose and it gave
enough light to do something, or it is just a noise in the
communication, and so it thought that it reached the server, but could
not connect. Anyway, both gave a timeout and my program went on.
After few (not too many) connection refused error, came the last
block, where the system thinks that it is connected, so it sends the
GET message and never gets an answer. And it never timed out.

So, I checked the class and found that there are two timeout values,
ConnectTimeout and IOTimeout and I only had the connect one set. So as
long as it could not connect, it was OK, but once it though it
connected, it waited forever for the RECVFROM. Although in the morning
the server came back, as it was not really reading, it never went on.
So now I set the IOTimeout as well, and cross my fingers.

Still it bothers me a bit, why a dead server can give different
responses for the CONNECT message. Maybe really the moon...