VGOEmulator.net

Bug ID       : 76 - VGClient Minimized, corrupts connection 
Bug Date     : 2015/01/07 04:10:48
Assigned To  : Lokked
Priority     : Critical

Category     : VGClient
Sub-Category : Other
Severity     : Severe (e.g. Exploitable)
Reproducible : Some of the time

Details:
Just watched as Cyrcle minimized his client to go to another app, on the world console his client erupted into a frenzy of spammed invalid opcodes and he crashed to Select when he returned. Upon returning, he cannot see any channels, I cannot respond to his Tells (player unknown) and he reports seeing 4-5 New Telon chat channels, none of which worked.

Originated From World: New Telon (1)
Chunk                : Khal (85)
Location             : -1991 -55913 1258

This issue is fairly critical, though it doesn't seem to happen to me at all. Maybe just a WAN thing, or Cyrcle is just lucky but when the VGClient is minimized (from full screen at maybe?) it starts shooting a shit-ton of spam to the world and eventually disconnects the client. Example:

[quote]05:55:48.530 E UDP Received packet with unknown protocol opcode 0x0352 (850) from 85.227.184.191:39050
05:55:48.530 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:49.341 E UDP Received packet with unknown protocol opcode 0x0355 (853) from 85.227.184.191:39050
05:55:49.341 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:50.558 E UDP Received packet with unknown protocol opcode 0x0358 (856) from 85.227.184.191:39050
05:55:52.181 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:52.571 E UDP Received packet with unknown protocol opcode 0x035E (862) from 85.227.184.191:39050
05:55:52.571 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:53.382 E UDP Received packet with unknown protocol opcode 0x0361 (865) from 85.227.184.191:39050
05:55:53.382 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:54.583 E UDP Received packet with unknown protocol opcode 0x0364 (868) from 85.227.184.191:39050
05:55:54.583 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:55.394 E UDP Received packet with unknown protocol opcode 0x0367 (871) from 85.227.184.191:39050
05:55:56.174 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:56.596 E UDP Received packet with unknown protocol opcode 0x036A (874) from 85.227.184.191:39050
05:55:56.596 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:57.407 E UDP Received packet with unknown protocol opcode 0x036D (877) from 85.227.184.191:39050
05:55:57.407 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:58.280 I Chunk Shutdown timer expired. Shutting down Flowing Seas.
05:55:58.624 E UDP Received packet with unknown protocol opcode 0x0370 (880) from 85.227.184.191:39050
05:55:58.624 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:55:59.419 E UDP Received packet with unknown protocol opcode 0x0373 (883) from 85.227.184.191:39050
05:56:01.073 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:01.447 E UDP Received packet with unknown protocol opcode 0x0379 (889) from 85.227.184.191:39050
05:56:01.447 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:02.648 E UDP Received packet with unknown protocol opcode 0x037C (892) from 85.227.184.191:39050
05:56:02.648 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:03.460 E UDP Received packet with unknown protocol opcode 0x037F (895) from 85.227.184.191:39050
05:56:03.460 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:04.661 E UDP Received packet with unknown protocol opcode 0x0382 (898) from 85.227.184.191:39050
05:56:04.661 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:05.472 E UDP Received packet with unknown protocol opcode 0x0385 (901) from 85.227.184.191:39050
05:56:06.751 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:07.094 E UDP Received packet with unknown protocol opcode 0x0389 (905) from 85.227.184.191:39050
05:56:07.094 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:07.094 E UDP Received packet with unknown protocol opcode 0xD2F0 (54000) from 85.227.184.191:39050
05:56:08.701 E UDP Received packet with unknown protocol opcode 0x038E (910) from 85.227.184.191:39050
05:56:08.701 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:09.512 E UDP Received packet with unknown protocol opcode 0x0391 (913) from 85.227.184.191:39050
05:56:09.512 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:10.729 E UDP Received packet with unknown protocol opcode 0x0394 (916) from 85.227.184.191:39050
05:56:12.118 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:13.537 E UDP Received packet with unknown protocol opcode 0x039D (925) from 85.227.184.191:39050
05:56:13.537 E UDP Received packet with unknown protocol opcode 0x0820 (2080) from 85.227.184.191:39050
05:56:14.754 E UDP Received packet with unknown protocol opcode 0x03A0 (928) from 85.227.184.191:39050
05:56:16.969 E UDP Read timed out after 2000 milliseconds! Disconnecting this client to be safe.
05:56:16.985 D Char Character Mackan Set to Offline
05:56:16.985 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.000 D Account Client Created. Total Now: 3
05:56:17.000 I UDP New client connected from 85.227.184.191:39050
05:56:17.375 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.390 D Account Client Created. Total Now: 4
05:56:17.390 I UDP New client connected from 85.227.184.191:39050
05:56:17.390 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.406 D Account Client Created. Total Now: 5
05:56:17.406 I UDP New client connected from 85.227.184.191:39050
05:56:17.406 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.422 D Account Client Created. Total Now: 6
05:56:17.422 I UDP New client connected from 85.227.184.191:39050
05:56:17.422 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.437 D Account Client Created. Total Now: 7
05:56:17.437 I UDP New client connected from 85.227.184.191:39050
05:56:17.437 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.453 D Account Client Created. Total Now: 8
05:56:17.453 I UDP New client connected from 85.227.184.191:39050
05:56:17.453 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.468 D Account Client Created. Total Now: 9
05:56:17.468 I UDP New client connected from 85.227.184.191:39050
05:56:17.468 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.484 D Account Client Created. Total Now: 10
05:56:17.484 I UDP New client connected from 85.227.184.191:39050
05:56:17.484 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.500 D Account Client Created. Total Now: 11
05:56:17.500 I UDP New client connected from 85.227.184.191:39050
05:56:17.500 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.515 D Account Client Created. Total Now: 12
05:56:17.515 I UDP New client connected from 85.227.184.191:39050
05:56:17.515 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.531 D Account Client Created. Total Now: 13
05:56:17.531 I UDP New client connected from 85.227.184.191:39050
05:56:17.531 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:17.546 D Account Client Created. Total Now: 14
05:56:17.546 I UDP New client connected from 85.227.184.191:39050
05:56:17.546 I UDP Client from 85.227.184.191:39050 set to disconnect : Application
05:56:18.295 D Account Character Created. Total Now: 2
05:56:18.295 D Account Character Created. Total Now: 3
05:56:18.295 D Account Character Created. Total Now: 4
05:56:18.295 D Net Sending char data for 'Mackan', New Telon
05:56:18.311 D Net Sending char data for 'Klippan', New Telon
05:56:18.311 D Net Sending char data for 'Sanguine', New Telon
05:56:18.311 D Account Character Destroyed. Total Now: 3
05:56:18.311 D Account Character Destroyed. Total Now: 2
05:56:18.311 D Account Character Destroyed. Total Now: 1
05:56:19.013 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:19.013 D Account Client Destroyed. Total Now: 13
05:56:20.027 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.027 D Account Client Destroyed. Total Now: 12
05:56:20.027 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.027 D Account Client Destroyed. Total Now: 11
05:56:20.027 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.027 D Account Client Destroyed. Total Now: 10
05:56:20.027 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.042 D Account Client Destroyed. Total Now: 9
05:56:20.042 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.042 D Account Client Destroyed. Total Now: 8
05:56:20.042 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.042 D Account Client Destroyed. Total Now: 7
05:56:20.042 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.042 D Account Client Destroyed. Total Now: 6
05:56:20.042 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.042 D Account Client Destroyed. Total Now: 5
05:56:20.042 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.058 D Account Client Destroyed. Total Now: 4
05:56:20.058 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.058 D Account Client Destroyed. Total Now: 3
05:56:20.058 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.058 D Account Client Destroyed. Total Now: 2
05:56:20.058 I UDP Client from 85.227.184.191:39050 has been removed.
05:56:20.058 D Account Client Destroyed. Total Now: 1
[/quote]

Happening multiple times a day now, here's a look at the issue with the console debug (that does not get written to the logs) It is really a mess.

Pretty sure the net result of this is the client exploding and leaving the world.

Edit: Standing in the world with iRogues, he was literally 5' in front of me doing nothing at all but chatting and the console kept going crazy with packet/desync issues. I asked him a few times what he was doing, and he said he was just standing there. I had noticed most times, he would enter the world naked, stand there chatting with me. He'd touch something on his equipment, and I'd see all his stuff. Then it seemed I'd see the console spam right after. Could be coincidence.

Console log, and dumped chat log attached.
Timestamp in the chat log should coincide with the console dump.

So I had 2 more spammy console posts, but with me pooping out so many bug reports I have no idea if I posted them or not Here's the one that happened a little earlier, if it provides any more info;

This was once again a group of players online for extended periods, chatting and everything seemed normal - then BAM. One of them freaks out.
This one however, is most interesting.
This is me, Cyrcle, Moldew and Zarlore (Glaxono) all standing in Vol Tuniel at the ruins, chatting. Zarlore's connection goes wonky
[quote]17:53:13.230 E UDP Received packet with unknown protocol opcode 0x0400 (1024) from 71.100.53.18:58236[/quote]

While he's crapping out:
[quote]17:53:23.214 I UDP Received session request from 71.100.53.18:58236 with connection ID 4255886251[/quote]

Continues to crap out:
[quote]17:53:24.727 E UDP Received packet with unknown protocol opcode 0x0400 (1024) from 71.100.53.18:58236
17:53:24.727 E UDP Received packet with unknown protocol opcode 0x7104 (28932) from 71.100.53.18:58236
17:53:24.727 E UDP Received packet with unknown protocol opcode 0x0372 (882) from 71.100.53.18:58236
17:53:25.476 D Chat [NewTelon] John: someone is about to crash[/quote]

And finally:
[quote]17:53:33.229 E UDP Read timed out after 2000 milliseconds! Disconnecting this client to be safe.
17:53:33.229 I UDP Client from 71.100.53.18:58236 set to disconnect : Application
17:53:33.292 I UDP New client connected from 71.100.53.18:58236
17:53:35.257 I UDP Client from 71.100.53.18:58236 has been removed.[/quote]

Yet, there he was... able to still talk to me:
[quote]17:53:45.132 D Chat [NewTelon] Zarlore: who?
17:54:12.308 D Chat [NewTelon] John: whoeever 71.100.53.18 was
17:54:17.518 D Chat [NewTelon] Zarlore: me
17:54:26.613 D Chat [NewTelon] Zarlore: but stable right now[/quote]

[quote]17:54:42.261 D Chat [NewTelon] John: weird, it shows you got booted.
17:54:44.149 D Chat [NewTelon] Moldew: Zarlore's not in /who list though
17:54:50.592 D Chat [NewTelon] Zarlore: Am I visible to you all?
17:54:55.662 D Chat [NewTelon] Moldew: nope
17:54:56.957 D Chat [NewTelon] John: no i see you.
17:54:59.905 D Chat [NewTelon] Cyrcle: yes
17:55:05.147 D Chat [NewTelon] Moldew: yes I mean
17:55:06.036 D Chat [NewTelon] Cyrcle: move your char?
17:55:21.137 D Chat [NewTelon] Cyrcle: I dont think we can see you moving though
17:55:26.534 D Chat [NewTelon] Zarlore: Yeah. Not in /who but all my cmmands work
17:55:37.260 W Chunk Camp requested from client with character==null
17:55:39.154 D Chat [NewTelon] John: wow.


17:55:43.047 D Char Saving character 'Cyrcle' (43)
17:55:44.286 D Char Saved successful for character 'Cyrcle' (43)
17:55:44.287 D Char Saving character 'John Adams' (1)
17:55:44.335 D Char Saved successful for character 'John Adams' (1)
17:55:44.337 D Char Saving character 'Moldew' (537)
17:55:44.396 D Char Saved successful for character 'Moldew' (537)

^^^ No Zarlore

17:55:46.163 D Chat [NewTelon] Zarlore: naw... /camp failed
17:55:53.634 D Chat [NewTelon] Moldew: can you do a goto?
17:55:58.471 W Chunk Camp requested from client with character==null
17:56:10.379 D Chat [NewTelon] Moldew: need to be in /say mode
17:56:13.913 D Chat [NewTelon] John: Camp requested from client with character==null
17:56:27.650 E Chunk ChunkServer::HandleChatSay: No WorldCharacter object.[/quote]

Also, /who in game shows me and Cyrcle, though I see Zarlore.
[attachment=0]ScreenShot_00177.JPG[/attachment]
This is correct:
clients: shows 3 connected clients (me, cyrcle and glaxono) and characters show all 3 of us in Vol Tuniel, tho /who shows only 2.

Methinks we got much bigger issues with this particular bug than we imagined.


Lokked: What revision should I roll NT back to in order to test if it's a recent change?

I've been minimizing quite often during our session and I haven't been dropped. I now have two screens so it's not quite "minimizing", but instead switching from one monitor to the other with VG in the "background".

One more small bit of info, which may end up being a bug of it's own eventually. I am chatting quite often tonight with these guys in-game trying to get info as I see it in the console; as a result, I am noticing almost a 2 second delay from the time I hit Enter in my chat box until the text goes to the chat system and is displayed. Display in client and World console are at the same time, so the delay is leaving my client and being received by the world.

I am posting this in this topic for now because it's likely World is dealing with a critical mass of packets coming in, which would explain the lag. As far as the in-game Lag Meter though, I am 45FPS and avg 200ms RT. So doesn't seem to laggy far as the client is concerned.

(Cyrcle confirms)

Btw, maybe this is another queuing issue? If so, I'll split it off this topic. Cyrcle and I said something at the same time, it almost seemed to be slow at that moment.

I've been doing some reading on different UDPServer implementations. One common thing that I have not seen is a thread.sleep call. They typically have a thread dedicated to handling packets and never ask it to sleep. It uses more processor power, but here's the caveat to thread.sleep:
Thread Schedulers are OS implementations, but thread scheduling also depends on the hardware architecture. PC architecture general has a minimum thread sleep/wake cycle of 7-10 milliseconds, while Windows (non-server) has around 45-55 ms. This means the UDPServer is potentially only answering packets every ~50ms instead of every 1 ms, as the thread.sleep(1) call would lead you to believe.

The World Server must be receiving all these malformed packets. The Chunk Client remains connected. I wonder if we can re-establish World Connection if it dies and chunk maintains.

I'm going to continue discussion in another thread. This is a bug thread, but I don't think the title is conducive the what's actually happening. I'll update this thread once we work through the (2, I believe) causes.

[quote="John Adams"]Lokked: What revision should I roll NT back to in order to test if it's a recent change?[/quote]

Sorry can't look at exactly which. I commented 1 line in UDPServer where the switch is that processes packets based on OpCode. The Default: has a BeginDisconnectFromServer that I'd commented out. This will revert to just having them disconnected when they send a wonky packet.