DualSaveStrategy crash

[LordFenris]

We found a problematic crash bug with dual save strategyWorld. Server crash on average 2-3 times a day, during regular save game and dont create all save folders - only custom, guild, items and mobiles without attachment, accounts and staff runebook. My staff received a debug information and here is it:

Core: Using dual save strategyWorld: Saving...Error:
20:11:35 System.ArgumentOutOfRangeException: Argument is out of range.
at System.DateTime.op_Addition (DateTime d, TimeSpan t) [0x00000] in <filename unknown>:0
at Server.Timer.get_Next () [0x00000] in <filename unknown>:0
at Server.Items.DisguisePersistance.Serialize (Server.GenericWriter writer) [0x00000] in <filename unknown>:0
at Server.StandardSaveStrategy.SaveItems (Server.SaveMetrics metrics) [0x00000] in <filename unknown>:0
at Server.DualSaveStrategy+<Save>c__AnonStorey18.<>m__42 () [0x00000] in <filename unknown>:0
at System.Threading.Thread.StartInternal () [0x00000] in <filename unknown>:0 Crash: Generating report...done



And here is a crash log
RunUO Version 0.5, Build 5327.30231
Operating System: Unix 3.10.23.6
.NET Framework: 4.0.30319.17020
Time: 2014-08-02 20:11:35
Mobiles: 40459
Items: 191898
Exception:
System.ArgumentOutOfRangeException: Argument is out of range.
at System.DateTime.op_Addition (DateTime d, TimeSpan t) [0x00000] in <filename unknown>:0
at Server.Timer.get_Next () [0x00000] in <filename unknown>:0
at Server.Items.DisguisePersistance.Serialize (Server.GenericWriter writer) [0x00000] in <filename unknown>:0
at Server.StandardSaveStrategy.SaveItems (Server.SaveMetrics metrics) [0x00000] in <filename unknown>:0
at Server.DualSaveStrategy+<Save>c__AnonStorey18.<>m__42 () [0x00000] in <filename unknown>:0
at System.Threading.Thread.StartInternal () [0x00000] in <filename unknown>:0

Are you got any suggestions?

 

[Enroq]

Generally when something like this happens, you want to look for the place that modifications would have most likely occurred. As I doubt you've made any changes to the system namespace, the timers, the save strategy, or threads, you may want to check out:

at Server.Items.DisguisePersistance.Serialize (Server.GenericWriter writer) [0x00000] in <filename unknown>:0

 

[LordFenris]

Mhmmm i'm very confused. I never don't change disguise kit files (disguise persistance too) . We implement only one change which allow PK to be a member of thief guilds and buy this item for hide real name.
Are you got any idea which files may be responsible for this error? We noticed four demand that may be clue to finding the cause.
1 Crash occurs only during random save (once for example 50-60).
2 backup files are correct so we can upload them in place of an incomplete save.
3 server after uploading the files from the backup works correctly for the next crash, which again takes place at random.
4 Crash also appeared when nobody was logged but the two characters had disguise kit in a backpack.

I gave instructions to remove all the existing disguise kit to test to see if the accounts without these items in the game world crash appears.

 

[Ravenwolfe]

Mhmmm i'm very confused. I never don't change disguise kit files (disguise persistance too) . We implement only one change which allow PK to be a member of thief guilds and buy this item for hide real name.

Something is happening in relation a timer associated with the Disguise Persistence. Can you post your Disguise kit and the place you made the above change?

 

[LordFenris]

Hmmmmm, yesterday our staff removed all disguise from our test world and our shard work without crash near full day.
Here is my disguise files and files compared with this item which I change to allow their use by the murderers and criminals. Also, We allow to join a PK/Criminals to a thief guild.

disguisepersistance.cs - no changes
reportmurderer.cs - lines 133-136
baseguildmaster.cs - lines 47 and 54
stealing.cs - lines 76-79

Disguisekit.cs:
disable

//else if (Stealing.SuspendOnMurder && pm.Kills > 0)
//{
// // You are currently suspended from the thieves guild. They would frown upon your actions.
// from.SendLocalizedMessage(501703);
//}

reportmurderer.cs
disable

//else if (SkillHandlers.Stealing.SuspendOnMurder && pk.Kills == 1 && pk.NpcGuild == NpcGuild.ThievesGuild)
//{
// pk.SendLocalizedMessage(501562); // You have been suspended by the Thieves Guild.
//}

Edit:
It's definitely the error associated with the disguise files. I bought one kit at Thief Guildmaster, next used it on our test toon (murderer and member of thief guild) and less than 30 minutes later, there was a crash (during the second save, toon was used disguise kit in the bag but did nothing ). Earlier our shard work near full day without errors. Now we will test disguise on innocent toon in order to determine whether an error occurs if the disguise will hold and use by blue toon.

 

[Ravenwolfe]

Your problem seems to be here in disguisepersistance.cs:

foreach (DictionaryEntry entry in DisguiseTimers.Timers)
 {
 Mobile m = (Mobile)entry.Key;
 
 writer.Write(m);
 writer.Write(((Timer)entry.Value).Next - DateTime.UtcNow);
 writer.Write(m.NameMod);
 }

Specifically the line where it is writing the DateTime value. Somehow the math is getting out of range. I can't replicate this issue in a windows environment so far and I'm not good with linux. Is it possible the date/times are handled differently in linux?

 

[LordFenris]

It seems to me that in case the problem stemmed from the operating system crash would occur not only from time to time but would have a repetitive nature. Note that if the crash occurs, you can load a file from the backup and fire on them without a problem server, and another savy are overwritten properly. But I could be wrong: D
Paradoxically, the problem may be some blach matter. Certainly not related to what the player is doing because there is a crash when she does nothing and is not even logged. Currently, we verify whether the crash occurs when the disguise is in possession of and use by the player blue.
Also will check whether the same way, both the player and the red blue always disguise effect persists two hours of the game (does not count as a logoff time) and whether or not there is a difference in the countdown time to revert change the name, appearance, etc..

Edit: disguise effect persists two hours of the game on both red and blue players (our test confirm that)
Still tested disguise on blue toons.

 

[Ravenwolfe]

Yeah, I said that badly, I didn't mean the operating system as much as I meant using Mono. The crash is occuring at random times because it is only happening when the math being applied goes outside of the range of a proper TimeSpan. If this theory is correct, it has nothing to do with blues or reds but with the way the math is being done.

System.ArgumentOutOfRangeException: Argument is out of range.
System.DateTime.op_Addition (DateTime d, TimeSpan t)

One of the two arguments is out of range, either the DateTime or the TimeSpan.

Perhaps you could add a console write to the Serialize method of the DisguisePersistance.cs that gives us the result of (((Timer)entry.Value).Next - DateTime.UtcNow) before it attempts to write that value. Then we can see if that is what is giving the out of range error.

The other possibility is that you need a null check for the Timer, but I would think if that were the issue then it would be affecting everyone.

 

[LordFenris]

Thanks for your suggestion
I change our script for a console raport

foreach (DictionaryEntry entry in DisguiseTimers.Timers)
{
Mobile m = (Mobile)entry.Key;

writer.Write(m);
Console.WriteLine("(((Timer)entry.Value).Next - DateTime.UtcNow) is {0}",(((Timer)entry.Value).Next - DateTime.UtcNow));
writer.Write(((Timer)entry.Value).Next - DateTime.UtcNow);
writer.Write(m.NameMod);
}
Console.WriteLine("saved (((Timer)entry.Value).Next - DateTime.UtcNow)");
}

and test saves

Here is a raport when when no one uses disguise and server create save properly ( two players have them in their bags but dont use it)

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.08:38:46.8490030saved (((Timer)entry.Value).Next - DateTime.UtcNow)
08:38:47 Closing Save Files.
08:38:47 Save finished in 0,16 seconds.

When one player use disguise for name change (second tester got kit but unused)

Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.08:40:42.2530030(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:59:49.6639990saved (((Timer)entry.Value).Next - DateTime.UtcNow)
08:40:42 Closing Save Files.
08:40:42 Save finished in 0,15 seconds

Two players used kit for name change (one online, second offline)

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.08:44:39.1640030(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:59:49.1250000(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:55:52.7529990saved (((Timer)entry.Value).Next - DateTime.UtcNow)
08:44:39 Closing Save Files.
08:44:39 Save finished in 0,15 seconds

Next save log when two players use it (one logged, second unlogged)

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.08:52:10.5850020(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:52:17.7040000(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:48:21.3319990saved (((Timer)entry.Value).Next - DateTime.UtcNow)
08:52:10 Closing Save Files.
08:52:10 Save finished in 0,17 seconds.

After 2 hours. Still only one toon is logged, second tester offline.

Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.10:42:12.9110030(((Timer)entry.Value).Next - DateTime.UtcNow) is 00:02:15.3779990(((Timer)entry.Value).Next - DateTime.UtcNow) is -00:01:40.9940010saved (((Timer)entry.Value).Next - DateTime.UtcNow)
10:42:13 Closing Save Files.
10:42:13 Save finished in 0,17 seconds.

About three minuts later. First toon still online, second offline.

Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.10:44:31.1380020(((Timer)entry.Value).Next - DateTime.UtcNow) is -00:00:02.8490000(((Timer)entry.Value).Next - DateTime.UtcNow) is -00:03:59.2210000saved (((Timer)entry.Value).Next - DateTime.UtcNow)
10:44:31 Closing Save Files.
10:44:31 Save finished in 0,15 seconds.

As I see -00.00.02 time is for first (logged) toon, but when I initiate a save , his timer gone. I still see a timer for second - offline toon.

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.10:49:12.4760020(((Timer)entry.Value).Next - DateTime.UtcNow) is -00:08:40.5590010saved (((Timer)entry.Value).Next - DateTime.UtcNow)
10:49:12 Closing Save Files.
10:49:12 Save finished in 0,16 seconds.

Next we logout first toon and logged second with timer -00.08.40. Enter a save and

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.10:52:34.6100020(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:55:36.3860000saved (((Timer)entry.Value).Next - DateTime.UtcNow)
10:52:34 Closing Save Files.
10:52:34 Save finished in 0,15 seconds.

As I see server properly restored timer for the toon that after using disguise was logged off and next logged onto after more than 2 hours, but logs indicated that two hours countdown continues even if the character is offline.

Still no crash

Also will check report at crash and paste it here.

 

[LordFenris]

I logged for our first test toon again, used disguise, relog on my staff toon, use save and

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is -735452.12:02:09.3940020Error:
12:02:09 System.ArgumentOutOfRangeException: Argument is out of range.
at System.DateTime.op_Addition (DateTime d, TimeSpan t) [0x00000] in <filename unknown>:0
at Server.Timer.get_Next () [0x00000] in <filename unknown>:0
at Server.Items.DisguisePersistance.Serialize (Server.GenericWriter writer) [0x00000] in <filename unknown>:0
at Server.StandardSaveStrategy.SaveItems (Server.SaveMetrics metrics) [0x00000] in <filename unknown>:0
at Server.DualSaveStrategy+<Save>c__AnonStorey18.<>m__42 () [0x00000] in <filename unknown>:0
at System.Threading.Thread.StartInternal () [0x00000] in <filename unknown>:0 Crash: Generating report...done

Unfortunately an error has not occurred again when I tried to do the same steps (after restarting the server)

I still thinks abouth this record -735452.12:02:09.3940020
Same -735452 with current time are in each log.

Next, I check all our test toon in all accounts and I found one with crazy disguise record -735452 and current time on properities. I looked that this toon are member of NPC Thieses Guild and join ...... 0001.01.01 00:00:00 ????? . Lool. Mayby its a good shot So Next I check all other test toon, selected all which are member of theves guild and check disguise and guild join data. Each other got a proper record .
So I del this toon because we cannot change this elements of it and now our logs looks like this:

Core: Using dual save strategyWorld: Saving...(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:18:40.7499980(((Timer)entry.Value).Next - DateTime.UtcNow) is 01:25:03.9989990saved (((Timer)entry.Value).Next - DateTime.UtcNow)
14:22:46 Closing Save Files.
14:22:46 Save finished in 0,15 seconds.

Perhaps this will solve the problem. 'll Let you know

Edit: Solved.

 

[Ravenwolfe]

Excellent, I figured it was getting a weird time somehow!

 

[LordFenris]

I just wonder how it happened for this error. Presumably the test character has been artificially appended to the Thieves Guild (by changing the NPC Guild in props) and perhaps even received generated by GM disguise. We'll play with it yet

 

[Ravenwolfe]

I was wondering the same thing, is it a one time anomoly that the value got out of range or did something cause it that could be repeated.