Login hangs at Retrieving Characters

[KorhalDragonir]

Hello All,

I have the issue that sometimes my login hangs on Retrieving Characters.

The symptoms I see are, mangos is using more CPU than normal:

top - 22:07:29 up 11 days,  3:22,  2 users,  load average: 2.38, 2.31, 2.26
Tasks: 131 total,   1 running, 130 sleeping,   0 stopped,   0 zombie
Cpu(s): 12.2%us,  5.0%sy,  0.2%ni, 41.9%id, 40.5%wa,  0.0%hi,  0.2%si,  0.0%st
Mem:   7788844k total,  5230104k used,  2558740k free,   584624k buffers
Swap: 15625212k total,        0k used, 15625212k free,  3526708k cached

 PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
30017 mangos    20   0 1053m 400m  11m S   29  5.3  13:34.37 mangosd
1154 mysql     20   0 1311m 143m 8424 S    2  1.9 172:19.66 mysqld
13642 mangos    20   0  111m 4784 3616 S    1  0.1  90:24.69 realmd

Not sure why.

This is the MaNGOS I am using:

MaNGOS/ (* * Revision 12348 - *) for Linux_x64 (little-endian)
Using script library: ScriptDev2 (for C-MaNGOS 12328+) Revision [2784] (*) * * (Unix)
Using World DB: UDB 0.12.2 (405) for MaNGOS 12111 with SD2 SQL for rev. 2712
Using creature EventAI: ACID 3.1.0 'Another Wild Adventure' - Full Release for CMaNGOS (3.3.5a Client)

So far I have tried tweaking the settings, but it seemed to be of no use. This process takes up about 15 minutes and then it continues again. This started a few revisions back.

So far I cannot seem to find out what is going on, the Linux server itself stays responsive and no extra processes start at that same time as well.

Some advice please.

Thank you in advance.

[KorhalDragonir]

So far it seem to have (temporarily) resolved itself. I will see if it occurs again within a week. And see if I can find a pattern as to why this is happening.

[KorhalDragonir]

Nope it is back.

[KorhalDragonir]

I have replaced the disk and the performance of the Disk I/O is now okay.

However it still freezes after login. Retrieving character list.. is sometimes shown for up to 30-minutes and basically then I just give up and don't want to login anymore.

I have been experiencing this issue for quite some time now and no matter what I try I cannot seem to get it resolved. The output is still the same as in the log files above.

I hope anyone still has an idea on how to resolve this.

[antz]

Thats strange, I often see a slight delay at that point - but never a lock up.

Is there anything of interest in the logs ?

[KorhalDragonir]

Not for as far as I have seen so far.

I have changed the LogFileLevel to 3 and am currently gathering some log files to see if anything changes when it locks. I will post some snippets this evening, since more eyes see more than just one pair.

I must agree with you I have never experienced anything like this before. The strange part is that only the logon itself hangs, since players already logged on are not influenced. I do not rule out an issue on my server just yet either.

Let's hope we can find what is causing this soon.

[KorhalDragonir]

This is the Realmd.log, all seems fine in the Realmd:

2013-02-05 16:51:25 Accepting connection from '127.0.0.1'
2013-02-05 16:51:29 [Auth] got data for cmd 0 recv length 40
2013-02-05 16:51:29 Entering _HandleLogonChallenge
2013-02-05 16:51:29 [AuthChallenge] got header, body is 0x24 bytes
2013-02-05 16:51:29 [AuthChallenge] got full packet, 0x24 bytes
2013-02-05 16:51:29 [AuthChallenge] name(6): 'KORHAL'
2013-02-05 16:51:29 [AuthChallenge] Account 'KORHAL' is not locked to ip
2013-02-05 16:51:29 database authentication values: v='0D0CC4FB013519C5B971414C348589BC1FE642534339FC5DBD870BFB9886DDA5' s='B6852D1F3A7F4F053E03D269C2304B88027C7671A6FFC28562AE8D4F224FA453'
2013-02-05 16:51:29 [AuthChallenge] account KORHAL is using 'enUS' locale (0)
2013-02-05 16:51:33 [Auth] got data for cmd 1 recv length 75
2013-02-05 16:51:33 Entering _HandleLogonProof
2013-02-05 16:51:33 User 'KORHAL' successfully authenticated
2013-02-05 16:51:36 [Auth] got data for cmd 16 recv length 5
2013-02-05 16:51:36 Entering _HandleRealmList
2013-02-05 16:51:43 Ping MySQL to keep connection alive

The reason for the 127.0.0.1 is because I use an SSH tunnel for this test. Mainly because the ports are blocked from where I was testing.

What I see in the Server.log when it fails is this:

2013-02-05 16:51:42 WorldSocket::HandleAuthSession: client build 12340, account KORHAL, clientseed 49700F55
2013-02-05 16:51:42 WorldSocket::HandleAuthSession: (s,v) check s: B6852D1F3A7F4F053E03D269C2304B88027C7671A6FFC28562AE8D4F224FA453 v: 0D0CC4FB013519C5B971414C348589BC1FE642534339FC5DBD870BFB9886DDA5
2013-02-05 16:51:42 WorldSocket::HandleAuthSession: Client 'KORHAL' authenticated successfully from 127.0.0.1.
2013-02-05 16:51:42 ADDON: Name: Blizzard_AchievementUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_ArenaUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_AuctionUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_BarbershopUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_BattlefieldMinimap, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_BindingUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_Calendar, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_CombatLog, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_CombatText, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_DebugTools, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_GMChatUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_GMSurveyUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_GlyphUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_GuildBankUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_InspectUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_ItemSocketingUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_MacroUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_RaidUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_TalentUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_TimeManager, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_TokenUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_TradeSkillUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 ADDON: Name: Blizzard_TrainerUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 16:51:42 Server Population (0.080000).
2013-02-05 16:51:45 WORLD: Received opcode CMSG_READY_FOR_ACCOUNT_DATA_TIMES
2013-02-05 16:51:45 WORLD: Received opcode CMSG_REALM_SPLIT

And then after 6 minutes:

2013-02-05 16:57:45 Build enum data for char guid 2 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 14 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 76 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 157 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 168 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 174 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 194 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 199 from account 5.
2013-02-05 16:57:45 Build enum data for char guid 204 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 2 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 14 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 76 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 157 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 168 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 174 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 194 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 199 from account 5.
2013-02-05 16:57:47 Build enum data for char guid 204 from account 5.

Strangely it sometimes waits for 15 minutes or longer as well.

[KorhalDragonir]

I am trying now from home, without tunnel. And see this:

2013-02-05 19:55:32 WorldSocket::HandleAuthSession: client build 12340, account KORHAL, clientseed 2071A240
2013-02-05 19:55:32 WorldSocket::HandleAuthSession: (s,v) check s: B6852D1F3A7F4F053E03D269C2304B88027C7671A6FFC28562AE8D4F224FA453 v: 0D0CC4FB013519C5B971414C348589BC1FE642534339FC5DBD870BFB9886DDA5
2013-02-05 19:55:32 WorldSocket::HandleAuthSession: Client 'KORHAL' authenticated successfully from 86.87.114.180.
2013-02-05 19:55:32 ADDON: Name: Blizzard_AchievementUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_ArenaUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_AuctionUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_BarbershopUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_BattlefieldMinimap, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_BindingUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_Calendar, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_CombatLog, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_CombatText, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_DebugTools, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_GMChatUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_GMSurveyUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_GlyphUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_GuildBankUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_InspectUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_ItemSocketingUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_MacroUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_RaidUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_TalentUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_TimeManager, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_TokenUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_TradeSkillUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 ADDON: Name: Blizzard_TrainerUI, Enabled: 0x1, CRC: 0x4c1c776d, Unknown2: 0x0
2013-02-05 19:55:32 Server Population (0.080000).
2013-02-05 19:55:32 WORLD: Received opcode CMSG_READY_FOR_ACCOUNT_DATA_TIMES
2013-02-05 19:55:32 WORLD: Received opcode CMSG_REALM_SPLIT
2013-02-05 19:58:01 GameEvent 61 "Stormwind City - Stockades Jail Break" started.
2013-02-05 19:58:01 Next game event check in 120 seconds

.

Everything is fine, but he refuses the Build the enums for the characters.

Then later once again:

2013-02-05 19:59:09 Build enum data for char guid 2 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 14 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 76 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 157 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 168 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 174 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 194 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 199 from account 5.
2013-02-05 19:59:09 Build enum data for char guid 204 from account 5.

I just cannot figure out what is causing this lock.