#742 built from Git quits with "Auction has ended" 10 minutes before actual end

[NickT]

I'm assuming that the very latest source is stored in the Git repository retried by:
git clone https://git.code.sf.net/p/esniper/git esniper-git
I have built esniper on two different Rasperry Pis and although the initial start is successful, it quits exactly 10 minutes before the actual end of the auction. The end of the log file I see is

*** 2018-02-19 20:21:42.397152

getUntil('"')

01000200000050cc5a3343a9f53d584b0809bd1486bc905f4501d93cff3e5b8494a053469e74a2f2ead22f9cea593c30385af02d10ad55b17c70119b5ef4076fb4ac5a2edbc62d54e2e0dc9b3d6f35da70e2e6da0a1cb8"

*** 2018-02-19 20:21:42.397398 preBid(): bidsrt is "01000200000050cc5a3343a9f53d584b0809bd1486bc905f4501d93cff3e5b8494a053469e74a2f2ead22f9cea593c30385af02d10ad55b17c70119b5ef4076fb4ac5a2edbc62d54e2e0dc9b3d6f35da70e2e6da0a1cb8"

*** 2018-02-19 20:21:42.397537 Auction 323070969389: Auction has ended

The end of the auction was at 20:31.
I have greped for "10 minutes" - no hits, but did find several references to "600" (presumably seconds) in auctio.c. I'm unable to debug this code as I run my Raspberry Pi machines headless.
Intrersting point is that if the esniper is launched after a time ten minutes before the auction end the bid is accepted successfully.

I do hope that I have used the correct source and that this ticket is in an acceptable format. It is easy to test this bug as a bid can be made and if esniper is still running 9 minutes or less before the auction end, then the process can be killed to stop the bid.

[NickT]

I have explored this bug a bit further and think that it only occurs if esniper is launched the day before the auction actually ends. I launched it yesterday on my Raspberry Pi (Stretch Lite) and set it to snipe a bid before the auction end time of 8.11 this morning. I also added some log lines to catch where it hit the error ae_ended. At 8.01 esniper quit with:

*** 2018-02-25 08:01:34.031779
getUntil('"')
01000200000050222ee8d3bebf5dbbd8bb7d126b4e6be0d31ac9c089fb17e50c4ae28cb9852164f256cbbd1903fed2e0f53081552cf365345c1fbdcffb56348948542ecc02a00507f8809a99c84c12b7d426484ca00f5e"
*** 2018-02-25 08:01:34.032037 preBid(): bidsrt is "01000200000050222ee8d3bebf5dbbd8bb7d126b4e6be0d31ac9c089fb17e50c4ae28cb9852164f256cbbd1903fed2e0f53081552cf365345c1fbdcffb56348948542ecc02a00507f8809a99c84c12b7d426484ca00f5e"
*** 2018-02-25 08:01:34.032176 quitting at 1065
*** 2018-02-25 08:01:34.032308 Auction 302642822416: Auction has ended

I added the quitting at 1065 log line with:

int
snipeAuction(auctionInfo *aip)
{
        int won = 0;
        char *tmpUsername;
        if (!aip)
                return 0;
        if (options.debug)
                logOpen(aip, options.logdir);
        tmpUsername = stars(strlen(options.username));
        log(("auction %s price %s quantity %d user %s bidtime %ld\n",
             aip->auction, aip->bidPriceStr,
             options.quantity, tmpUsername, options.bidtime));
        free(tmpUsername);
        if (ebayLogin(aip, 0)) {
                printAuctionError(aip, stderr);
                return 0;
        }
        /* 0 means "now" */
        if ((options.bidtime == 0) ? preBid(aip) : watch(aip)) {
                printAuctionError(aip, stderr);
                if (aip->auctionError != ae_highbidder)
                        return 0;
        }
        /* ran out of time! */
        if (aip->endTime <= time(NULL)) {
                printLog(stdout, "quitting at 1065\n");    // <<<<<<< EXITS FROM HERE
                (void)auctionError(aip, ae_ended, NULL);
                printAuctionError(aip, stderr);

I shall try some more, logging the aip->endTime and current time.

All assistance will be greatly appreciated.

Update: I just noticed that in the log file at 6.27 we have:

*** 2018-02-25 06:27:13.857612 Time remaining: 0 days 1 hours 44 mins 13 secs (6253 seconds)
*** 2018-02-25 06:27:13.857964 End time: 25/02/2018 07:55:36

which is clearly incorrect

Further update:
I can't help but think that this bug has some connection to the changes made for ticket 737. I should add that esniper started and ran to completion a day or two later, ran successfully and made a winning bid successfully in January

[NickT]

Latest test: esniper started yesterday for an auction ending at 8:58 today, again ended too early.
This slight modification to the logging code:

/ ran out of time! /
if (aip->endTime <= time(NULL)) {
printLog(stdout, "quitting at 1065\n");
printLog(stdout, "aip->endTime is %ld\n",aip->endTime);
printLog(stdout, "current time is %ld\n", time(NULL));
tmPtr = localtime(&(aip->endTime));
strftime(timestr , 20, "%d/%m/%Y %H:%M:%S", tmPtr);
printLog(stdout, "End time as a date string: %s\n", timestr);
(void)auctionError(aip, ae_ended, NULL);
printAuctionError(aip, stderr);
return 0;
}

Produced this log:

*** 2018-02-26 08:48:03.034531 quitting at 1065
*** 2018-02-26 08:48:03.034662 aip->endTime is 1519634540
*** 2018-02-26 08:48:03.034800 current time is 1519634883
*** 2018-02-26 08:48:03.034972 End time as a date string: 26/02/2018 08:42:20
*** 2018-02-26 08:48:03.035095 Auction 263505969202: Auction has ended

[Michael S.]

Please attach the html-source of one of this sides. Without the html-source the developers cant investigate the problem.

[Michael S.]

Probably duplicate of #737.