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]

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.

[cubber]

file core
core: ELF 32-bit LSB core file Intel 80386, version 1 (SYSV), SVR4-style, from './world'

[cubber]

Ok gdb finished compiling here is the output:

gdb ./world core
GNU gdb 6.8
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-pc-linux-gnu"...
(no debugging symbols found)

warning: Can't read pathname for load map: Input/output error.
Reading symbols from /usr/lib/gcc/i686-pc-linux-gnu/4.3.2/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/gcc/i686-pc-linux-gnu/4.3.2/libstdc++.so.6
Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libz.so.1...
(no debugging symbols found)...done.
Loaded symbols for /lib/libz.so.1
Reading symbols from /lib/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /usr/lib/libmysqlclient.so.15...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libmysqlclient.so.15
Reading symbols from /lib/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libnsl.so.1...
(no debugging symbols found)...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /usr/lib/libssl.so.0.9.8...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libssl.so.0.9.8
Reading symbols from /usr/lib/libcrypto.so.0.9.8...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libcrypto.so.0.9.8
Reading symbols from /usr/lib/libperl.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libperl.so.1
Reading symbols from /lib/libpthread.so.0...
(no debugging symbols found)...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib/libutil.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/libutil.so.1
Reading symbols from /lib/libc.so.6...
(no debugging symbols found)...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /usr/lib/gcc/i686-pc-linux-gnu/4.3.2/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/gcc/i686-pc-linux-gnu/4.3.2/libgcc_s.so.1
Reading symbols from /lib/ld-linux.so.2...
(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /opt/eqemu/libEMuShareMem.so...
(no debugging symbols found)...done.
Loaded symbols for libEMuShareMem.so
(no debugging symbols found)
Core was generated by `./world'.
Program terminated with signal 11, Segmentation fault.
[New process 27074]
[New process 27081]
[New process 27083]
[New process 27077]
[New process 27076]
[New process 27079]
[New process 27080]
#0 0x0807e4a8 in Client::OPCharCreate ()
(gdb) bt
#0 0x0807e4a8 in Client::OPCharCreate ()
#1 0x08080e03 in Client::HandlePacket ()
#2 0x08081aee in Client::Process ()
#3 0x080f3c3a in ClientList::Process ()
#4 0x080860ec in main ()
(gdb)

[gaeorn]

Your world executable appears to be stripped. That removes a lot of debugging information. I would suggest you rebuild it and not strip it. Then get the backtrace from a fresh core dump.

[gaeorn]

From what I'm hearing, gentoo strips the executable by default. I don't know how to change that behavior. You should do some google searches or ask a gentoo expert to find out how to disable stripping the executable.

[cubber]

here is what I change in my makefiles

DFLAGS=-DDEBUG=5 -DEQDEBUG=2 -DSHAREMEM -DCATCH_CRASH -DNO_PIDLOG -DFIELD_ITEMS -DIRC -Di386 -DAPP_OPCODE_SIZE=2 -DEQBOTS


COPTS=$(WFLAGS) -march=native -O3 -pthread -pipe

I also remove the -g and -pg flags if they are there.

I take it you want me to change the DEQDEBUG=2 to something like DEQDEBUG=5?

[gaeorn]

You need the -g option in there to include debugging information.

[cubber]

Ok I will try recompiling with -g, then I will reproduce the crash and hit the new core file with gdb and post the results.

[cubber]

Very Interesting...

I wacked my svn source folder and just pulled down new sources. Ended up being rev752.

I then only changed the -march=i686 option in each makefile to -march=native and left everything else at default. I also did NOT enable bots.

I did not change any -O options or remove the -g flags like I normally do nor did I change -DEQDEBUG=5 to -DEQDEBUG=2.

When I went to log in and create a character the character created fine but I got an error saying that the zone was not available yet. It then just stuck the character in my list and I was then able to choose the character and login to Gloomingdeep.

So something in the compile options was screwing me up. Though I have used those settings for quite a while now without an issue. The only change now is that I am running gcc4.3.2 instead of gcc3.2.6 and using -march=native instead of -march=cpufamily_name.

I will have to try recompiling with bots and see if it still works.

[gaeorn]

If I were to venture a guess, I would suspect the -O3 as the culprit.

[cubber]

yah gonna leave them alone, and just keep everything default with the -march=native and try enabling bots.

does removing -g and changing -DEQDEBUG=2 give that much more of a performance boost over running the server with it enabled?

[gaeorn]

As far as the DEBUG=2, I would doubt it would have much effect since most of the debugging is configured at runtime now.

As to the -g, I'm not the right person to ask. My guess would be that it doesn't slow it down much.

[cubber]

Compiled with bots and all seems fine. Thanks for the assistance!