0001843: Many debug messages about flushing data for client.

Notes
(0000720) Mirravin (reporter) 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.

(0000724) MrSugarCube (administrator) 25-10-10 17:41	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).

(0000725) Mirravin (reporter) 25-10-10 17:54	I only found logs and don't have information about other problems caused by this.

(0000726) Terrikate (developer) 25-10-10 18:36	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?

(0000728) MrSugarCube (administrator) 27-10-10 14:25	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 (reporter) 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.

(0000732) Terrikate (developer) 28-10-10 01:17	// 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).

(0000742) MrSugarCube (administrator) 04-11-10 12:03	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+)?

(0000750) Terrikate (developer) 05-11-10 20:35	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.

(0000766) Terrikate (developer) 21-11-10 16:39	I forgot to mention that the latest changes increased the number of connections that remain open even when user do logout.

(0000788) MrSugarCube (administrator) 21-12-10 03:45	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?

(0000793) Terrikate (developer) 23-12-10 01:58	Testing...

(0000800) Terrikate (developer) 25-12-10 17:22	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.

Issue History
Date Modified	Username	Field	Change
25-10-10 00:29	Terrikate	New Issue
25-10-10 02:28	Mirravin	Note Added: 0000720
25-10-10 02:29	Mirravin	Note Edited: 0000720	View Revisions
25-10-10 17:41	MrSugarCube	Note Added: 0000724
25-10-10 17:54	Mirravin	Note Added: 0000725
25-10-10 18:36	Terrikate	Note Added: 0000726
27-10-10 14:25	MrSugarCube	Note Added: 0000728
27-10-10 15:08	Mirravin	Note Added: 0000729
27-10-10 15:09	Mirravin	Note Edited: 0000729	View Revisions
27-10-10 15:11	Mirravin	Note Edited: 0000729	View Revisions
27-10-10 15:15	Mirravin	Note Edited: 0000729	View Revisions
27-10-10 15:16	Mirravin	Note Edited: 0000729	View Revisions
28-10-10 01:17	Terrikate	Note Added: 0000732
04-11-10 12:03	MrSugarCube	Note Added: 0000742
05-11-10 20:35	Terrikate	Note Added: 0000750
21-11-10 16:39	Terrikate	Note Added: 0000766
21-12-10 03:45	MrSugarCube	Note Added: 0000788
23-12-10 01:58	Terrikate	Note Added: 0000793
25-12-10 17:22	Terrikate	Note Added: 0000800
02-01-11 01:38	MrSugarCube	Status	new => resolved
02-01-11 01:38	MrSugarCube	Fixed in Version	=> 0.56c Nightly
02-01-11 01:38	MrSugarCube	Resolution	open => fixed
02-01-11 01:38	MrSugarCube	Assigned To	=> MrSugarCube

Relationships