#773 Fails to wake up for its 2 minute check (often but not always)long past auction end, get bid uiid not found

[NickT]

Background:
Running latest code from Git on a headless Raspberry Pi as the only esniper running. Often the auction ends without it making a bid. It does this if the ssh from an Ubuntu box or putty from a Windows machine is closed or left open. It does it with ibcurl4-gnutls-dev. or libcurl4-openssl-dev installed. The evidence a user would see from the terminal box is just the oft reported "bid uiid not found" long after the auction has ended. I attach the bug html for what it's worth (not much)

By including "curldebug = yes" in my auction file, much more informative material is available. I ran esniper this morning by' nohup esniper myauction'. nohup.out has several instances of 'seems to be dead', which may lie at the root of the problem.

I picked an auction with about 15 minutes to go, nohup.out will show that it woke for its 10 minute check , said it was sleeping until 2 minutes to go but didn't wake for that.

I appreciate that it may not be an error caused by esniper (as turning on the curl debug rveals the dead conections) I have reduced the min bidtime on my version t o 3 seconds which used to work till about last August. Looking at the code, I can't see it making any difference. I attach the bug.html, my .esaniper, myauction and nohup.out files with my username and password changed to secret.

I will appreciate any help that may be coming. I can't believe that I'm the only person who has seen such a problem

[Michael S.]

I am also running esniper on a raspi without any problems.

Please provide the output from following the commands:

$ lsb_release -a
$ dpkg -l | grep -iE '.*curl.*dev.*'
$ ldd /usr/local/bin/esniper | grep curl

This is from my raspi:

$ lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description:    Raspbian GNU/Linux 9.6 (stretch)
Release:    9.6
Codename:   stretch
$ dpkg -l | grep -iE '.*curl.*dev.*'
ii  libcurl4-openssl-dev:armhf            7.52.1-5+deb9u9                    armhf        development files and documentation for libcurl (OpenSSL flavour)
$ ldd /usr/local/bin/esniper | grep curl
    libcurl.so.4 => /usr/lib/arm-linux-gnueabihf/libcurl.so.4 (0x76ee2000)

Do you have a stable internet connection (cable) or dialup (cellular, ...) ?

I personally do not think, that it is a problem with the 'sleep' command.

Can you please provide a log of such a situation, where esniper seems to doesn't wake up ?

Greetings

M.

[NickT]

Thank you.
Here's the o/p that you asked for:

$ lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description: Raspbian GNU/Linux 9.9 (stretch)
Release: 9.9
Codename: stretch

$ dpkg -l | grep -iE '.curl.dev.*'
ii libcurl4-openssl-dev:armhf 7.52.1-5+deb9u9 armhf development files and documentation for libcurl (OpenSSL flavour)

ldd /usr/local/bin/esniper | grep curl
libcurl.so.4 => /usr/lib/arm-linux-gnueabihf/libcurl.so.4 (0xb6f05000)

My internet connection is good (Virgin Media cable, 100MB/s). I 'm going to attach the log of that failed transaction, although it's a bit big. I'm not sure that it will be thatuseful. I think the pertinent bit is that the nohup.out should contain a line sayingsomething like ' sleeping for 1 minute 50 something seconds' and it doesn't.

[NickT]

redacted ny username

[NickT]

Relevant lines from the log ( <<<<< my comments)

*** 2019-05-12 09:30:29.471858 Latency: 1 seconds
*** 2019-05-12 09:30:29.472059 Sleeping for 8 minutes 0 seconds <<<<<< Sleep unti 2 minutes before end
*** 2019-05-12 09:38:29.472330
*** getInfo auction 183799500703 price 1.53 user MYUSERNAME
* 2019-05-12 09:38:29.472733 https://offer.ebay.com/ws/eBayISAPI.dll?ViewBids&item=183799500703 <<<< it woke up and tried this and hung
* 2019-05-12 09:54:58.032095 checking for META Refresh <<<<<<< 16 minutes later- far too late and esniper is just about finished

[Michael S.]

The huge time gap occurs in function 'getInfoTiming' and seems to be the 'httpGet' call.
'httpGet' calls 'httpRequest' where the output ": <url>" and "checking for META Refresh" comes from.</url>

Between this 2 log entries happens the following things:

       if ((curlrc = curl_easy_setopt(easyhandle, CURLOPT_URL, url)))
                return httpRequestFailed(mp);

        if ((curlrc = curl_easy_perform(easyhandle)))
                return httpRequestFailed(mp);

From my point of view it only can be a libcurl issue for any reason.

Greetings

M.

[NickT]

I thinkthat you are probably correct. When I could debug this in Eclipse on an old laptop last year, I remember that it seemed to hang in one of the curl_easy functions. I could see the same bug under Ubuntu 14.04 and on a newer laptop running 18.04.

The question is why just me who reports a fault? I can only conclude that it must be down to my UK location. This would make sense if it was running from a browser in which I login via ebay.co.uk but why from a headless RPi? Perhaps the user-agent? Any weird suggestions gratefully received!

Thanks once again
Nick

[Michael S.]

curl_easy_perform performs the entire request in a blocking manner and returns when done, or if it failed.

https://curl.haxx.se/libcurl/c/curl_easy_perform.html

The questions are:
1) Why it took so long to return from the call ?
2) Why it not results in an error ?

Maybe it's an issue of name resolving. Please try to use another one than the one your provider offers.

Greetings

M.

[NickT]

Thanks Michael
If it were a DNS issue for a browser, I could change the server in Windows and I guess under Ubuntu too. As it's for a headless Pi, I'm stuck with what's avavilable via the VM Superhub (badged Netgearrouter). There's no such option available, unless I buy another router and set the VM one to modem mode.
Regards
Nick

[Michael S.]

You can simply change the nameserver on your raspi until next reboot/change by typing

echo "nameserver 8.8.8.8" > /etc/resolv.conf

(or another nameserver of your choice).

Greetings

[NickT]

Thank you Michael
It's now under test using Google's 8.8.8.8 DNS, which I made permanent via dhcpcd.conf. I'll report back after a long test
Regards
Nick

[NickT]

Sadly the test didn't take too long.

cat /etc/resolv.conf
(hash symbol)Generated by resolvconf
nameserver 8.8.8.8

didn't fix it. Behaviour much the same as before. Starting from 16 minutes to go, it woke for the 10 minute to go slot but failed to wake for the 2 minute one.

[Michael S.]

Could please try another thing.

Using /etc/hosts for the ebay servers temporaly (I'm not sure, if the C-libraries using /etc/hosts):

66.211.160.251 offer.ebay.com
23.211.2.124 www.ebay.com
66.211.185.114 my.ebay.com

The 2nd entry could be a problem, because of an akamaiedge CDN address.
Please have a try - maybe it helps.

Check nsswitch.conf:

# grep host /etc/nsswitch.conf
hosts:          files myhostname mdns4_minimal [NOTFOUND=return] dns mdns4

Greetings

[Michael S.]

If this doesn't help - try this (http.c line 176 ff. - before curl_easy_perform):

$ diff http-old.c http-new.c
177a178,180
>   curl_easy_setopt(easyhandle, CURLOPT_CONNECTTIMEOUT, 15L);
>   curl_easy_setopt(easyhandle, CURLOPT_TIMEOUT, 30L);
> 

Then curl_easy_perform should return after 30 sec. with an error.

Greetings

[NickT]

Thanks, I tried that it didn't wake at 2 minutes to go after putting those lines in hosts which were picked up
from nohup.out
Found bundle for host www.ebay.com: 0x17df240 [can pipeline]
* Re-using existing connection! (#0) with host www.ebay.com
* Connected to www.ebay.com (23.211.2.124) port 443 (#0)

GET /bfl/viewbids/392291265209 HTTP/1.1

The grep gave:
grep host /etc/nsswitch.conf
hosts: files mdns4_minimal [NOTFOUND=return] dns

I'll try adding those lines like :
log(("%s", logUrl ? logUrl : url));
if ((curlrc = curl_easy_setopt(easyhandle, CURLOPT_URL, url)))
return httpRequestFailed(mp);
/** NBT MOD START ***/
curl_easy_setopt(easyhandle, CURLOPT_CONNECTTIMEOUT, 15L);
curl_easy_setopt(easyhandle, CURLOPT_TIMEOUT, 30L);
/*** NBT MOD END *******/

    if ((curlrc = curl_easy_perform(easyhandle)))
            return httpRequestFailed(mp);

 I'll pick another auction with about 15 mins toi run

[Michael S.]

Please remove the additional lines from /etc/hosts. It happened, what I'm afraid of:

Found bundle for host www.ebay.com: 0x17df240 [can pipeline]
Re-using existing connection! (#0) with host www.ebay.com
Connected to www.ebay.com (23.211.2.124) port 443 (#0)

Please try only the 2 lines in http.c I've mentioned above.

Greetings

[NickT]

I'm not sure what you were/are afraid of (please explain) but with the two lines in http.c at 2 minutes to go I got this in nohup.out

• Operation timed out after 28940 milliseconds with 0 bytes received
• Curl_http_done: called premature == 1
• stopped the pause stream!
• Closing connection 0

Latency: 30 seconds
Auction 153479436221: Cannot connect to URL https://offer.ebay.com/ws/eBayISAPI.dll?ViewBids&item=153479436221: Timeout was reached: Operation timed out after 28940 milliseconds with 0 bytes received
Cannot find auction - internet or eBay problem?
Will try again after sleep.
Sun May 12 18:18:02 2019: Sleeping for 1 minutes 2 seconds

I'm going to take the lines out of hosts and reboot and retest now.. Thanks again
Regards
Nick

[NickT]

With lines out of hosts and two lines suggested in http.c I got:

• Operation timed out after 29134 milliseconds with 0 bytes received
• Curl_http_done: called premature == 1
• stopped the pause stream!
• Closing connection 0

Latency: 30 seconds
Auction 303142039211: Cannot connect to URL https://offer.ebay.com/ws/eBayISAPI.dll?ViewBids&item=303142039211: Timeout was reached: Operation timed out after 29134 milliseconds with 0 bytes received
Cannot find auction - internet or eBay problem?
Will try again after sleep.
Sun May 12 18:37:08 2019: Sleeping for 1 minutes 1 seconds

Auction 303142039211: Bidding...
Auction 303142039211: Bid uiid not found

If successful I would have expected :
bidding disabled (because of bid = no )
You would have won.

I don't know what this error signifies. Is it a bug in curl or esniper?
Regards
Nick

[Michael S.]

That's definitly a curl/connection problem. You can clearly see, that no data was returned by curl_easy_perform within 30 sec.

Please try to contact the curl developers on https://github.com/curl/curl/issues

Greetings

[NickT]

Thank you for your help Michael. I did say in bug 764 that I knew it was hanging in curl_easy_perform and had added log lines to prove that.

I wish I could produce the smallest reproducible example of a fault in curl. I shall investigate.

What I can't understand is why this problem occurs on my RPi (and my Ubuntu machines) and you (and presumably every other user) have working systems. After all you have a Stretch Rpi with the same gcc, openssh, curl and evrything else being the same as mine. The only differences that I can think of are our ISPs and locations. How could these be responsible for the fault?
Regards
Nick

[Michael S.]

Hi Nick,

what you can do to analyse the problem, is run esniper with strace:

 $ strace esniper <auctionfile>

You can examine which systemcall is responsible for the hung of curl_easy_perform.

Greetings

[NickT]

I have some more information regarding this bug:
For months running on a raspberry pi with Stretch o/s it has failed and still does.
I have now upgraded my pi to the new Buster raspbian o/s and built esniper and it works OK!

When I was trying to debug it, I also noted that when I ran it on my old laptop (Ubuntu 14.04) through Eclipse, then curl debug showed 'connection nn has died' when it lost the auction id.

However I have this information regarding the pi Raspbian versions, which might be of use to the esniper authors
BUSTER s/w versions

pi@piwifi1bust:/etc $ cat debian_version
10.0

pi@piwifi1bust:/etc $ uname -a
Linux piwifi1bust 4.19.57+ #1244 Thu Jul 4 18:42:50 BST 2019 armv6l GNU/Linux

pi@piwifi1bust:/etc $ curl -V
curl 7.64.0 (arm-unknown-linux-gnueabihf) libcurl/7.64.0 OpenSSL/1.1.1c zlib/1.2.11 libidn2/2.0.5 libpsl/0.20.2 (+libidn2/2.0.5) libssh2/1.8.0 nghttp2/1.36.0 librtmp/2.3
Release-Date: 2019-02-06
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

pi@piwifi1bust:/etc $ esniper -v
esniper version 2.35.1

STRETCH s/w versions

pi@0wifi:/etc $ cat debian_version
9.9

pi@0wifi:/etc $ uname -a
Linux 0wifi 4.14.98+ #1200 Tue Feb 12 20:11:02 GMT 2019 armv6l GNU/Linux

pi@0wifi:/etc $ curl -V
curl 7.52.1 (arm-unknown-linux-gnueabihf) libcurl/7.52.1 OpenSSL/1.0.2r zlib/1.2.8 libidn2/0.16 libpsl/0.17.0 (+libidn2/0.16) libssh2/1.7.0 nghttp2/1.18.1 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

pi@0wifi:/etc $ esniper -v
esniper version 2.35.1

I have just built the Buster one from the git tip and I had built the Stretch one may times. When building the Buster version I had to selete aclocal.m4 and chane references from 1.14 to 1.16 , as buster came with automake 1.16.1.

I hope all this info is of use to someone.

[Michael S.]

Thank you for that information. This is the evidence, that nothing is wrong with esniper.

Just one remark on automake:
There is no need to edit any files. You just have to run the complete automake + autoconf process:

$ aclocal
$ autoheader
$ automake --force-missing --add-missing --copy -W all
$ autoconf
$ ./configure
$ make

[NickT]

Hello Michael, thank you for all your help on this bug - I'm happy to attribute the errors in operation firmly at the feet of the curl's authors.

To expand - this morning I started with the official Raspberry PI last image of 2019-04-08-raspbian-stretch-lite.img. I put git, libcurl4-gnutls-dev and automake on to it and that's all. I built esniper and tested it with "bid = no" set. It failed to wake up as before. The curl version is the same as before (7.52.1). After an apt-get update, it still has that as the latest version of curl available. When I was trying to debug it, I remember seeing it hanging in a curl_easy_perform call.

With the buster load and a curl version of 7.64.0, I see success every time so far. I remember that you said you were using a raspberry pi without problems and can only assume you were using stretch, so I don't know how you managed it.

Now that I've moved my 'always on' esniper to a pizero running buster, I have no problems and all prvious problems were because of a bug in curl 7.52.1.

Thanks once again,

regards
Nick

[Michael S.]

My Raspi 2 is still on "Raspbian GNU/Linux 9.9 (stretch)" and Curl is Version 7.52.1, but I do not have any problems.