Server Crashes/Restarts Due To Scheduled Reward #437


  • Defect
  • Started
Open
Assigned to _ForgeUser8455416
  • _ForgeUser10435848 created this issue Feb 19, 2014

    NOTE: If you supply copies of your .yml or console log files, please use pastebin, dropbox, or other service and provide link,  instead of copy/paste of the file into this report. Thanks!

    What Version of OnTime and Bukkit are you using?
    OnTime: 3.12.1
    Bukkit: Tekkit Classic

    What storage option are you using? (YML or MYSQL) ?

    YML, but issue exists for both.

    What permissions plugin are you using? (Groupmanager, PEX,bPermissions, etc.)

    PEX

    Please provide a link to a copy of your plugins/OnTime/config.yml:

    http://pastebin.com/e3QsjGHp

    What steps will reproduce the problem?

    1. Schedule rewards (type, frequency etc doesn't matter).
    2. Wait up to 2 weeks.

    What is the expected output? What do you see instead?

    Expected: Things carry on as normal and rewards are scheduled and issues as configured.

    What Happens: Server restarts every time a specific player logs in until '/ontime rewards delete <name>' is run for the player, in every case they have one or more rewards with a scheduled time showing as '0', time stamps are meaningless for all players after the first occurrence of this issue showing dates such as '23/19/2078' for last login etc, only longer term fix currently seems to be a complete database reset but problem comes back after a week or two making it a fairly useless fix.

    Do you have an console log of what happened?

    2014-02-19 10:32:58 [WARNING] Task of 'OnTime' generated an exception
    java.lang.IllegalArgumentException: Delay cannot be less than 0
        at org.bukkit.craftbukkit.scheduler.CraftScheduler.scheduleSyncRepeatingTask(CraftScheduler.java:195)
        at org.bukkit.craftbukkit.scheduler.CraftScheduler.scheduleSyncDelayedTask(CraftScheduler.java:180)
        at me.edge209.OnTime.Rewards.Rewards.scheduleIndiRewards(Rewards.java:3774)
        at me.edge209.OnTime.PlayerEventListener$2.run(PlayerEventListener.java:299)
        at org.bukkit.craftbukkit.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:126)
        at net.minecraft.server.MinecraftServer.w(MinecraftServer.java:543)
        at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:467)
        at net.minecraft.server.ThreadServerApplication.run(SourceFile:492)

    Are you having a "rewards" problem?  Please provide a link to a copy of your /plugins/OnTime/rewards.yml :

    Can provide if needed but issue occurs eventually with any scheduled reward so almost certainly irrelevant in this case.

    Did you turn on OnTime logging (/ontime logfile enable 1)?  If so, provide a link to that file too.

    Just done this now, will post any relevant information as soon as it next happens.

    Please provide any additional information below.

  • _ForgeUser10435848 added the tags New Defect Feb 19, 2014
  • _ForgeUser8455416 posted a comment Feb 19, 2014

    There is another file that may be contributing to the problem. Please share a link to a copy of the file indirewards.yml now, and another after a crash but before you fix by deleting the player's rewards.

    Is it always the same one player, or different players on each occurrence ?

  • _ForgeUser8455416 removed a tag New Feb 19, 2014
  • _ForgeUser8455416 added a tag Waiting Feb 19, 2014
  • _ForgeUser10435848 posted a comment Mar 2, 2014

    Hey, sorry but I'm still waiting, always seems to happen when I'm not around at the moment and so gets fixed by someone else before I can take a copy of the file, I'll be around more this week so hopefully will get what you need.

    So far I don't think it has happened to the same player more than once, so it seems to be a different one each time.

    Another weird thing I've noticed is rewards listed in the indie rewards file that shouldn't have been scheduled, for example promotions for players that have already received that promotion several days ago, not sure if it's connected in any way.

  • _ForgeUser10435848 removed a tag Waiting Mar 2, 2014
  • _ForgeUser10435848 added a tag Replied Mar 2, 2014
  • _ForgeUser8455416 posted a comment Mar 2, 2014

    @JBDiggy: Go

    Ok. If there is an OnTime/OnTimeLog.txt and/or an OnTime/OnTimeERROR.txt file in your plugins directory, please share those as they may provide some clues.

  • _ForgeUser8455416 removed a tag Replied Mar 2, 2014
  • _ForgeUser8455416 added a tag Waiting Mar 2, 2014
  • _ForgeUser8455416 posted a comment Apr 29, 2014

    Sent IM reminder to author. If no response is received by May 9th, this ticket will be closed.

    http://dev.bukkit.org/home/private-messages/201028-ontime-ticket-437/


    Edited Apr 29, 2014
  • _ForgeUser8455416 removed a tag Waiting Apr 29, 2014
  • _ForgeUser8455416 added a tag Replied Apr 29, 2014
  • _ForgeUser8455416 removed a tag Replied Apr 29, 2014
  • _ForgeUser8455416 added a tag Waiting Apr 29, 2014
  • _ForgeUser10435848 posted a comment May 3, 2014

    This is still an issue but we seem to be avoiding the crashes now, presumably because of the messed up timestamps. Time based rewards (hourly etc) issue as normal but dayson rewards are very mixed, sometimes they are issued but other times they aren't and just constantly get rescheduled and never received or get scheduled for players that shouldn't receive them and just sit in the list of rewards due soon saying they'll be issued in a number of days which changes every time they connect.

    I'm reluctant to reset the data again because players would lose their dayson etc which would annoy quite a few people and I'm worried the crashes will start again so for now we're just promoting people that get missed manually and I've removed any use of timestamps from the command output that players see so it doesn't confuse people (for example, apparently today is 34/23/2083!).

    The only types of message appear in OnTime_ERROR.txt seem to be related to the messed up timestamps, although the timestamps appear fine in the logs, just not in the command outputs, here's some examples;

    [04/17/2014 02:16:18] {logout} JBDiggy was not marked as 'online' by ontime. Logout failed. No data update.

    [04/18/2014 19:21:51] {logout} JBDiggy was not marked as 'online' by ontime. Logout failed. No data update.

    [04/20/2014 23:16:44] {loginPlayer} JBDiggy may have logged off before delayed login task completed. No rewards set.

    [04/21/2014 12:03:10] {setLogin} OnTime is attempting to increment DaysOn (21) greater than DaysAgo (4) for JBDiggy

    I've been over the logs again and again and I can't find anything else. If I set the reward to be issued manually, as long as it's issued before the player disconnects it works fine, otherwise it just reschedules at next login and is never issued.

    I turned off OnTimeLog.txt as it was growing rapidly but didn't seem to show any problems, the reward schedules fine, well except it schedules for days into the future, e.g. ;

    [01/12/2014 12:40:41] Indi reward: S7PROMOTION1Member set for JBDiggy time: 13 Day 20 Hr 10 Min

    [01/12/2014 12:40:41] Set new Reward at positon 0 of PERSONAL for JBDiggy

    It seems to me that it's all down to the timestamp issue in one way or another, is there any way to fix the timestamps without resetting everyones records?

    In case it's relevant this is how the reward looks in rewards.yml;

    - DO,A,T,P,null,default,all,7,0,0,0,0,1,7,+R,1,Member,S7PROMOTION1Member

    And a typical entry from playerdata.yml;

    player605: 'JBDiggy,1478460992,1398017643055,0,0,37929480,0,0,0,0'

    and the date data from the end of that file;

    TodayDate: 1398034800000 WeekStartDate: 1398034800000 MonthStartDate: 1396306800000

    I've also had to turn off data purging as it was purging players based on strange dates, for some reason it decided about 20 players hadn't logged in since some random date in 1970 and purged them all even though some had been online the day before!

    Obviously I changed the names above to mine, but as you can see the logs don't seem to offer any clues. :(

  • _ForgeUser10435848 removed a tag Waiting May 3, 2014
  • _ForgeUser10435848 added a tag Replied May 3, 2014
  • _ForgeUser10435848 posted a comment May 16, 2014

    Just a quick note to say that I have now upgraded to v3.13.1 and the issue is unchanged.

  • _ForgeUser10435848 posted a comment May 17, 2014

    I had a bit of free time so I was looking at what the reward strings actually mean and noticed that for some reason everytime I created a DaysOn reward the 'recurrence count' was set to match the number of 'reward days', might explain why it was getting scheduled for players that had already been promoted, I've also manually set it back to 'Exclusive' as at some point it reverted to 'All'.

    What is the +R? I can't find any mention of it on the rewards.yml page, shouldn't that be a 'G' for group in this case?

    Here's the changes I made manually;

    Old string:

    - DO,A,T,P,null,default,all,7,0,0,0,0,1,7,+R,1,Member,S7PROMOTION1Member

    New string:

    - DO,E,T,P,null,default,all,7,0,0,0,0,1,0,+R,1,Member,S7PROMOTION1Member

  • _ForgeUser8455416 posted a comment May 17, 2014

    @JBDiggy: Go

    I appreciate the effort to help me figure this one out. (And it looks like my rewards.yml documentation needs some updating.) Although your questions did not lead straight to an answer, it made me question how I had coded the 'daysOn' reward, and that did lead me to the source of the problem.

    • I used the 'recurrence count' to hold the target number of 'daysOn' for those types of rewards, and have special handling for this case. So this was not contributing to the problem. In fact the "7 days" you have in the 'time' definition for the reward is completely ignored. So, when you hand edited the reward you have it now set for zero daysOn.
    • The "+R" is for "up rank" (a.k.a. promotion). When I added the "-R" or "down rank" (a.k.a demotion), the old "G" designation I used for "group promotion" was retired. (Doc update needed)

    So, I have found the source of the problem and understand why it seems so random. (The scheduled time of the days on reward was based on the time since their last login, when it should always be right away.)

    I am looking to get out a v3.13.2 this weekend, so you should have a fix soon.

  • _ForgeUser8455416 removed a tag Replied May 17, 2014
  • _ForgeUser8455416 added a tag Started May 17, 2014
  • _ForgeUser10435848 posted a comment Aug 13, 2014

    Great that you've managed to pin it down, any news on when this will be implemented? It's still doing the same thing in 3.13.3 so I figure it must have been more difficult to fix than you thought.

  • _ForgeUser8455416 posted a comment Aug 13, 2014

    @JBDiggy: Go

    I'm going to have to go back and check my notes, as I thought I had this one fixed, but then again I didn't close out the ticket. I'll get back to you shortly ....


To post a comment, please login or register a new account.