Crashes / Disconnects

[LethalEncounter]

Mkay... interesting. For days, I ran Debug code with remote debugger attached, not one crash through all the work Scatman has done and players testing items, zoning all around. I put the release binary online, and within 2 hours, it crashes. No idea what was happening, but here's the console for the last connection (this same user seemed to be dropped a few times doing the same thing)

Code: Select all

AddAuth: 3842 Key: 1236653247
3383687 New client from ip: xxx.xxx.xxx.xxx port: 54016
ZoneAuth: Access Key, 1236653247, Character Name, Useuchu, Account ID, xxxx, TimeStamp, 1236653247
OP_ChatFiltersMsg Received 0x013d
   0: 0D 00 FF FF FF FF FF 01 - 00 00 00 80 FF FF 0B 01  | ................
OP_ChatFiltersMsg Received 0x013d
   0: 0D 00 FF FF FF FF FF FF - FF FF FF FF FF FF 0B 01  | ................
OP_Unknown Received 0x0026
   0: 01 00 00 00 96 43                                  | .....C
OP_Unknown Received 0x00b2
   0: 00 00                                              | ..
   0: CC 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: 23 00 01 00 31                                     | #...1
   0: CC 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
OP_ChatFiltersMsg Received 0x013d
   0: 0D 00 FF FF FF FF FF FF - FF FF FF FF FF FF 0B 01  | ................
   0: 01 00 07 00 64 65 74 61 - 69 6C 73                 | ....details
Left Grid 4294967295 and Entered Grid 771354606
   0: CC 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 01 00 07 00 64 65 74 61 - 69 6C 73                 | ....details
OP_BeginTrackingMsg Received 0x0175
   0: 3E                                                 | >
Zone: Removing client from ip:xxx.xxx.xxx.xxx port:54016
Removing connection

This is "unknwon"s IP, and there was some talk about a packet scanner he made, which I am still waiting for an explanation why it would be used on my server.

Hmm, I'll enable the new Mutex code on release and see if that solves the problem.

[John Adams]

I tried doing "/spawn set faction 1" today and instantly got booted. I don't think World crashed but John will have to verify that.

I do not see a world restart today. Scat, that logview script I linked you should show you what the world is doing live. I'll move that into the editor's Admin section soon, promise.

[Scatman]

Yah, I forgot the link Meant to ask you for it again.

[John Adams]

Seeing around 2-3 crashes per day still. When I run in Debug, the server runs for a week without a single failure. Soon as I put it in Release, it will crash regularly again. Can't really debug things that way. Hopefully some things in this console output can give you a clue what may be happening... but to me, it looks like standard play - nothing special going on. Movement, spell casting, zones shutting down, etc.

Code: Select all

Shutting Down Zone 'Darklight'
   0: 22 00 01 00 32                                     | "...2
   0: 22 00 01 00 32                                     | "...2
   0: 22 00 01 00 32                                     | "...2
   0: 22 00 05 00 31 30 30 30 - 32                       | "...10002
   0: 22 00 06 00 31 30 30 30 - 30 32                    | "...100002
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
Left Grid 4294967295 and Entered Grid 1698999948
Zone: Removing client from ip:71.120.238.196 port:2087
Removing connection
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
OP_Unknown Received 0x01d2
   0: 00 00 00 FF FF FF FF 88                            | ........
   0: 55 00 00 00                                        | U...
OP_DialogCloseMsg Received 0x0067
   0: 24 65 11 00                                        | $e..
[Status] Using database 'eq2live' at mysql
[Status] CURRENT_WORLD_VERSION:EQ2EMu 0.6.5 Developer Alpha

I am turning off Beta Heal and Beta Damage for now, in case those are causing problems.

[LethalEncounter]

I'll enable the Mutex code for the release build as well. That should explain the problem if it is a lock issue.

[John Adams]

I just compiled another debug, but I'll wait to try this code after you check it in. Maybe something will surface.

[John Adams]

Er, LE?

I am getting possible deadlocks just running the new EXE (self compiled off SVN). I will try a clean and make again just in case. Got 3 of them before the code would continue loading, and it is verrrry slow...

Code: Select all

[Status] CURRENT_WORLD_VERSION:EQ2EMu 0.6.5 Developer Alpha
[Status] ./LoginServer.ini read.
[Status] Connecting to Update Server..
[Status]        Connected to Update Server: updates.eq2emulator.net:9103
[Status]        Checking for updates.
[Status]        Server is already up-to-date.
[Status] Loading opcodes..
[Status] Loading structs..
[Status] Loading command list..
[Status] Loaded 506 entity command lists.
[Status] Loaded 3907 NPC(s).
[Status] Loaded 627 Object(s).
[Status] Loaded 84 GroundSpawn(s).
[Status] Loaded 467 Widget(s).
Possible deadlock attempt by 'Spawn::MPacketData'!
Possible deadlock attempt by 'Spawn::MPacketData'!
Possible deadlock attempt by 'Spawn::MPacketData'!
[Status] Loaded 567 Sign(s).
[Status] Loading ground spawn items..
[Status] Loading loot data..
[Status]        Loaded 4 loot tables.
[Status]        Loaded 8 loot drops.
[Status]        Loaded 4 spawn loot lists.
[Status] Loading Transporter Information..
[Status]        Loaded 24 Teleporter(s)
[Status] Loaded global variables list..
[Status] Loaded visual states list..
[Status] Loading World Time..
[Status] Loading items.. (this might take a few minutes)
[Status]        Loaded 282 Bag(s)
[Status]        Loaded 2072 Food(s)
[Status]        Loaded 14064 Weapon(s)
[Status]        Loaded 32761 Armor/Shield Piece(s)
[Status]        Loaded 0 Skill Item(s)
[Status]        Loaded 9906 Regular Items
[Status] Loading spells..
Possible deadlock attempt by 'Spell::MSpellInfo'!

[John Adams]

k after a Clean and Rebuild Project, I got passed the first set of deadlocks, but it hit the Spells load and is deadlocking again. Or, just saying that there is a possible deadlock anyway. I'll let it load all the way to see how it works once running completely.

Code: Select all

[Status] CURRENT_WORLD_VERSION:EQ2EMu 0.6.5 Developer Alpha
[Status] ./LoginServer.ini read.
[Status] Connecting to Update Server..
[Status]        Connected to Update Server: updates.eq2emulator.net:9103
[Status]        Checking for updates.
[Status]        Server is already up-to-date.
[Status] Loading opcodes..
[Status] Loading structs..
[Status] Loading command list..
[Status] Loaded 506 entity command lists.
[Status] Loaded 3907 NPC(s).
[Status] Loaded 627 Object(s).
[Status] Loaded 84 GroundSpawn(s).
[Status] Loaded 467 Widget(s).
[Status] Loaded 567 Sign(s).
[Status] Loading ground spawn items..
[Status] Loading loot data..
[Status]        Loaded 4 loot tables.
[Status]        Loaded 8 loot drops.
[Status]        Loaded 4 spawn loot lists.
[Status] Loading Transporter Information..
[Status]        Loaded 24 Teleporter(s)
[Status] Loaded global variables list..
[Status] Loaded visual states list..
[Status] Loading World Time..
[Status] Loading items.. (this might take a few minutes)
[Status]        Loaded 282 Bag(s)
[Status]        Loaded 2072 Food(s)
[Status]        Loaded 14064 Weapon(s)
[Status]        Loaded 32761 Armor/Shield Piece(s)
[Status]        Loaded 0 Skill Item(s)
[Status]        Loaded 9906 Regular Items
[Status] Loading spells..
Possible deadlock attempt by 'Spell::MSpellInfo'!
Possible deadlock attempt by 'Spell::MSpellInfo'!
Possible deadlock attempt by 'Spell::MSpellInfo'!
Possible deadlock attempt by 'Spell::MSpellInfo'!
Possible deadlock attempt by 'Spell::MSpellInfo'!
Possible deadlock attempt by 'Spell::MSpellInfo'!

If you don't respond tonight, I'll just revert to an older version for the night.

[LethalEncounter]

hmm wtf, there must be something else going on there because there is not way that MSpellInfo could be deadlocked. I'll try to figure it out tomorrow :/

[John Adams]

Heh, ok. Yeah I thought that was pretty damn strange... considering otherwise, the world loads and starts with no problems.

Btw, I just watched the world die. unfortunately, no debug or mutex code running, so another dud... maybe we'll get fortunate and alfa or xanibunib will come tell us what they experienced.

But here's what I saw... player zoned, moved, after excessive spell casting and movement... saw the zone crash:

Code: Select all

Unhandled command: clearallqueuedabilities
   0: 22 00 05 00 31 30 30 30 - 30                       | "...10000
   0: 25 00 01 00 31                                     | %...1
   0: 22 00 05 00 33 30 30 30 - 32                       | "...30002
   0: 22 00 05 00 33 30 30 30 - 36                       | "...30006
   0: 22 00 05 00 31 30 30 30 - 32                       | "...10002
   0: 22 00 05 00 33 30 30 30 - 32                       | "...30002
   0: 22 00 05 00 31 30 30 30 - 32                       | "...10002
   0: 22 00 05 00 33 30 30 30 - 36                       | "...30006
   0: 22 00 05 00 33 30 30 30 - 31                       | "...30001
   0: 22 00 05 00 33 30 30 30 - 36                       | "...30006
   0: 22 00 05 00 33 30 30 30 - 36                       | "...30006
   0: 29 00 03 00 61 6C 6C                               | )...all
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: 38 00 06 00 6F 63 68 61 - 69 6D                    | 8...ochaim
AddAuth: 1667 Key: 1237774479
OP_ReadyToZone: Player Xanibunib zoning to SourceEvil
2188461 New client from ip: 67.190.134.169 port: 61574
ZoneAuth: Access Key, 1237774479, Character Name, Xanibunib, Account ID, 1667, TimeStamp, 1237774479
OP_Unknown Received 0x0026
   0: 01 00 66 66 31 44                                  | ..ff1D
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
Zone: Removing client from ip:67.190.134.169 port:61574
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
Left Grid 4294967295 and Entered Grid 3240910078
Error Processing SpawnLoop, shutting down zone...
Removing connection
Removing connection
[Status] Using database 'eq2live' at mysql
[Status] CURRENT_WORLD_VERSION:EQ2EMu 0.6.5 Developer Alpha

Boot both players, and a moment later, world restarted.

[LethalEncounter]

bah nm, I found it. Was an issue with me not removing a #ifdef debug tag and when you were running it in release mode it was causing that issue. I'll upload the changes in a couple of minutes, but if you run in debug you should be fine also.

[John Adams]

Woot. I knew you'd be too curious to let it go. hee hee. lucky me.

Thanks LE. I'll see if I can catch some of these oddball crashes this week.

[John Adams]

Got that weird thing again where the world is "DOWN", but there is a zone loaded showing 12 clients connected.

12-clients.jpg

Xan might be able to shed some light on how to reproduce this, but I honestly cannot say it was his script/reload sequence, since we've seen this before. Real odd part, someone is still in the server, playing away. I see movement and spell casting going on, yet I cannot connect to it myself.

(the repeated Logging to is how many times the world has crashed today. :p)

[John Adams]

Not sure why Tess showed offline. Maybe it was the loginserver offline a moment? Anyway. I am logged in now, 3 players online (including myself). 2 zones active. 14 clients connected. I'm thinking if I disconnnect now and reconnect immediately, I will see 15 clients connected in teh console.

We've seen this before. No idea how to reproduce it.

[John Adams]

Not a crash, but something Scat and I seem to be able to reproduce - and it may just be a side effect of casting spells too fast before the other "tick" finishes.

Code: Select all

Left Grid 1246288135 and Entered Grid 771354606
   0: 01 00 0F 00 73 65 74 20 - 73 68 6F 77 5F 6E 61 6D  | ....set show_nam
  16: 65 20 30                                           | e 0
   0: 01 00 10 00 73 65 74 20 - 74 61 72 67 65 74 61 62  | ....set targetab
  16: 6C 65 20 30                                        | le 0
Combined Packet!
Combined Packet!
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: 0C 00 4C 00 74 68 61 74 - 73 20 77 65 69 72 64 2C  | ..L.thats weird,
  16: 20 69 20 6B 6E 6F 77 20 - 79 6F 75 20 63 61 6E 20  |  i know you can
  32: 68 69 64 65 20 79 6F 75 - 72 20 6F 77 6E 20 68 6F  | hide your own ho
  48: 6F 64 2C 20 64 75 6E 6E - 6F 20 77 68 61 74 73 20  | od, dunno whats
  64: 75 70 20 77 69 74 68 20 - 74 68 65 20 4E 50 43 73  | up with the NPCs
   0: 03 00 02 00 38 30                                  | ....80
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 22 00 04 00 33 30 30 30                            | "...3000
Possible deadlock attempt by 'SpellProcess::MActiveSpells'!
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: 29 00 03 00 61 6C 6C                               | )...all
Combined Packet!
Possible deadlock attempt by 'SpellProcess::MActiveSpells'!
   0: 0C 00 12 00 77 65 20 6A - 75 73 74 20 64 65 61 64  | ....we just dead
  16: 6C 6F 63 6B 65 64                                  | locked
   0: 29 00 03 00 61 6C 6C                               | )...all
   0: 0C 00 61 00 69 20 63 61 - 73 74 20 2F 75 73 65 61  | ..a.i cast /usea
  16: 62 69 6C 69 74 79 20 33 - 30 30 30 2C 20 6F 6E 63  | bility 3000, onc
  32: 65 20 6F 6E 20 6E 6F 20 - 74 61 72 67 65 74 2C 20  | e on no target,
  48: 74 77 69 63 65 20 6F 6E - 20 6D 65 20 69 6E 20 71  | twice on me in q
  64: 75 69 63 6B 20 73 75 63 - 63 65 73 73 69 6F 6E 20  | uick succession
  80: 61 6E 64 20 6C 6F 63 6B - 65 64 20 74 68 65 20 77  | and locked the w
  96: 6F 72 6C 64 2E                                     | orld.
   0: 0C 00 0F 00 63 61 6E 20 - 79 6F 75 20 74 72 79 20  | ....can you try
  16: 69 74 3F                                           | it?
   0: 0C 00 10 00 74 72 79 20 - 2F 75 73 65 61 62 69 6C  | ....try /useabil
  16: 69 74 79 3F                                        | ity?
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 22 00 04 00 33 30 30 30                            | "...3000
Combined Packet!
   0: 0C 00 0F 00 69 20 68 65 - 61 6C 65 64 20 6D 79 73  | ....i healed mys
  16: 65 6C 66                                           | elf

   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 22 00 05 00 33 30 30 30 - 30                       | "...30000
   0: 22 00 05 00 33 30 30 30 - 30                       | "...30000
   0: 0C 00 0A 00 79 65 61 68 - 2E 20 33 30 30 30        | ....yeah. 3000
   0: 22 00 05 00 33 30 30 30 - 30                       | "...30000
   0: 25 00 01 00 31                                     | %...1
   0: 22 00 05 00 33 30 30 30 - 30                       | "...30000
   0: 0C 00 12 00 64 6F 33 20 - 6F 66 20 74 68 65 6D 20  | ....do3 of them
  16: 71 75 69 63 6B 2E                                  | quick.
   0: 0C 00 11 00 69 6D 20 61 - 74 74 61 63 6B 69 6E 67  | ....im attacking
  16: 20 66 69 6E 65                                     |  fine
   0: 0C 00 02 00 6F 6B                                  | ....ok
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 25 00 01 00 30                                     | %...0
   0: CB 01 00 00                                        | ....
Unhandled command: clearallqueuedabilities
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: 22 00 04 00 33 30 30 30                            | "...3000
Combined Packet!
   0: 29 00 03 00 61 6C 6C                               | )...all
   0: 0C 00 04 00 68 6D 6D 2E                            | ....hmm.
Possible deadlock attempt by 'SpellProcess::MActiveSpells'!
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: 22 00 04 00 33 30 30 30                            | "...3000
   0: 0C 00 11 00 63 61 6E 74 - 20 63 61 73 74 20 61 6E  | ....cant cast an
  16: 79 6D 6F 72 65                                     | ymore
   0: 0C 00 10 00 63 61 6E 74 - 20 74 61 6C 6B 20 65 69  | ....cant talk ei
  16: 74 68 65 72                                        | ther
Possible deadlock attempt by 'SpellProcess::MActiveSpells'!
   0: 0C 00 2F 00 77 65 6C 6C - 2E 20 49 20 64 69 64 20  | ../.well. I did
  16: 61 20 2F 6C 65 76 65 6C - 20 38 30 2C 20 73 6F 20  | a /level 80, so
  32: 69 20 77 61 73 20 6F 75 - 74 20 6F 66 20 68 65 61  | i was out of hea
  48: 6C 74 68                                           | lth
   0: 0C 00 03 00 6E 76 6D                               | ....nvm
   0: 0C 00 06 00 6C 61 67 67 - 65 64                    | ....lagged
   0: 0C 00 05 00 61 68 68 21 - 21                       | ....ahh!!
   0: 0C 00 0C 00 74 68 61 74 - 20 77 61 73 20 69 74 21  | ....that was it!
   0: 0C 00 13 00 67 72 61 62 - 62 69 6E 67 20 74 68 61  | ....grabbing tha
  16: 74 2E 20 73 65 63 2E                               | t. sec.
   0: 0C 00 03 00 3F 3F 3F                               | ....???
Possible deadlock attempt by 'SpellProcess::MActiveSpells'!

I was level 1, and did a /level 80 - and had barely a HP. So I used our CH script to give me all my health back. First time I did it, I wasn't targeted so I didn't think it worked. I pressed F1, cast the CH again but didn't see anything happen so I did it again thinking I mis-typed. The world reported a deadlock, the all the casts and chat came flying out.

I asked Scat to reproduce it, and he did. Cast the spell, couldn't type (echo), and finally you see the deadlock warning at the bottom.

In the TessDB, this is either spell ID 3 (Beta Heal) or 3000.