|
Notes |
|
|
(0000720)
|
|
Mirravin
|
25-10-10 02:28
(edited on: 25-10-10 02:29) |
|
I get this problem one time on version #1340. Then I get logs with > 100 mb weight. But this flood ended without any actions a few hours after beggining. I found only result of it in logs.
|
|
|
|
|
Other than the increased log size / console output, is there anything bad actually happening?
Multiple flushing messages are possible (especially with EF_NetworkOutThread enabled), so I can simply disable the debug message as long as everything else is working normally (i.e. the messages stop within a 'reasonable' length of time, followed by other debug messages indicating client 97 is closed & cleared). |
|
|
|
|
|
I only found logs and don't have information about other problems caused by this. |
|
|
|
|
Other than the increased log size / console output, is there anything bad actually happening?
No. In the previous lines to the thousands of messages there are no errors.
The messages can take hours and hours without anyone connecting or anyone connected, strange, no? |
|
|
|
|
Does this happen often? The message lasting hours doesn't really sound right, unless there are a lot of packets queued up and you have your network settings set particularly low (MaxPacketsPerTick and MaxSizePerTick)?
Could you upload a log starting from when the client connected ("97:Client connected") until it disconnects ("97:Client disconnected")?
(I don't need to see every flush message, just the first and last to get an idea of how long it lasted for) |
|
|
|
(0000729)
|
|
Mirravin
|
27-10-10 15:08
(edited on: 27-10-10 15:16) |
|
16:34:DEBUG:Receiving new connection
16:34:DEBUG:Retrieving IP history
16:34:DEBUG:Incoming connection from 'IP1' [blocked=0, ttl=245, pings=0, connecting=0, connected=-1]
16:34:DEBUG:35:Allocated slot for client (25).
16:34:DEBUG:35:Clearing client state.
16:34:DEBUG:35:initialising client
16:34:35:Client connected [Total:12] ('IP1' 1/0)
16:34:DEBUG:35:determining async mode
16:34:DEBUG:35:Opening network state
16:34:DEBUG:35:State initialised, registering client instance.
16:34:DEBUG:35:Client successfully initialised.
16:34:DEBUG:35:Receiving old client login handshake.
16:34:DEBUG:35:Client connected with a seed of 0xa000811 (new handshake=0, seed length=4, received=66, version=0x0).
16:34:35:Login 'acc1'
16:34:DEBUG:Receiving new connection
16:34:DEBUG:Retrieving IP history
16:34:DEBUG:Incoming connection from 'IP1' [blocked=0, ttl=296, pings=1, connecting=0, connected=0]
16:34:DEBUG:36:Allocated slot for client (26).
16:34:DEBUG:36:Clearing client state.
16:34:DEBUG:36:initialising client
16:34:36:Client connected [Total:13] ('IP1' 1/1)
16:34:DEBUG:36:determining async mode
16:34:DEBUG:36:Opening network state
16:34:DEBUG:36:State initialised, registering client instance.
16:34:DEBUG:36:Client successfully initialised.
16:34:DEBUG:35:Client being closed by read-thread
16:34:DEBUG:35:Flushing data for client.
16:34:DEBUG:35:Client being closed by read-thread
16:34:DEBUG:36:Receiving old client login handshake.
16:34:DEBUG:36:Client connected with a seed of 0x79949b89 (new handshake=0, seed length=4, received=69, version=0x0).
16:34:36:Login 'acc1'
16:34:DEBUG:35:Client being closed by write-thread
16:34:DEBUG:35:Client is being cleared since marked to close.
16:34:DEBUG:35:Clearing client state.
16:34:35:Client disconnected [Total:12] ('IP1')
16:34:36:Setup_Start acct='acc1', char='name1', IP='IP1'
17:03:WARNING:36:TX Error 11
17:03:DEBUG:36:Client being closed by write-thread
17:03:DEBUG:36:Flushing data for client.
17:03:DEBUG:36:Flushing data for client.
17:03:DEBUG:36:Flushing data for client.
...
23:31:DEBUG:36:Flushing data for client.
23:31:DEBUG:36:Flushing data for client.
23:31:DEBUG:36:Flushing data for client.
23:31:DEBUG:Receiving new connection
23:31:DEBUG:Retrieving IP history
23:31:DEBUG:Incoming connection from 'IP2' [blocked=0, ttl=82, pings=6, connecting=0, connected=0]
23:31:DEBUG:36:Allocated slot for client (28).
23:31:DEBUG:36:Clearing client state.
23:31:36:Client disconnected [Total:18] ('IP1')
23:31:DEBUG:36:initialising client
23:31:36:Client connected [Total:19] ('IP2' 1/1)
23:31:DEBUG:36:determining async mode
23:31:DEBUG:36:Opening network state
23:31:DEBUG:36:State initialised, registering client instance.
23:31:DEBUG:36:Client successfully initialised.
23:31:DEBUG:36:Receiving new client login handshake.
23:31:DEBUG:36:Client connected with a seed of 0xc0a80102 (new handshake=1, seed length=20, received=82, version=0x600081).
23:31:36: Account 'acc2' already in use.
23:31:ERROR:36:Bad Login 1 (The account entered is already being used)
23:31:DEBUG:36:Client being closed by read-thread
23:31:DEBUG:36:Flushing data for client.
23:31:DEBUG:36:Client being closed by write-thread
23:31:DEBUG:36:Client is being cleared since marked to close.
23:31:DEBUG:36:Clearing client state.
//IP1 - 1 constant IP.
//IP2 - 2 contant IP.
|
|
|
|
|
// Disconnect inactive socket in x min
DeadSocketTime=5
// Maximum number of packets to send per tick
MaxPacketsPerTick=25
// Number of connections a client can make before being blocked
MaxPings=15
// Maximum number of packets before lowering packet priorities (0 for no limit)
MaxQueueSize=50
// Maximum number of bytes to send per tick (also governs maximum size of outgoing packets)
MaxSizePerTick=18000
// Time to remember previous connection history (seconds)
NetTTL=300
// Use asynchronous data sends (changing this setting at runtime may produce unexpected behaviour)
// 0 = Off
// 1 = On
// 2 = On for 4.0.0+ game clients only
UseAsyncNetwork=1
// Prioritise outgoing packets (provides a smoother experience in crowded areas)
UsePacketPriority=1
// Tooltip modes
// 0 = Always send full tooltip
// 1 = Wait for client to request full tooltip
TooltipMode=0
// Time to cache tooltip data for (seconds)
//TooltipCacheTime=30
__________________________________
01:44:DEBUG:Receiving new connection
01:44:DEBUG:Retrieving IP history
01:44:DEBUG:Incoming connection from 'IP1' [blocked=0, ttl=174, pings=1, connecting=0, connected=1]
01:44:DEBUG:162:Allocated slot for client (964).
01:44:DEBUG:162:Clearing client state.
01:44:DEBUG:162:initialising client
01:44:162:Client connected [Total:63] ('IP1' 1/2)
01:44:DEBUG:162:determining async mode
01:44:DEBUG:162:Opening network state
01:44:DEBUG:162:State initialised, registering client instance.
01:44:DEBUG:162:Client successfully initialised.
01:44:DEBUG:15c:Client being closed by read-thread
01:44:DEBUG:15c:Flushing data for client.
01:44:DEBUG:15c:Client being closed by read-thread
01:44:DEBUG:162:Receiving old client login handshake.
01:44:DEBUG:15c:Client being closed by write-thread
01:44:DEBUG:162:Client connected with a seed of 0x7f000001 (new handshake=0, seed length=4, received=4, version=0x0)
01:44:162:Login 'account1'
...
01:45:DEBUG:162:Client being closed by read-thread
01:45:DEBUG:162:Flushing data for client.
01:45:DEBUG:162:Flushing data for client.
01:45:DEBUG:162:Flushing data for client.
01:45:DEBUG:162:Flushing data for client.
...
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:160:Client being closed by write-thread
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:160:Client is being cleared since marked to close.
03:29:DEBUG:160:Clearing client state.
03:29:160:Client disconnected [Total:46] ('IP1')
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:162:Flushing data for client.
03:29:DEBUG:Receiving new connection
03:29:DEBUG:Retrieving IP history
03:29:DEBUG:Incoming connection from 'IP1' [blocked=0, ttl=296, pings=3, connecting=0, connected=-1]
03:29:DEBUG:162:Allocated slot for client (952).
03:29:DEBUG:162:Clearing client state.
03:29:162:Client disconnected [Total:45] ('IP1')
03:29:DEBUG:162:initialising client
03:29:162:Client connected [Total:46] ('IP1' 1/0)
03:29:DEBUG:162:determining async mode
03:29:DEBUG:162:Opening network state
03:29:DEBUG:162:State initialised, registering client instance.
03:29:DEBUG:162:Client successfully initialised.
03:29:161:Login 'account2'
03:29:DEBUG:75:Flushing data for client.
03:29:DEBUG:162:Receiving old client login handshake.
03:29:DEBUG:162:Client connected with a seed of 0x7f000001 (new handshake=0, seed length=4, received=4, version=0x0). |
|
|
|
|
It seems strange that it could last so long, it seems that the messages keep being printed until a new client connects and happens to get assigned to the same slot.
I've made a few changes which may have helped, could you see if the problem still exists on the latest automated build (internal build version 1366+)? |
|
|
|
|
The problem seems to continue.
02:30:DEBUG:Receiving new connection
02:30:DEBUG:Retrieving IP history for 'IP1'.
02:30:DEBUG:Incoming connection from 'IP1' [blocked=0, ttl=267, pings=1, connecting=0, connected=-1]
02:30:DEBUG:17b:Allocated slot for client (692).
02:30:DEBUG:17b:Clearing client state.
02:30:DEBUG:17b:Initialising client
02:30:17b:Client connected [Total:51] ('IP1' 1/0)
02:30:DEBUG:17b:Opening network state
02:30:DEBUG:17b:Determining async mode
02:30:DEBUG:17b:State initialised, registering client instance.
02:30:DEBUG:17b:Client successfully initialised.
02:30:DEBUG:17b:Receiving old client login handshake.
02:30:DEBUG:17b:Client connected with a seed of 0x7f000001 (new handshake=0, seed length=4, received=4, version=0x0).
02:30:17b:Login 'acct1'
02:30:DEBUG:Receiving new connection
02:30:DEBUG:Retrieving IP history for 'IP2'.
02:30:DEBUG:Incoming connection from 'IP2' [blocked=0, ttl=300, pings=0, connecting=0, connected=0]
02:30:DEBUG:17c:Allocated slot for client (772).
02:30:DEBUG:17c:Clearing client state.
02:30:DEBUG:17c:Initialising client
02:30:17c:Client connected [Total:52] ('IP2' 1/1)
02:30:DEBUG:17c:Opening network state
02:30:DEBUG:17c:Determining async mode
02:30:DEBUG:17c:State initialised, registering client instance.
02:30:DEBUG:17c:Client successfully initialised.
02:30:DEBUG:17c:Client being closed by read-thread
02:30:DEBUG:17c:Flushing data for client.
02:30:DEBUG:17c:Client being closed by read-thread
02:30:DEBUG:17c:Client being closed by write-thread
02:30:DEBUG:17c:Flushing data for client.
02:30:DEBUG:17c:Client being closed by read-thread
02:30:DEBUG:17c:Client is being cleared since marked to close.
02:30:DEBUG:17c:Clearing client state.
02:30:17c:Client disconnected [Total:51] ('IP2')
02:30:17b:Setup_Start acct='acct1', char='char1', IP='IP1'
02:30:DEBUG:17b:Client being closed by read-thread
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
02:30:DEBUG:17b:Flushing data for client.
...
20:37:DEBUG:64:Flushing data for client.
20:37:DEBUG:17b:Flushing data for client.
20:37:DEBUG:1dd:Flushing data for client.
20:37:DEBUG:64:Flushing data for client. |
|
|
|
|
|
I forgot to mention that the latest changes increased the number of connections that remain open even when user do logout. |
|
|
|
|
|
I think the flushing message being 'spammed' should be cleared up on the latest automated build (internal build version 1379+), please can you check if the problem with the connections remaining open is still present? |
|
|
|
|
|
|
|
|
Well with the revision 1379 the problem was still present (to a lesser extent) and now with the revision 1381 after 40 hours no error.
Good news. Thanks and happy holidays. |
|