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:
Code:
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
Code:
[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
Code:
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
Code:
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:
Code:
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!