World crashes

[cubber]

For about the past month my server has been experiencing random world crashes. I tend to keep my server pretty recient with SVN and I think it may have been around the time the new bot code was starting to get worked in. I could have a few people playing on the server or just one and it could be stable for a few hours then everyone just goes LD and I see an entry in the crashlog.

I made a new server in a virtualbox on a different PC, using the same OS and all the same settings I normally use with the same DB and still get the issue. So I ruled out hardware.

The logs do not really tell me anything interesting but here is what I have found:

Note these logs are from the VM but appear the same on the live server.

crashlog:

Thu Jul 2 09:14:56 EDT 2009 World crashed.
Thu Jul 2 09:19:18 EDT 2009 World crashed.
Thu Jul 2 10:39:19 EDT 2009 World crashed.
Thu Jul 2 13:25:20 EDT 2009 World crashed.
Fri Jul 3 22:07:21 EDT 2009 World crashed.
Sun Jul 5 18:58:04 EDT 2009 World crashed.
Mon Jul 6 21:11:14 EDT 2009 World crashed.
Mon Jul 6 21:15:31 EDT 2009 World crashed.
Mon Jul 6 21:17:55 EDT 2009 World crashed.

eqemu_debug_5089.log

[07.05. - 18:59:35] Starting Log: logs/eqemu_debug_5089.log
[07.05. - 18:59:35] [LAUNCHER__INIT] Loading server configuration..
[07.05. - 18:59:35] [COMMON__THREADS] Starting TCPConnectionLoop with thread ID -1214076016
[07.05. - 18:59:35] [LAUNCHER__INIT] Starting main loop...
[07.05. - 18:59:35] [NET__WORLD] Connected to World: localhost:9000
[07.05. - 18:59:40] [LAUNCHER__WORLD] World told us to start zone dynamic_01.
[07.05. - 18:59:40] [LAUNCHER__WORLD] World told us to start zone dynamic_02.
[07.05. - 18:59:40] [LAUNCHER__WORLD] World told us to start zone dynamic_03.
[07.05. - 18:59:40] [LAUNCHER__WORLD] World told us to start zone dynamic_04.
[07.05. - 18:59:40] [LAUNCHER__WORLD] World told us to start zone dynamic_05.
[07.05. - 18:59:40] [LAUNCHER__ERROR] World told us to start zone dynamic_01, but it is already running.
[07.05. - 18:59:40] [LAUNCHER__ERROR] World told us to start zone dynamic_02, but it is already running.
[07.05. - 18:59:40] [LAUNCHER__ERROR] World told us to start zone dynamic_03, but it is already running.
[07.05. - 18:59:40] [LAUNCHER__ERROR] World told us to start zone dynamic_04, but it is already running.
[07.05. - 18:59:40] [LAUNCHER__ERROR] World told us to start zone dynamic_05, but it is already running.
[07.05. - 18:59:40] [LAUNCHER__STATUS] Starting zone dynamic_01
[07.05. - 18:59:40] [LAUNCHER__STATUS] Zone dynamic_01 has been started.
[07.05. - 18:59:40] [LAUNCHER__STATUS] Waiting 20000 milliseconds before booting the second zone.
[07.05. - 19:00:00] [LAUNCHER__STATUS] Starting zone dynamic_02
[07.05. - 19:00:00] [LAUNCHER__STATUS] Zone dynamic_02 has been started.
[07.05. - 19:00:00] [LAUNCHER__STATUS] Waiting 2000 milliseconds before booting the next zone.
[07.05. - 19:00:02] [LAUNCHER__STATUS] Starting zone dynamic_03
[07.05. - 19:00:02] [LAUNCHER__STATUS] Zone dynamic_03 has been started.
[07.05. - 19:00:02] [LAUNCHER__STATUS] Waiting 2000 milliseconds before booting the next zone.
[07.05. - 19:00:04] [LAUNCHER__STATUS] Starting zone dynamic_04
[07.05. - 19:00:04] [LAUNCHER__STATUS] Zone dynamic_04 has been started.
[07.05. - 19:00:04] [LAUNCHER__STATUS] Waiting 2000 milliseconds before booting the next zone.
[07.05. - 19:00:06] [LAUNCHER__STATUS] Starting zone dynamic_05
[07.05. - 19:00:06] [LAUNCHER__STATUS] Zone dynamic_05 has been started.
[07.05. - 19:00:06] [LAUNCHER__STATUS] Waiting 2000 milliseconds before booting the next zone.
[07.06. - 21:11:14] [COMMON__THREADS] Ending TCPConnectionLoop with thread ID -1214076016
[07.06. - 21:11:21] [COMMON__THREADS] Starting TCPConnectionLoop with thread ID -1222468720
[07.06. - 21:11:23] [NET__WORLD] Connected to World: localhost:9000
[07.06. - 21:11:25] [LAUNCHER__ERROR] World told us to start zone dynamic_01, but it is already running.
[07.06. - 21:11:25] [LAUNCHER__ERROR] World told us to start zone dynamic_02, but it is already running.
[07.06. - 21:11:25] [LAUNCHER__ERROR] World told us to start zone dynamic_03, but it is already running.
[07.06. - 21:11:25] [LAUNCHER__ERROR] World told us to start zone dynamic_04, but it is already running.
[07.06. - 21:11:25] [LAUNCHER__ERROR] World told us to start zone dynamic_05, but it is already running.
[07.06. - 21:15:31] [COMMON__THREADS] Ending TCPConnectionLoop with thread ID -1222468720
[07.06. - 21:15:32] [COMMON__THREADS] Starting TCPConnectionLoop with thread ID -1230861424
[07.06. - 21:15:44] [NET__WORLD] Connected to World: localhost:9000
[07.06. - 21:15:46] [LAUNCHER__ERROR] World told us to start zone dynamic_01, but it is already running.
[07.06. - 21:15:46] [LAUNCHER__ERROR] World told us to start zone dynamic_02, but it is already running.
[07.06. - 21:15:46] [LAUNCHER__ERROR] World told us to start zone dynamic_03, but it is already running.
[07.06. - 21:15:46] [LAUNCHER__ERROR] World told us to start zone dynamic_04, but it is already running.
[07.06. - 21:15:46] [LAUNCHER__ERROR] World told us to start zone dynamic_05, but it is already running.
[07.06. - 21:17:55] [COMMON__THREADS] Ending TCPConnectionLoop with thread ID -1230861424
[07.06. - 21:18:03] [COMMON__THREADS] Starting TCPConnectionLoop with thread ID -1239254128
[07.06. - 21:18:05] [NET__WORLD] Connected to World: localhost:9000
[07.06. - 21:18:07] [LAUNCHER__ERROR] World told us to start zone dynamic_01, but it is already running.
[07.06. - 21:18:07] [LAUNCHER__ERROR] World told us to start zone dynamic_02, but it is already running.
[07.06. - 21:18:07] [LAUNCHER__ERROR] World told us to start zone dynamic_03, but it is already running.
[07.06. - 21:18:07] [LAUNCHER__ERROR] World told us to start zone dynamic_04, but it is already running.
[07.06. - 21:18:07] [LAUNCHER__ERROR] World told us to start zone dynamic_05, but it is already running.

eqemu_debug_world.log
(only stuff around the time of the crash)

07-06 21-11-14 crash

5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Name approval request.  Name=Deadend, race=Iksar, class=Monk
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Character creation request from accountname LS#50 (68.214.46.138:50422) :
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Name: Deadend
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Race: 128  Class: 7  Gender: 0  Deity: 203  Start zone: 189
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: STR  STA  AGI  DEX  WIS  INT  CHA    Total
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname:  75   95  100   95   80   75   55     575
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Face: 6  Eye colors: 5 5
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Hairstyle: 255  Haircolor: 255
5078 [07.06. - 21:11:13] [WORLD__CLIENT] accountname: Beard: 255  Beardcolor: 255
5078 [07.06. - 21:11:13] [WORLD__CLIENT] Validating char creation info...
5078 [07.06. - 21:11:13] [WORLD__CLIENT] Found 0 errors in character creation request
---------------------------------------------
8660 [07.06. - 21:11:16] Starting Log: logs/eqemu_debug_world.log
8660 [07.06. - 21:11:16] [COMMON__THREADS] Starting TCPServerLoop with thread ID -1215624304
8660 [07.06. - 21:11:16] [COMMON__THREADS] Starting TCPServerLoop with thread ID -1224017008
8660 [07.06. - 21:11:16] [RULES__CHANGE] Resetting running rules to default values
8660 [07.06. - 21:11:16] [WORLD__INIT] Loading server configuration..
8660 [07.06. - 21:11:16] [WORLD__INIT] Log settings loaded from log.ini
8660 [07.06. - 21:11:16] [WORLD__INIT] CURRENT_WORLD_VERSION:EQEMu 0.7.0
8660 [07.06. - 21:11:16] [WORLD__INIT] Connecting to MySQL...
8660 [07.06. - 21:11:16] [COMMON__THREADS] Starting DBAsyncLoop with thread ID -1232409712
8660 [07.06. - 21:11:16] [WORLD__INIT] Starting HTTP world service...
8660 [07.06. - 21:11:16] [WORLD__HTTP] Loaded mime types from mime.types
8660 [07.06. - 21:11:16] [WORLD__INIT] Loading variables..
8660 [07.06. - 21:11:16] [WORLD__INIT] Loading zones..
8660 [07.06. - 21:11:16] [WORLD__INIT] Clearing groups..
8660 [07.06. - 21:11:16] [WORLD__INIT] Clearing raids..
8660 [07.06. - 21:11:16] [WORLD__INIT] Loading items..
8660 [07.06. - 21:11:16] [WORLD__INIT] Loading guilds..

07-06 21:15:31 crash

8660 [07.06. - 21:15:30] [WORLD__CLIENT] accountname: Name approval request.  Name=Deadwrong, race=Iksar, class=Monk
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Character creation request from dexxmexx LS#50 (68.214.46.138:50437) :
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Name: Deadwrong
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Race: 128  Class: 7  Gender: 0  Deity: 203  Start zone: 189
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: STR  STA  AGI  DEX  WIS  INT  CHA    Total
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname:  75   95  100   95   80   75   55     575
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Face: 6  Eye colors: 3 3
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Hairstyle: 255  Haircolor: 255
8660 [07.06. - 21:15:31] [WORLD__CLIENT] accountname: Beard: 255  Beardcolor: 255
8660 [07.06. - 21:15:31] [WORLD__CLIENT] Validating char creation info...
8660 [07.06. - 21:15:31] [WORLD__CLIENT] Found 0 errors in character creation request
---------------------------------------------
8675 [07.06. - 21:15:33] Starting Log: logs/eqemu_debug_world.log
8675 [07.06. - 21:15:33] [COMMON__THREADS] Starting TCPServerLoop with thread ID -1214485616
8675 [07.06. - 21:15:33] [COMMON__THREADS] Starting TCPServerLoop with thread ID -1222878320
8675 [07.06. - 21:15:33] [RULES__CHANGE] Resetting running rules to default values
8675 [07.06. - 21:15:33] [WORLD__INIT] Loading server configuration..
8675 [07.06. - 21:15:33] [WORLD__INIT] Log settings loaded from log.ini
8675 [07.06. - 21:15:33] [WORLD__INIT] CURRENT_WORLD_VERSION:EQEMu 0.7.0
8675 [07.06. - 21:15:33] [WORLD__INIT] Connecting to MySQL...
8675 [07.06. - 21:15:33] [COMMON__THREADS] Starting DBAsyncLoop with thread ID -1231271024
8675 [07.06. - 21:15:33] [WORLD__INIT] Starting HTTP world service...
8675 [07.06. - 21:15:33] [WORLD__HTTP] Loaded mime types from mime.types
8675 [07.06. - 21:15:33] [WORLD__INIT] Loading variables..
8675 [07.06. - 21:15:33] [WORLD__INIT] Loading zones..
8675 [07.06. - 21:15:33] [WORLD__INIT] Clearing groups..
8675 [07.06. - 21:15:33] [WORLD__INIT] Clearing raids..
8675 [07.06. - 21:15:33] [WORLD__INIT] Loading items..
8675 [07.06. - 21:15:33] [WORLD__INIT] Loading guilds..

the last one was another character creation attempt. All of my users use the SoF client. These crashes also occur randomly when just playing. I don't have any logs of those at this time though.

If anyone would like to see any other logs please let me know. I am anxious to get this issue resolved.

One last bit, my PrivateLogin server console showing the world reconnects:

Using database 'eqemuls' at 127.0.0.1
Reading LoginServer.ini...
[LS-Config] Server Name: Server Name
[LS-Config] Server Description: Server Description
[LS-Config] Custom IP Interface Bind: 192.168.42.10
[LS-Config] Allowing anonymous world servers are disabled.
LoginServer.ini read.
Server mode: Private Login
============================
EQEmu Private Login v1.04PL
http://eqemu.devnoob.com
============================
Resolved 192.168.42.10 to 170567872
Login server listening on port:5999
World has connected with account name: account
Removing LWorld from ip: 192.168.42.10, port: 33185
World has connected with account name: account
Removing LWorld from ip: 192.168.42.10, port: 33192
World has connected with account name: account
Removing LWorld from ip: 192.168.42.10, port: 44318
World has connected with account name: account
Removing LWorld from ip: 192.168.42.10, port: 44326
World has connected with account name: account

Thanks!

[gaeorn]

Do you have any core dumps from the crashes? If so, could you get a backtrace in gdb? Thanks.

Also, what kind of system is this running on: debian, fedora, etc.?

[cubber]

There are no core dumps in the eqemu directory. The os is Gentoo x86 on both systems. I actually have since wiped the live server and am in the process of redoing it so I am just running off the VM.

Also the user that the crashes happend to last night said it was only on character creation. He tried to create an iksar monk 3 x and it failed each time. He had a hydra account up and noticed a "world crashed" notice in yellow letters in his chat.

I just tried to create a new character on my GM account and got the same issue. I could create the character but as soon as I clicked enter world and it tried to put me in glooming deep it crashed the world. This was on a SoF client.

I also noticed that there is an option for start city for each character with the old home town and crescent reach. with crescent reach being the default. Now on a peq clone server crescent reach is not avaialable to non GM accounts.

[cubber]

Ok I just logged into my account I just tried to create the toon on. I had a console window open ssh'd into the server and rain tail -f world in the logs directory. This poped up as soon as I logged into my account:

Got a bogus character (Lyla) Ignoring!!!
PP length =0 but PP should be 19568

and the character was not in my character list but it is present in the DB if I look under phpmyadmin. So are all of the characters that the other user tried to create.

[cubber]

Also as soon as I hit create character button the world immediatly crashes in the console.

[gaeorn]

Your DB will need to be cleaned up to remove the incomplete chars. I have no idea if the incomplete chars could be a cause for the crashes. They might simply be a result of the crashes.

You could run world under gdb and get a backtrace when it crashes. In your server dir, run the following. You type the portions in red.

gdb ./world
...misc output...
(gdb) handle SIGTRAP nostop
SIGTRAP is used by the debugger.
Are you sure you want to change it? (y or n) y
Signal        Stop      Print   Pass to program Description
SIGTRAP       No        Yes     No              Trace/breakpoint trap
(gdb) run
...bunch of output...

At that point you can start up your zone servers and then log in and try to create a character. When the process crashes, it will drop you back to the (gdb) prompt.

(gdb) bt
...bunch of output from backtrace...
(gdb)

Post the backtrace output here and I'll see if I can help you further.

[cubber]

I don't have GDB

gdb ./world
-bash: gdb: command not found


I have been deleting the "borked" characters after i attempt to create them. They are sticking in phpmyadmin I just go into the character_ table and remove them one by one.

As for the core dump I do have one just missed it. The file is huge and has just a bunch of characers in it with some words here and there. Want me to post it somewhere for download?

I also just updated my server to SVN Rev751. I tried to create a new toon, and it still has the same issue.

Note I am using PEQ rev703 as a DB with all the updates in the utils/sql/svn folder applied.

[gaeorn]

You can get a backtrace of the corefile using gdb:

gdb ./world <corefilename>
...bunch of output...
(gdb) bt
...output from backtrace...
(gdb)

Replace <corefilename> with the name of the core file. Save the output from the backtrace and post it here.

[gaeorn]

doh. no gdb. hrm, lemme get you information about how to install it.

[cubber]

this look like the right package:

 emerge -av gdb

These are the packages that would be merged, in order:

Calculating dependencies... done!
[ebuild  N    ] sys-devel/gdb-6.8-r1  USE="nls -multitarget -test -vanilla" 15,337 kB

[gaeorn]

try:

emerge gdb

that might get it installed. I'm not a Gentoo expert, though, so perhaps someone who runs Gentoo could chime in here.

[cubber]

Gonna take a bit to compile gdb I will post the backtrace of the core file when it is done.

the file I am looking to use for the backtrace is called "core" and has a bunch of characters in it like @@@@ correct?

[gaeorn]

Originally Posted by cubber

this look like the right package:

 emerge -av gdb

These are the packages that would be merged, in order:

Calculating dependencies... done!
[ebuild  N    ] sys-devel/gdb-6.8-r1  USE="nls -multitarget -test -vanilla" 15,337 kB

Yeah, that looks good. See if you can run gdb after that. If so, there's information in earlier posts to use gdb on the core file. No need to run world under gdb since you have core files.

[cubber]

here is more info on the gdb package I am installing

http://www.gentoo-portage.com/sys-devel/gdb

says gnu debugger so I figured it was correct. I am emerging it now.

[gaeorn]

File name is dependent on system configuration, but usually includes 'core' in the file name. The file is a binary image of the memory used by the program when it crashed, so it will not appear very human readable. You should be able to type 'file core' and it will tell you what the core file is from.