#1111 ✓resolved
Therese Telepski

JBW 2.1 Pre6 fails to snipe

Reported by Therese Telepski | May 5th, 2010 @ 08:32 AM | in 2.1 Release

In some instances JBW 2.1 Pre6 seems to fail sniping on a German Win 7 x64 with Java 6.20.

Computer time is synchronized with web servers and shows up correctly.

Items can be bid on manually on ebay.de and ebay.co.uk w/o problems.

Here's an excerpt from the error log:

Wed May 05 13:06:00 CEST 2010: Time delta with ebay is 32462
Wed May 05 13:36:01 CEST 2010: Time delta with ebay is 34188
Wed May 05 13:37:15 CEST 2010: No items on page!
Wed May 05 13:44:36 CEST 2010: 220596980079 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Cancelling snipe, auction is reported as ended.
Wed May 05 13:44:36 CEST 2010: Cancelling Snipe for: TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m(220596980079)
Wed May 05 13:44:36 CEST 2010: 220596980079 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Cancelling snipe.
Wed May 05 14:06:01 CEST 2010: Time delta with ebay is 36102
Wed May 05 14:36:03 CEST 2010: Time delta with ebay is 36391
Wed May 05 14:37:15 CEST 2010: No items on page!
Wed May 05 15:06:00 CEST 2010: Time delta with ebay is 40235
Wed May 05 15:16:03 CEST 2010: 220597005543 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Cancelling snipe, auction is reported as ended.
Wed May 05 15:16:03 CEST 2010: Cancelling Snipe for: TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m(220597005543)
Wed May 05 15:16:03 CEST 2010: 220597005543 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Cancelling snipe.
Wed May 05 15:36:01 CEST 2010: Time delta with ebay is 41767
Wed May 05 15:36:32 CEST 2010: Failed to load auction title from header: "eBay - The UK's Online Marketplace"
Wed May 05 15:36:32 CEST 2010: There was a problem parsing the title.
Wed May 05 15:36:32 CEST 2010: 220598556087 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Communications failure talking to the server.
Wed May 05 15:36:32 CEST 2010: Failed to parse auction!  Bad return result from auction server.
Wed May 05 15:36:32 CEST 2010: 220598556087 (TCM Cordless Desktop / Funktastatur+Maus NEU / 1,5-3m) - Failed to load from server!
Wed May 05 15:37:21 CEST 2010: No items on page!
Wed May 05 16:05:57 CEST 2010: Time delta with ebay is 44644
Wed May 05 16:06:37 CEST 2010: 120562894913 (Sapphire HD5870 Grafikkarte ATI 5870 1024 MB HDMI ) - Cancelling snipe, auction is reported as ended.
Wed May 05 16:06:37 CEST 2010: Cancelling Snipe for: Sapphire HD5870 Grafikkarte ATI 5870 1024 MB HDMI (120562894913)
Wed May 05 16:06:37 CEST 2010: 120562894913 (Sapphire HD5870 Grafikkarte ATI 5870 1024 MB HDMI ) - Cancelling snipe.
Wed May 05 16:35:57 CEST 2010: Time delta with ebay is 46455
Wed May 05 16:37:14 CEST 2010: No items on page!
Wed May 05 17:05:56 CEST 2010: Time delta with ebay is 48648

What's a bit confusing are recurring messages about:

a. HUGE and randomly changing time deltas with eBay (Whatever this means, usually a delta describes a difference)
b. Allegedly 'No items on page'.

If you look for 'TCM Cordless Desktop' from seller 'hegermain'
you find a bunch of items I'm interested in — already several
of those auctions ended below my snipe of 3.60 EUR.

If you win one, just let me know; I'm taking up to three
of those kits.

Sincerely,

Therese

Comments and changes to this ticket

  • David Frith

    David Frith May 7th, 2010 @ 01:05 AM

    I have something similar with a failed snipe.

    My console log contains :-

    Thu May 06 23:02:41 BST 2010: Thu May 06 23:02:41 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Preparing snipe.
    Thu May 06 23:02:41 BST 2010: Getting the sign in cookie.
    Thu May 06 23:02:46 BST 2010: Done getting the sign in cookie.
    Thu May 06 23:02:46 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Loading bid request...
    Thu May 06 23:02:48 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Done loading bid request, got form...
    Thu May 06 23:04:40 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Firing actual snipe.
    Thu May 06 23:04:40 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Submitting bid form.
    Thu May 06 23:04:45 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Done submitting bid form.
    Thu May 06 23:04:45 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Loading post-bid data.
    Thu May 06 23:04:45 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Done loading post-bid data.
    Thu May 06 23:04:45 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Snipe apparently failed, as the auction cannot be bid on anymore: DRAYTON RF DIGISTAT (RF 601 MODEL)
    Thu May 06 23:04:45 BST 2010: Snipe apparently failed, as the auction cannot be bid on anymore: DRAYTON RF DIGISTAT (RF 601 MODEL)
    Thu May 06 23:04:52 BST 2010: Sum serious exception!
    java.lang.ClassCastException: java.lang.String cannot be cast to com.jbidwatcher.auction.AuctionEntry
    at com.jbidwatcher.ui.AuctionsUIModel.sum(AuctionsUIModel.java:227)
    at com.jbidwatcher.ui.AuctionsUIModel.updateSum(AuctionsUIModel.java:143)
    at com.jbidwatcher.ui.AuctionsUIModel.access$000(AuctionsUIModel.java:34)
    at com.jbidwatcher.ui.AuctionsUIModel$1.valueChanged(AuctionsUIModel.java:130)
    at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:167)
    at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:147)
    at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:194)
    at javax.swing.DefaultListSelectionModel.insertIndexInterval(DefaultListSelectionModel.java:615)
    at javax.swing.JTable.tableRowsInserted(JTable.java:4468)
    at javax.swing.JTable.tableChanged(JTable.java:4404)
    at com.jbidwatcher.ui.table.TableSorter$3.run(TableSorter.java:223)
    at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)
    at java.awt.EventQueue.dispatchEvent(EventQueue.java:633)
    at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:296)
    at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:211)
    at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:201)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:196)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:188)
    at java.awt.EventDispatchThread.run(EventDispatchThread.java:122)
    
    Hope this helps to discover what's going wrong.

    All the best, David

  • Therese Telepski

    Therese Telepski May 9th, 2010 @ 02:10 PM

    Update - about every second snipe fails with error messages similar to the one mentioned in my first post above. Unsatisfactory.

    Sincerely,

    Therese

  • cdmackay

    cdmackay May 9th, 2010 @ 04:05 PM

    I just had two snipes fail "auction is reported as ended", some errors in common with the above.

    The first failure (140399643070) also claimed "Communications failure talking to the server", although I wasn't aware of any network issue at the time.

    The second failure (140399646458) doesn't mention this.

    Sun May 09 17:56:28 BST 2010: JBidwatcher 2.1pre6-
    Sun May 09 17:56:28 BST 2010: Sun Microsystems Inc. Java, version 1.6.0_18 on SunOS
    ...
    4 snipes outstanding
    101 auctions completed
    130 auctions total
    Sun May 09 18:37:59 BST 2010: Failed to load auction title from header: "eBay - New & used electronics, cars, apparel, collectibles, sporting goods & more at low prices"
    Sun May 09 18:37:59 BST 2010: There was a problem parsing the title.
    Sun May 09 18:37:59 BST 2010: 140403797067 (OPTICRON SR GA 8X32 BINOCULAR. SUPERB OPTICS) - Communications failure talking to the server.
    Sun May 09 18:37:59 BST 2010: Failed to parse auction!  Bad return result from auction server.
    Sun May 09 18:37:59 BST 2010: 140403797067 (OPTICRON SR GA 8X32 BINOCULAR. SUPERB OPTICS) - Failed to load from server!
    Sun May 09 18:50:52 BST 2010: Failed to load auction title from header: "eBay - New & used electronics, cars, apparel, collectibles, sporting goods & more at low prices"
    Sun May 09 18:50:52 BST 2010: There was a problem parsing the title.
    Sun May 09 18:50:52 BST 2010: 140399643070 (RUSSIAN 12X40 BINOCULAR. HIGH QUALITY OPTICS) - Communications failure talking to the server.
    Sun May 09 18:50:52 BST 2010: Failed to parse auction!  Bad return result from auction server.
    Sun May 09 18:50:52 BST 2010: 140399643070 (RUSSIAN 12X40 BINOCULAR. HIGH QUALITY OPTICS) - Failed to load from server!
    Sun May 09 19:17:43 BST 2010: Failed to load auction title from header: "eBay - New & used electronics, cars, apparel, collectibles, sporting goods & more at low prices"
    Sun May 09 19:17:43 BST 2010: There was a problem parsing the title.
    Sun May 09 19:17:43 BST 2010: 300420805609 (SWIFT10x50 KESTREL HR5 (AUDUBON) MC BINOCULARS BOXED. ) - Communications failure talking to the server.
    Sun May 09 19:17:43 BST 2010: Failed to parse auction!  Bad return result from auction server.
    Sun May 09 19:17:43 BST 2010: 300420805609 (SWIFT10x50 KESTREL HR5 (AUDUBON) MC BINOCULARS BOXED. ) - Failed to load from server!
    Sun May 09 19:20:53 BST 2010: 140399643070 (RUSSIAN 12X40 BINOCULAR. HIGH QUALITY OPTICS) - Cancelling snipe, auction is reported as ended.
    Sun May 09 19:20:53 BST 2010: Cancelling Snipe for: RUSSIAN 12X40 BINOCULAR. HIGH QUALITY OPTICS(140399643070)
    Sun May 09 19:20:53 BST 2010: 140399643070 (RUSSIAN 12X40 BINOCULAR. HIGH QUALITY OPTICS) - Cancelling snipe.
    Sun May 09 19:20:53 BST 2010: MQ_my: Postponing Message: CANCEL 140399643070
    Sun May 09 19:20:53 BST 2010: MQ_tray: Postponing Message: TOOLTIP Next Snipe at: 09-May-2010 19:52:46 BST
    3 snipes outstanding
    103 auctions completed
    130 auctions total
    Sun May 09 19:52:58 BST 2010: 140399646458 (RUSSIAN 7X50 BINOCULAR. HIGH QUALITY OPTICS) - Cancelling snipe, auction is reported as ended.
    Sun May 09 19:52:58 BST 2010: Cancelling Snipe for: RUSSIAN 7X50 BINOCULAR. HIGH QUALITY OPTICS(140399646458)
    Sun May 09 19:52:58 BST 2010: 140399646458 (RUSSIAN 7X50 BINOCULAR. HIGH QUALITY OPTICS) - Cancelling snipe.
    Sun May 09 19:52:58 BST 2010: MQ_my: Postponing Message: CANCEL 140399646458
    Sun May 09 19:52:58 BST 2010: MQ_tray: Postponing Message: TOOLTIP Next Snipe at: 10-May-2010 14:11:44 BST
    2 snipes outstanding
    104 auctions completed
    130 auctions total
    ...
    
  • Morgan Schweers

    Morgan Schweers May 10th, 2010 @ 03:39 AM

    • Milestone set to 2.1 Release
    • Tag changed from bug, parsing, snipe to bug, parsing, serious, snipe
    • State changed from “new” to “open”

    Greetings,
    In reverse order...

    @cdmackay - What version are you using? It doesn't look like it's showing the git version information, which seems weird. You're also getting very bad auction data; none of them have the standard eBay auction title information in their title tags. I'm not sure how that happens, but it certainly isn't going to give good eBay item data, which means bad times, which means bad snipes. It's also concerning, because two of the threads (MQ_my and MQ_tray) never started up, which makes me worry about other threads that may have failed to start up, like...sniping.

    @Therese - Yes, that would be unsatisfactory. I'd call it sucking, in fact. :(

    @David Frith - Do you have your snipe time set at 4 seconds? I strongly recommend against putting a number closer than 10 seconds, in general. This is a perfect example; it started the single-page process of submitting the bid at 23:04:40, and it took five seconds to get a response, by which point the response was, essentially, 'This auction has ended.' JBidwatcher can't make the packets go any faster, unfortunately. In your case, JBidwatcher did everything 'right', it just couldn't get the packet to eBay in time, starting 4 seconds before the end.

    Now, to the meat of the bug, @Therese's log. I'm sorry you're having these problems... The 'time delta' is the official time as returned by eBay minus the time when your computer started the request MINUS half the time it took to get the page from eBay. The number is expressed in milliseconds.

    So if your clock reads 12:34:56 (adjusted to GMT), and eBay's clock reads 12:36:22 (adjusted to GMT), and it takes 2.4 seconds to load the page, the time delta will be 12:36:22-12:34:56 (86000 milliseconds) - 2400 milliseconds, or 83600.

    It's not random; your system clock was systematically losing time compared to eBay's time. Every half hour it lost between 200ms and about 3 seconds, ending up over a minute at various places in the card file. Do you run any kind of virtual machines? I've seen time slippage like that with VMs, but not in general use.

    To the log files...

    First off, I noticed the problem with the version number again. I'll have to dig into that, that's bad.

    There's a bunch of sum() exceptions; that'll be something to fix.

    Then at roughly 8:29pm, you cancel snipes for an AppleMacbook and a Vorwerk Kobold. You also are having trouble with eBay listings coming back with essentially static, non-item pages.

    There's a ton of sleep-wake warnings, and...I've got to get to sleep. I'll finish going through the log file tomorrow, but I notice a bid error page, and one of the more complex scenes in JBidwatcher. Two multisnipes, overlapped tightly, where you don't know whether the first is done or not until very late in the bidding process for the second. It worked fine, though, apparently.

    ...bleh, I'll get back to this.

    -- Morgan Schweers, Cyber*FOX*!

  • cdmackay

    cdmackay May 10th, 2010 @ 06:41 AM

    thanks Morgan,

    @cdmackay - What version are you using?

    2.1pre6, as it says in the msg :)

    Mon May 10 11:49:55 BST 2010: JBidwatcher 2.1pre6-

    I start it like this:

    /usr/bin/java -Xmx256m -jar JBidwatcher-2.1pre6.jar

    # MD5 16c81ed8a33fd346552044a4036b5977 JBidwatcher-2.1pre6.jar

    java version "1.6.0_18" Java(TM) SE Runtime Environment (build 1.6.0_18-b07) Java HotSpot(TM) Server VM (build 16.0-b13, mixed mode)

    It doesn't look like it's showing the git version information, which seems weird. You're also getting very bad auction data; none of them have the standard eBay auction title information in their title tags. I'm not sure how that happens, but it certainly isn't going to give good eBay item data, which means bad times, which means bad snipes.

    for what it's worth, the times in the GUI listings are indeed correct, so it does seem to be getting good data, at some point.

    It's also concerning, because two of the threads (MQ_my and MQ_tray) never started up, which makes me worry about other threads that may have failed to start up, like...sniping.

    I am displaying it remotely, via X. I assumed that was why I saw tray issues, and the GNOME tray probably isn't accessible to jbw running on the remote system.

    I also had a snipe fail this morning, where jbw didn't even login to eBay on startup. Is that supposed to happen?

    I had setup a snipe last night, then killed off jbw. I then started it this morning, verified the snipe was still there, and left it, having done nothing else. I've done this dozens of times successfully in the past (but not with 2.1pre6).

    Today, the snipe did not fire, and when I checked on it after, I saw that jbw was still not even logged in to ebay. The log to that point was:

    Mon May 10 11:49:55 BST 2010: JBidwatcher 2.1pre6-
    Mon May 10 11:49:55 BST 2010: Sun Microsystems Inc. Java, version 1.6.0_18 on SunOS
    Mon May 10 11:49:56 BST 2010: Loaded the appropriate driver.
    Mon May 10 11:49:56 BST 2010: Connected to database jbdb (JBidwatcher DataBase)
    Mon May 10 11:49:56 BST 2010: Auction information database already exists.
    Mon May 10 11:49:56 BST 2010: Closed connection
    Mon May 10 11:49:56 BST 2010: Database shut down normally
    Mon May 10 11:49:56 BST 2010: Loaded the appropriate driver.
    Mon May 10 11:49:56 BST 2010: Connected to database jbdb (JBidwatcher DataBase)
    Mon May 10 11:49:56 BST 2010: Closed connection
    Mon May 10 11:49:56 BST 2010: Database shut down normally
    Mon May 10 11:49:56 BST 2010: Scripting is not enabled.
    Mon May 10 11:49:57 BST 2010: Loaded the appropriate driver.
    Mon May 10 11:49:57 BST 2010: Connected to database jbdb (JBidwatcher DataBase)
    Mon May 10 11:49:57 BST 2010: Loading listings from the database (21/128/128 entries, 128/128 auctions)
    Mon May 10 11:49:57 BST 2010: Done with the initial load (got 21 active entries)
    Mon May 10 11:49:57 BST 2010: Auction Entries loaded
    Mon May 10 11:49:57 BST 2010: Completed loader spun off
    Mon May 10 11:49:57 BST 2010: Snipes processed
    Mon May 10 11:49:57 BST 2010: setServer: 0.0 x 21(0)
    Mon May 10 11:49:57 BST 2010: addEntry: 7.571428571428571 x 21(159)
    Mon May 10 11:49:57 BST 2010: snipeSetup: 0.5 x 2(1)
    Mon May 10 11:49:57 BST 2010: findAll: 14.0 x 1(14)
    Mon May 10 11:49:57 BST 2010: getAuction: 1.2380952380952381 x 21(26)
    Mon May 10 11:49:57 BST 2010: addEntry-current: 5.5 x 2(11)
    Mon May 10 11:49:57 BST 2010: addEntry-My eBay: 6.421052631578948 x 19(122)
    Mon May 10 11:49:57 BST 2010: counts: 35.0 x 1(35)
    Mon May 10 11:49:57 BST 2010: Last 10 from addEntry: 12, 12, 11, 5, 6, 5, 5, 5, 5, 5
    Mon May 10 11:49:57 BST 2010: MQ_my: Postponing Message: CANCEL 140403797067
    Mon May 10 11:49:57 BST 2010: MQ_my: Postponing Message: SNIPE 140403797067
    Mon May 10 11:49:57 BST 2010: MQ_my: Postponing Message: CANCEL 170482312340
    Mon May 10 11:49:57 BST 2010: MQ_my: Postponing Message: SNIPE 170482312340
    Exception in thread "Thread-28" java.lang.UnsatisfiedLinkError: org.jdesktop.jdic.tray.internal.impl.DisplayThread.initTray()V
    at org.jdesktop.jdic.tray.internal.impl.DisplayThread.initTray(Native Method)
    at org.jdesktop.jdic.tray.internal.impl.DisplayThread.run(Unknown Source)
    Mon May 10 11:50:33 BST 2010: MQ_my: Postponing Message: SNIPE 140403797067
    Mon May 10 11:50:33 BST 2010: MQ_tray: Postponing Message: TOOLTIP Next Snipe at: 10-May-2010 14:11:44 BST
    2 snipes outstanding
    107 auctions completed
    128 auctions total
    
    after I noted the snipe had not fired, and the eBay login hadn't occurred, I manually did a "get my eBay items", and that worked:
    Mon May 10 14:19:26 BST 2010: Getting the sign in cookie.
    Mon May 10 14:19:29 BST 2010: Done getting the sign in cookie.
    Mon May 10 14:19:29 BST 2010: Loading page 1 of My eBay for user cdmackay
    Mon May 10 14:19:29 BST 2010: URL: http://my.ebay.com/ws/eBayISAPI.dll?MyEbayBeta&SortOrder=ASCEND&GotoPage=1&View=WatchingNext&Column=EndTime&CurrentPage=MyeBayNextWatching
    Mon May 10 14:19:29 BST 2010: MQ_tray: Postponing Message: TOOLTIP Next Snipe at: 10-May-2010 14:11:44 BST
    2 snipes outstanding
    107 auctions completed
    128 auctions total
    Mon May 10 14:19:32 BST 2010: Mon May 10 14:19:32 BST 2010: 140403797067 (OPTICRON SR GA 8X32 BINOCULAR. SUPERB OPTICS) - Cancelling snipe, auction is reported as ended.
    Mon May 10 14:19:32 BST 2010: Cancelling Snipe for: OPTICRON SR GA 8X32 BINOCULAR. SUPERB OPTICS(140403797067)
    Mon May 10 14:19:32 BST 2010: Mon May 10 14:19:32 BST 2010: 140403797067 (OPTICRON SR GA 8X32 BINOCULAR. SUPERB OPTICS) - Cancelling snipe.
    Mon May 10 14:19:32 BST 2010: MQ_my: Postponing Message: CANCEL 140403797067
    Mon May 10 14:19:33 BST 2010: MQ_tray: Postponing Message: TOOLTIP Next Snipe at: 10-May-2010 19:44:37 BST
    1 snipes outstanding
    108 auctions completed
    128 auctions total
    

    am happy to try further testing as required...

  • cdmackay

    cdmackay May 10th, 2010 @ 06:49 AM

    I reproduced the git version problem on my local system:

    $ java -Xmx256m -jar JBidwatcher-2.1pre6.jar Mon May 10 14:49:14 BST 2010: JBidwatcher 2.1pre6-
    Mon May 10 14:49:14 BST 2010: Sun Microsystems Inc. Java, version 1.6.0_20 on Linux

    $ java -version java version "1.6.0_20"
    Java(TM) SE Runtime Environment (build 1.6.0_20-b02)
    Java HotSpot(TM) Client VM (build 16.3-b01, mixed mode, sharing)

  • David Sanderson

    David Sanderson May 10th, 2010 @ 10:07 PM

    I noticed that JBidwatcher on OS X 10.5.8 moved an auction from
    "Current" to "Complete" even though it was not actually complete. This appeared to correlate with a new bid being placed on the item
    (Mon May 10 18:01:01 EDT 2010). Here's the log.

    [...log file dsanderson.log...]

  • Hauke Fath

    Hauke Fath May 11th, 2010 @ 03:13 AM

    Morgan,

    thanks for the detailed description of how jbw is supposed to do its timing.

    The current jbw doesn't seem to do it that way, though. For the following log, I set up jbw to bid 25 sec in advance, and also (just to be sure) placed a manual bid. There was no competition, and jbw's snipe was cancelled since it came 5 sec late.

    For the second bid, I set jbw to snipe 35 sec in advance (that's the "...saving to:" entry), and again placed a manual bid. Again, there was no competition, And again, the snipe was cancelled, since it came in - 5 sec late. See the pattern?

    The Powerbook running MacOS X 10.4.11 is synced through ntp, and it is sitting on a fat pipe, so bandwidth is not an issue.


    Tue May 11 11:33:07 CEST 2010: Saving to: /Users/hauke/Library/Preferences/JBidwatcher/JBidWatch.cfg
    Tue May 11 11:35:32 CEST 2010: Time delta with ebay is -5276
    Tue May 11 11:53:02 CEST 2010: 370373871635 (Explosionszeichnung Rolleicord Va) - Cancelling snipe, auction is reported as ended.
    Tue May 11 11:53:02 CEST 2010: Cancelling Snipe for: Explosionszeichnung Rolleicord Va(370373871635)
    Tue May 11 11:53:02 CEST 2010: 370373871635 (Explosionszeichnung Rolleicord Va) - Cancelling snipe.
    Tue May 11 11:54:41 CEST 2010: Failed to get https://my.jbidwatcher.com/services/account?browse_to=1: I'm sorry Dave, I'm afraid I can't do that.
    Tue May 11 11:54:41 CEST 2010: Saving to: /Users/hauke/Library/Preferences/JBidwatcher/JBidWatch.cfg
    Tue May 11 11:56:38 CEST 2010: 370373872791 (Explosionszeichnung Rolleiflex 4*4) - Cancelling snipe, auction is reported as ended.
    Tue May 11 11:56:38 CEST 2010: Cancelling Snipe for: Explosionszeichnung Rolleiflex 4*4(370373872791)
    Tue May 11 11:56:38 CEST 2010: 370373872791 (Explosionszeichnung Rolleiflex 4*4) - Cancelling snipe.

  • David Frith

    David Frith May 11th, 2010 @ 05:20 AM

    Thanks Morgan, I see that my close to end snipe was probably too close. I was confused by the subsequent error messages in the log into thinking that jbidwatcher had broken but I've had subsequent snipes work. I think at the time of that error, my son was doing a mega-download which gobbled all the bandwidth through the router and my snipes took longer than usual. It's the first one for a long time that failed hence why I've not modified the snipe time from 4 seconds.

    Keep up the good work.

  • Hauke Fath

    Hauke Fath May 11th, 2010 @ 10:10 AM

    Another attempt with 60 sec, and again the jbw snipes exactly 5 sec after the auction has ended:

    Tue May 11 17:05:15 CEST 2010: Saving to: /Users/hauke/Library/Preferences/JBidwatcher/JBidWatch.cfg
    Tue May 11 17:05:28 CEST 2010: Time delta with ebay is -5464
    Tue May 11 17:35:28 CEST 2010: Time delta with ebay is -5155
    Tue May 11 18:05:27 CEST 2010: Time delta with ebay is -5742
    Tue May 11 18:35:27 CEST 2010: Time delta with ebay is -6123
    Tue May 11 18:46:05 CEST 2010: Failed to get https://my.jbidwatcher.com/services/account?browse_to=1: I'm sorry Dave, I'm afraid I can't do that.
    Tue May 11 18:46:05 CEST 2010: Saving to: /Users/hauke/Library/Preferences/JBidwatcher/JBidWatch.cfg
    Tue May 11 18:50:48 CEST 2010: Failed to get https://my.jbidwatcher.com/services/account?browse_to=1: I'm sorry Dave, I'm afraid I can't do that.
    Tue May 11 18:50:48 CEST 2010: Saving to: /Users/hauke/Library/Preferences/JBidwatcher/JBidWatch.cfg
    Tue May 11 18:53:43 CEST 2010: 270572532411 (ORWO SL Kassette - NP 20 - Schwarzweiß-Negativfilm) - Cancelling snipe, auction is reported as ended.
    Tue May 11 18:53:43 CEST 2010: Cancelling Snipe for: ORWO SL Kassette - NP 20 - Schwarzweiß-Negativfilm(270572532411)
    Tue May 11 18:53:43 CEST 2010: 270572532411 (ORWO SL Kassette - NP 20 - Schwarzweiß-Negativfilm) - Cancelling snipe.

  • Morgan Schweers

    Morgan Schweers May 11th, 2010 @ 12:09 PM

    Greetings,
    @Hauke - Yours isn't actually trying to snipe at all. This is why I ask for the entire log file as an attachment; your sniping process is not running, as far as I can tell. If it were running, it would show like David Frith's messages above:

    Thu May 06 23:02:46 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Loading bid request...
    Thu May 06 23:02:48 BST 2010: 220597791422 (DRAYTON RF DIGISTAT (RF 601 MODEL)) - Done loading bid request, got form...
    
    If something like that isn't showing up two minutes before the auction end, then your snipe thread isn't running. What I need to understand is why, and I think that takes at least the entire log file. Please don't paste it into the bug, though. There's a section just below this, 'Attach a file', which is what you'll want to use.

    I have to go back and clean up the log files that have been pasted in...

    -- Morgan Schweers, CyberFOX!

  • Morgan Schweers

    Morgan Schweers May 11th, 2010 @ 12:19 PM

    Uploading dsanderson's log as an attachment.

  • Hauke Fath

    Hauke Fath May 11th, 2010 @ 03:06 PM

    Here goes the logfile for yesterday's snipe attempts (~500 K).

  • Hauke Fath

    Hauke Fath May 11th, 2010 @ 03:21 PM

    ...and here's the next one. I terminated jbw in between, and this one actually has a timely snipe (set to 60 sec, sniped 55 sec before end).

  • Therese Telepski

    Therese Telepski May 13th, 2010 @ 10:37 AM

    And another item ( eBay 130388357660 ) which ended well below my snipe with JBW just cancelling any action.

    The snipe time is set to 62 seconds ahead of the auction end, the computer is synchronized every 30 minutes with the time servers of the PTB (Physikalisch Technische Bundesanstalt Braunschweig, maintaining the German time standard with an accuracy of about 10^-14).

    Z:((

    Therese

  • Morgan Schweers

    Morgan Schweers May 13th, 2010 @ 12:38 PM

    Greetings,
    Actually that log file is really interesting; specifically how a snipe fired 'successfully' (i.e. it placed the bid) at Wed May 12 13:31:25 CEST 2010 (Preparing snipe.), but then appeared to fail to snipe a different entry at Wed May 12 16:08:44 CEST 2010 (Cancelling snipe, auction is reported as ended.)

    Then it successfully placed a bid again at Wed May 12 17:31:01 CEST 2010 (Preparing snipe.), and again at Wed May 12 20:18:23 CEST 2010.

    An item legitimately was removed from the site (330431814831), which canceled your snipe on it.

    It looks like it fails to place a bid for a snipe again at Thu May 13 16:48:56 CEST 2010 (Cancelling snipe, auction is reported as ended.), and then at Thu May 13 19:07:54 CEST 2010 (Cancelling snipe, auction is reported as ended.) which is the item number you listed.

    That's where the log ends.

    You manually cancel snipes a lot, it seems (or delete the items, which triggers snipe cancellations, I can't tell from the log file), and have lots of socket timeouts and non-item responses from eBay, but neither of those should be causes for this problem.

    I'm going to look into whether a snipe cancellation might be cancelling the wrong snipes as well as the right ones... I'm pretty sure it doesn't, but I need to dig into the code and find out. The weird part is that you have successful snipes interleaved with ones where the program seems to have completely forgotten to snipe.

    -- Morgan

  • nabsltd

    nabsltd May 13th, 2010 @ 08:03 PM

    I have similar errors:

    Wed May 12 14:46:47 EDT 2010: 200469209685 (Hauppauge Win TV-HVR 2250 Kit) - Cancelling snipe, auction is reported as ended.
    Wed May 12 14:46:47 EDT 2010: Cancelling Snipe for: Hauppauge Win TV-HVR 2250 Kit(200469209685)
    Wed May 12 14:46:47 EDT 2010: 200469209685 (Hauppauge Win TV-HVR 2250 Kit) - Cancelling snipe.
    Wed May 12 18:42:58 EDT 2010: 180505610609 (Hauppage WinTV 2250 WinTV-HVR-2250 TV Dual Tuner Card) - Cancelling snipe, auction is reported as ended.
    Wed May 12 18:42:58 EDT 2010: Cancelling Snipe for: Hauppage WinTV 2250 WinTV-HVR-2250 TV Dual Tuner Card(180505610609)
    Wed May 12 18:42:58 EDT 2010: 180505610609 (Hauppage WinTV 2250 WinTV-HVR-2250 TV Dual Tuner Card) - Cancelling snipe.

    My snipe time is set to 15 seconds, and my clock is within a few milliseconds of the eBay time.

    I rolled back to 2.1pre5 and although there are more errors parsing auctions (missing seller info, etc.), the snipe work.

  • Morgan Schweers

    Morgan Schweers May 13th, 2010 @ 11:07 PM

    Greetings,
    Well, I have more time to debug this. :) My company let go half the Seattle office today, including myself.

    So...I'll be debugging at this tomorrow, in between fixing up my resume and contacting companies, in the hopes of getting a fix out on Saturday.

    -- Morgan

  • Morgan Schweers

    Morgan Schweers May 17th, 2010 @ 02:51 AM

    Greetings,
    Okay, I'm adding a new logging feature to help with debugging this. It exists under the current version, but I'm making it store it in the log file now.

    I'm about to put up a 2.1pre7 version that contains the following feature:

    Under the 'eBay' menu, choose 'Dump eBay Activity Queue'. It will pour all the currently outstanding sniping information into the log, in roughly this format:

    Mon May 17 02:05:23 PDT 2010: ebay_co_uk: queue empty
    Mon May 17 02:05:23 PDT 2010: ebay_com: Queue: com.jbidwatcher.auction.server.ebay.ebayServer$SnipeListener@22489c42
    Mon May 17 02:05:23 PDT 2010: ebay_com: Object: [310220096318]
    Mon May 17 02:05:23 PDT 2010: ebay_com: When: Fri May 21 01:29:31 PDT 2010
    Mon May 17 02:05:23 PDT 2010: --
    Mon May 17 02:05:23 PDT 2010: ebay_com: Queue: com.jbidwatcher.auction.server.ebay.ebayServer$SnipeListener@22489c42
    Mon May 17 02:05:23 PDT 2010: ebay_com: Object: [310220096318]
    Mon May 17 02:05:23 PDT 2010: ebay_com: When: Fri May 21 01:31:31 PDT 2010
    Mon May 17 02:05:23 PDT 2010: --
    Mon May 17 02:05:23 PDT 2010: ebay_com: Queue: drop
    Mon May 17 02:05:23 PDT 2010: ebay_com: Object: [310220096318]
    Mon May 17 02:05:23 PDT 2010: ebay_com: When: Fri May 21 01:32:31 PDT 2010
    Mon May 17 02:05:23 PDT 2010: --
    

    The way this reads is as follows:

    ebay_co_uk: queue empty -- Simple; the queue for that eBay instance (there are two, ebay_co_uk and ebay_com) is empty. For some of you, ebay_co_uk will usually be empty, and for others, ebay_com will usually be empty.

    ebay_com: Queue: followed by something containing SnipeListener means that this entry is a snipe. Every snipe consists of two entries and a 'drop' action. One snipe at T-2 minutes, and one at T, where T is the time at which the snipe is to fire, NOT the time at which the auction is to end. The 'drop' action is essentially telling JBidwatcher to do a final post-closing update on the item, to make certain it gets the final bid status, for things like multisnipes.

    After the SnipeListener lines and the ebay_com: Queue: drop lines, there'll be a payload line (ebay_com: Object: [310220096318]) which identifies the object that is to be sniped. Lastly there'll be a line that specifies when the action is to be taken, like ebay_com: When: Fri May 21 01:29:31 PDT 2010, which will be at T-2 minutes or T.

    I'd ask you to trigger this every so often, especially before expected snipes, to see what's going to happen. If you do something, like delete items, add or change snipes, etc., and snipes that shouldn't have vanished have vanished, then I really need to know about it.

    Now that you've read this small manuscript, I'll point you to the pre-pre-release: 2.1pre7-0-ga318f67

    Standalone Windows: http://www.jbidwatcher.com/download/JBidwatcher-2.1pre7.exe
    Disk Image (Mac OS X): http://www.jbidwatcher.com/download/JBidwatcher-2.1pre7.dmg
    Linux .jar: http://www.jbidwatcher.com/download/JBidwatcher-2.1pre7.jar

    As per usual, please let me know in as much detail as you can, about any issues you run into! This isn't an official 2.1pre7 release, but it's for folks who are willing to spend some extra time helping with the debugging.

    -- Morgan Schweers, CyberFOX!

  • Therese Telepski

    Therese Telepski May 17th, 2010 @ 03:06 AM

    Dear Morgan,

    alright, Pre7 is downloaded and running.

    Is there any way to schedule or automate the 'Dump eBay Activity Queue'?

    A lot of my snipes occur when I'm sleeping or not at home
    (and I guess I'm not the only one using a sniper because of not having to watch his PC screen all day long). ;-)

    Thus for debugging purposes it would be much easier
    if the dump is automatically triggered let's say
    2.5 minutes before and 0.5 minutes after a snipe.

    Regarding my personal logs: I delete still outstanding, but
    clearly outbid auctions on a regular basis. My grid contains
    100+ auctions anyway, W/o that deletion it would blow up to
    several hundred entries making the whole thing a bit, hmmm
    -- obscured?!

    Sincerely,

    Therese

  • Morgan Schweers

    Morgan Schweers May 17th, 2010 @ 10:42 PM

    Greetings,
    Yeah, I was thinking about automating the dumps, but I'd want to automatically make them happen when user actions occurred. I also wanted to get some eyeballs out there, just to see if humans caught anything while I tried to figure out where to trigger the automated dumps.

    What I really need to do is have a regular thread which goes through and looks for items that have snipes, but aren't in any snipe queues, and alert to that. Need to think about that...

    -- Morgan Schweers, CyberFOX!

  • Andreas Stempfhuber

    Andreas Stempfhuber May 27th, 2010 @ 01:29 PM

    Hi Morgan,

    unfortunate to hear that about your job. I hope that the situation in Seattle is not all too bad so that you quickly find a new job with great new prospects for your life!

    I just found this bug report because I had the same sniping issue yesterday and have now prepared a test environment with a very basic setup to help debugging the issue. I am using the latest JBidWatcher version from the GIT repository (2010-05-17) with very small local modifications (not related to sniping).

    I have changed the following configuration options from the default:
    - added eBay username and password - enabled debug option - disabled time sync.

    I have only added one auction at a time which I have then used for sniping. As I am sitting in Europe (Germany), ebay.com is only used when the auction has Paypal available.

    During the test all snipes failed, please find the logs attached.

    I am currently looking into the source to see if I can find someting but I am sure you have a much better understanding of your code.

    Let me know if you need additional tests or if you have any suggestions to try.

    Cheers!

    Andi

  • Morgan Schweers

    Morgan Schweers May 27th, 2010 @ 02:11 PM

    Greetings,
    @Andreas - Whoa...that was really helpful!

    That's exactly the kind of information I was hoping to see; it's clearly not a site-specific issue as I first thought it might be...

    The queue obviously exists, but for some reason wasn't being called during that time.

    ACK! Wait, why don't any of your logs have 'Time delta with ebay is -134' or some similar message?

    facepalm This is probably a by-blow of a bugfix I did, where for some users JBidwatcher would snipe during start-up before it had synchronized with eBay's clock, so it would snipe up to an hour early. I made it not snipe until it had synchronized with eBay's clock. (The inner class eBayTimeQueueManager in the ebayServer class.)

    I'm trying to see how it would end up not being called... One test for you to do is to watch the initial time of the pre-snipe go by in the log (using the dump activity command), and then explicitly do a time sync. If my theory is right, it should trigger the snipe to start happening immediately. Give that a try!

    Now...why the hell isn't the time being synchronized for some folks...

    -- Morgan Schweers, CyberFOX!

  • Andreas Stempfhuber

    Andreas Stempfhuber May 27th, 2010 @ 03:52 PM

    Hi Morgan,

    because I had disabled time synchronisation in the setup as my intention was to disable all unrelated log lines :-)

    Once enabled snipe seems to work for me:

    Fri May 28 00:35:27 CEST 2010: Fri May 28 00:35:27 CEST 2010: 380236076594 (SONY F-V 120 MIKROFON F-V120 MIKROPHON MICROPHONE) - Preparing snipe.
    Fri May 28 00:35:27 CEST 2010: Getting the sign in cookie.
    Fri May 28 00:35:29 CEST 2010: Done getting the sign in cookie.
    Fri May 28 00:35:29 CEST 2010: Fri May 28 00:35:29 CEST 2010: 380236076594 (SONY F-V 120 MIKROFON F-V120 MIKROPHON MICROPHONE) - Loading bid request...
    Fri May 28 00:35:30 CEST 2010: Checking sign in as bid key load failed!
    Fri May 28 00:35:30 CEST 2010: Fri May 28 00:35:30 CEST 2010: 380236076594 (SONY F-V 120 MIKROFON F-V120 MIKROPHON MICROPHONE) - Snipe was too low, and was not accepted.
    

    (I intended to snipe too low as it is for testing, I am not interested in the product.)

    Since I have time sync. also disabled in my production setup that was then also the reason why my snipe yesterday failed.

    This does however not explain why it is not working for other people where the log shows that time sync. is enabled...

    I'll do a few more tests with modifying the relevant part of the source and let you know the results tomorrow, as it's already late for me today.

    Thanks for your quick help!

    Andi

  • Morgan Schweers

    Morgan Schweers May 27th, 2010 @ 07:47 PM

    • Tag changed from bug, parsing, serious, snipe to bug, committed, parsing, serious, snipe

    Greetings,
    I need to thank you! Your help with this has cleared it all up, and I understand what's going on. The problem is that the alternative server (ebay.co.uk) never actually was doing time synchronization before, under the belief that all that was needed was to sync time with the main eBay server, and the other servers would be based on the same time settings.

    So once I made it a requirement for an instance of ebayServer to get time synchronized before snipes fired, virtually every listing which was only available from eBay Europe (aka visible on ebay.co.uk) was failing sniping, because the sniping process was waiting for a time sync event which was never going to happen. :( This explains why it's limited to the 2.1pre6/7 release, and 2.1pre5 worked; because 2.1pre5 still has the snipe-before-time-sync bug.

    So. I've committed a TON of fixes today, including making it so the snipe check operation happens even if you've turned off time synchronization (as you do), making the backup server (ebay.co.uk) do its own time synchronization, and triggering it all at the start. Also when time sync events show up in the log files, they'll identify which eBay site they're coming from.

    I also committed a few other minor features that I've had in the backlog for a bit, coded, but not pushed up, and am probably going to push one more 'big' feature in if I have time before you wake up and check out the code. :)

    If you can grab the latest code from GitHub when you get a chance tomorrow, and let me know if you're seeing relatively consistent sniping behavior with it, I can publish it as the next version, and get it into more folks hands.

    Thanks a MILLION, this has been really helpful!

    -- Morgan Schweers, CyberFOX!

  • Andreas Stempfhuber

    Andreas Stempfhuber May 28th, 2010 @ 03:19 PM

    Hi Morgan,

    wow, that was really fast and it works! I have tested about 20 auctions with and without Paypal and with time sync. enabled and disabled and the 2 minute preparing snipe started for all of them, 100% success.

    Once I find something that I need I place a real snipe, but I have no doubt that the issue is solved now.

    Thanks!

    Andi

  • Morgan Schweers

    Morgan Schweers May 31st, 2010 @ 02:23 AM

    • State changed from “open” to “resolved”

    Greetings,
    I'm just letting folks know, I've pushed up a 2.1pre7-28-gcd0e285 version to the same download spot described here and will be releasing it as a 2.1pre7 officially tomorrow evening, unless some showstoppers come up.

    So...please try it out and let me know if there are any showstoppers! :)

    It fixes...snipes failing, bad seller names, bad bidder names, auctions seen as fixed price, unable to retrieve prices, selection color customization, private listing recognition, some sticky search and update infinite loops, and it reduces the amount of derby.log data dumped out when debugging is set to true. There's also a bunch of improvements internally, and some work towards a new feature that a bunch of users have been asking about.

    Yeah...there's a lot of code in there.

    It's about as tested as I can manage personally, so I'd love some more eyes on it! Feedback is all I ask...!

    Best of luck with your auctions!

    -- Morgan Schweers, CyberFOX!

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile ยป

Shared Ticket Bins

People watching this ticket

Attachments

Referenced by

Pages