Hmm, I guess the section in red in the logs above aren't the issue. That seems to be normal when I compare it to these logs from a Titanium login that works:
Code:
13958 [12.08. - 04:33:25] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x0103
13958 [12.08. - 04:33:25] [NET__APP_TRACE] Queueing acked packet with opcode 0x4ec (OP_ExpansionInfo) and length 4
13958 [12.08. - 04:33:25] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x0102
13958 [12.08. - 04:33:25] [NET__APP_TRACE] Queueing acked packet with opcode 0x4513 (OP_SendCharInfo) and length 1704
13958 [12.08. - 04:33:32] [WORLD__CLIENT_TRACE] [OpCode OP_ApproveWorld (0x3c25) Size=272]
13958 [12.08. - 04:33:33] [WORLD__CLIENT_TRACE] [OpCode OP_World_Client_CRC1 (0x5072) Size=2056]
13958 [12.08. - 04:33:33] [WORLD__CLIENT_TRACE] [OpCode OP_World_Client_CRC2 (0x5b18) Size=2056]
[ProtoOpCode 0x0009 Size=8]
13958 [12.08. - 04:34:03] [NET__NET_CREATE_HEX] 1969-12-31 18:00:03.000000 [ProtoOpCode 0x0009 Size=4]
13958 [12.08. - 04:34:03] [WORLD__CLIENT_TRACE] [OpCode OP_AckPacket (0x7752) Size=4]
13958 [12.08. - 04:34:03] [WORLD__CLIENT_TRACE] [OpCode OP_WorldClientReady (0x5e99) Size=0]
13958 [12.08. - 04:34:42] [WORLD__CLIENT_TRACE] [OpCode OP_EnterWorld (0x7cba) Size=72]
13958 [12.08. - 04:34:42] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x00ff
13958 [12.08. - 04:34:42] [NET__APP_TRACE] Queueing acked packet with opcode 0x24d (OP_MOTD) and length 403
13958 [12.08. - 04:34:42] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x010d
13958 [12.08. - 04:34:42] [NET__APP_TRACE] Queueing acked packet with opcode 0xd7 (OP_SetChatServer) and length 58
13958 [12.08. - 04:34:42] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x010e
13958 [12.08. - 04:34:42] [NET__APP_TRACE] Queueing acked packet with opcode 0x6536 (OP_SetChatServer2) and length 58
[Debug] [ZONE__WORLD_TRACE] Got 0x0031 from world:
[Debug] [ZONE__WORLD_TRACE] Got 0x0008 from world:
[Debug] [ZONE__WORLD_TRACE] Got 0x0006 from world:
13958 [12.08. - 04:34:42] [WORLD__CLIENTLIST] ClientList[0x08152540]::FindByAccountID(0x2) iterator.GetData()[0x8173900]13958 [12.08. - 04:34:42] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x010f
13958 [12.08. - 04:34:42] [NET__APP_TRACE] Queueing acked packet with opcode 0x61b6 (OP_ZoneServerInfo) and length 130
[ProtoOpCode 0x0015 Size=2]
[ProtoOpCode 0x0009 Size=4]
13958 [12.08. - 04:34:43] [WORLD__CLIENT_TRACE] [OpCode OP_WorldComplete (0x509d) Size=0]
[Debug] [ZONE__WORLD_TRACE] Got 0x0027 from world:
[Debug] [ZONE__WORLD_TRACE] Got 0x0024 from world:
[Debug] [ZONE__WORLD_TRACE] Got 0x200e from world:
[Debug] [NET__NET_TRACE] 192.168.1.101:4296: Sending OP_SessionResponse: session 767659547, maxlen=512, key=0x11223344, compressed? yes, encoded? no
[Debug] [NET__NET_CREATE_HEX] 1969-12-31 18:04:16.000000 [ProtoOpCode 0x0009 Size=8]
[ProtoOpCode 0x0009 Size=72]
[Debug] [NET__IDENT_TRACE] 192.168.1.101:4296: First opcode 0x7752 did not match expected 0x2792
[Debug] [NET__IDENT_TRACE] 192.168.1.101:4296: First opcode 0x7213 did not match expected 0x2ec9
[Debug] [NET__IDENT_TRACE] 192.168.1.101:4296: First opcode 0x7752 did not match expected 0x4dd0
[Debug] [NET__IDENT_TRACE] 192.168.1.101:4296: First opcode matched 0x7213 and length matched 68
[Debug] [CLIENT__NET_IN_TRACE] No name: Dispatch opcode: [OpCode OP_AckPacket (0x7752) Size=4]
[Debug] [CLIENT__NET_IN_TRACE] [CLIENT__NET_IN_TRACE] No name: [OpCode OP_AckPacket (0x7752) Size=4]
[Debug] [CLIENT__NET_IN_TRACE] No name: Dispatch opcode: [OpCode OP_ZoneEntry (0x7213) Size=68]
[Debug] [CLIENT__NET_IN_TRACE] [CLIENT__NET_IN_TRACE] No name: [OpCode OP_ZoneEntry (0x7213) Size=68]
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x75df (OP_PlayerProfile) and length 19592
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x7213 (OP_ZoneEntry) and length 385
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x1580 (OP_TimeOfDay) and length 8
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x5639 (OP_TributeUpdate) and length 48
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x4665 (OP_TributeTimer) and length 4
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x5394 (OP_CharInventory) and length 78352
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x5ef7 (OP_TaskDescription) and length 325
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x682d (OP_TaskActivity) and length 72
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x682d (OP_TaskActivity) and length 28
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x682d (OP_TaskActivity) and length 28
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x682d (OP_TaskActivity) and length 28
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x682d (OP_TaskActivity) and length 28
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x76a2 (OP_CompletedTasks) and length 60
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x254d (OP_Weather) and length 12
[ProtoOpCode 0x0015 Size=2]
[ProtoOpCode 0x0009 Size=8]
[Debug] [CLIENT__NET_IN_TRACE] Trevazar: Dispatch opcode: [OpCode OP_AckPacket (0x7752) Size=4]
[Debug] [CLIENT__NET_IN_TRACE] [CLIENT__NET_IN_TRACE] Trevazar: [OpCode OP_AckPacket (0x7752) Size=4]
[Debug] [CLIENT__NET_IN_TRACE] Trevazar: Dispatch opcode: [OpCode OP_ReqNewZone (0x7ac5) Size=0]
[Debug] [CLIENT__NET_IN_TRACE] [CLIENT__NET_IN_TRACE] Trevazar: [OpCode OP_ReqNewZone (0x7ac5) Size=0]
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x920 (OP_NewZone) and length 700
[Debug] [NET__APP_TRACE] Queueing acked packet with opcode 0x2a28 (OP_CustomTitles) and length 4
[ProtoOpCode 0x0015 Size=2]
[ProtoOpCode 0x0009 Size=4]
[ProtoOpCode 0x0009 Size=4]
[Debug] [CLIENT__NET_IN_TRACE] Trevazar: Dispatch opcode: [OpCode OP_SendAATable (0x367d) Size=0]
[Debug] [CLIENT__NET_IN_TRACE] [CLIENT__NET_IN_TRACE] Trevazar: [OpCode OP_SendAATable (0x367d) Size=0]
The previous logs are all grepping on "0x" to catch all opcodes. Here are some more detailed logs of exactly when the failure happens with the SoF client:
Code:
14299 [12.08. - 04:45:48] [WORLD__CLIENTLIST] ClientList[0x08152540]::FindByAccountID(0x2) iterator.GetData()[0x8173520]14299 [12.08. - 04:45:48] [WORLD__CLIENT] trevadmin: Sending client to zone load (184) at 192.168.1.102:7503
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] trevadmin: Sending EQApplicationPacket OpCode 0x010f
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] [OpCode OP_ZoneServerInfo Size=130]
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0000: 31 39 32 2e 31 36 38 2e - 31 2e 31 30 32 00 00 00 | 192.168.1.102...
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0016: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0032: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0048: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0064: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0080: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0096: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0112: 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 | ................
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] 0128: 4f 1d - | O.
14299 [12.08. - 04:45:48] [NET__APP_TRACE] Queueing acked packet with opcode 0x18b1 (OP_ZoneServerInfo) and length 130
14299 [12.08. - 04:45:48] [NET__APP_TRACE] 192.168.1.101:4316: Pushing sequenced packet 202 of length 134. Base Seq is 202.
14299 [12.08. - 04:45:48] [NET__NET_COMBINE] 192.168.1.101:4316: Starting combined packet with seq packet 202 of len 13414299 [12.08. - 04:45:48] [NET__NET_COMBINE] 192.168.1.101:4316: Final combined packet not full, len 134
14299 [12.08. - 04:45:48] [NET__NET_CREATE] 192.168.1.101:4316: Extracting combined packet of length 4
14299 [12.08. - 04:45:48] [NET__NET_CREATE_HEX] 2030-10-13 02:40:48.2053207653 [216.66.23.8:0->0.0.0.2:64000]
[ProtoOpCode 0x0015 Size=2]
14299 [12.08. - 04:45:48] [NET__NET_CREATE_HEX] 0000: 00 ca - | ..
14299 [12.08. - 04:45:48] [NET__NET_ACKS] 192.168.1.101:4316: Received an ack with no window advancement (seq 202).
14299 [12.08. - 04:45:48] [NET__NET_CREATE] 192.168.1.101:4316: Extracting combined packet of length 6
14299 [12.08. - 04:45:48] [NET__NET_CREATE_HEX] 1974-04-21 20:19:36.000000 [216.66.23.8:17720->56.69.172.183:47020]
[ProtoOpCode 0x0009 Size=4]
14299 [12.08. - 04:45:48] [NET__NET_CREATE_HEX] 0000: 00 19 86 24 - | ...$
14299 [12.08. - 04:45:48] [NET__NET_ACKS] 192.168.1.101:4316: Set Next Ack To Send to 25
14299 [12.08. - 04:45:48] [NET__APP_CREATE] 192.168.1.101:4316: Creating new application packet, length 2
14299 [12.08. - 04:45:48] [NET__APP_CREATE_HEX] 0000: 86 24 - | .$
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] trevadmin: Recevied EQApplicationPacket
14299 [12.08. - 04:45:48] [WORLD__CLIENT_TRACE] [OpCode OP_WorldComplete (0x2486) Size=0]
14299 [12.08. - 04:45:48] [NET__DEBUG] 192.168.1.101:4316: Stream requested to Close(), but there is pending data, waiting for it.
14299 [12.08. - 04:45:48] [NET__NET_TRACE] 192.168.1.101:4316: Changing state from 0 to 1
14299 [12.08. - 04:45:48] [WORLD__CLIENT] trevadmin: Client disconnected (not active in process)
14299 [12.08. - 04:45:48] [WORLD__CLIENTLIST] Removing client from 192.168.1.101:4316
14299 [12.08. - 04:45:48] [NET__DEBUG] 192.168.1.101:4316: Stream requested to Close(), but there is pending data, waiting for it.
It looks like it happens right after the OP_WorldComplete comes in, so maybe that has something to do with it.