opensim-development – Blame information for rev 1

Subversion Repositories:
Rev:
Rev Author Line No. Line
1 eva 1 /*
2 * Copyright (c) Contributors, http://opensimulator.org/
3 * See CONTRIBUTORS.TXT for a full list of copyright holders.
4 *
5 * Redistribution and use in source and binary forms, with or without
6 * modification, are permitted provided that the following conditions are met:
7 * * Redistributions of source code must retain the above copyright
8 * notice, this list of conditions and the following disclaimer.
9 * * Redistributions in binary form must reproduce the above copyright
10 * notice, this list of conditions and the following disclaimer in the
11 * documentation and/or other materials provided with the distribution.
12 * * Neither the name of the OpenSimulator Project nor the
13 * names of its contributors may be used to endorse or promote products
14 * derived from this software without specific prior written permission.
15 *
16 * THIS SOFTWARE IS PROVIDED BY THE DEVELOPERS ``AS IS'' AND ANY
17 * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
18 * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
19 * DISCLAIMED. IN NO EVENT SHALL THE CONTRIBUTORS BE LIABLE FOR ANY
20 * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
21 * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
22 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
23 * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
24 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
25 * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
26 */
27  
28 using System;
29 using System.Collections.Generic;
30 using System.Diagnostics;
31 using System.IO;
32 using System.Net;
33 using System.Net.Sockets;
34 using System.Reflection;
35 using System.Threading;
36 using log4net;
37 using NDesk.Options;
38 using Nini.Config;
39 using OpenMetaverse.Packets;
40 using OpenSim.Framework;
41 using OpenSim.Framework.Console;
42 using OpenSim.Framework.Monitoring;
43 using OpenSim.Region.Framework.Scenes;
44 using OpenMetaverse;
45  
46 using TokenBucket = OpenSim.Region.ClientStack.LindenUDP.TokenBucket;
47  
48 namespace OpenSim.Region.ClientStack.LindenUDP
49 {
50 /// <summary>
51 /// A shim around LLUDPServer that implements the IClientNetworkServer interface
52 /// </summary>
53 public sealed class LLUDPServerShim : IClientNetworkServer
54 {
55 LLUDPServer m_udpServer;
56  
57 public LLUDPServerShim()
58 {
59 }
60  
61 public void Initialise(IPAddress listenIP, ref uint port, int proxyPortOffsetParm, bool allow_alternate_port, IConfigSource configSource, AgentCircuitManager circuitManager)
62 {
63 m_udpServer = new LLUDPServer(listenIP, ref port, proxyPortOffsetParm, allow_alternate_port, configSource, circuitManager);
64 }
65  
66 public void AddScene(IScene scene)
67 {
68 m_udpServer.AddScene(scene);
69  
70 StatsManager.RegisterStat(
71 new Stat(
72 "ClientLogoutsDueToNoReceives",
73 "Number of times a client has been logged out because no packets were received before the timeout.",
74 "",
75 "",
76 "clientstack",
77 scene.Name,
78 StatType.Pull,
79 MeasuresOfInterest.None,
80 stat => stat.Value = m_udpServer.ClientLogoutsDueToNoReceives,
81 StatVerbosity.Debug));
82  
83 StatsManager.RegisterStat(
84 new Stat(
85 "IncomingUDPReceivesCount",
86 "Number of UDP receives performed",
87 "",
88 "",
89 "clientstack",
90 scene.Name,
91 StatType.Pull,
92 MeasuresOfInterest.AverageChangeOverTime,
93 stat => stat.Value = m_udpServer.UdpReceives,
94 StatVerbosity.Debug));
95  
96 StatsManager.RegisterStat(
97 new Stat(
98 "IncomingPacketsProcessedCount",
99 "Number of inbound LL protocol packets processed",
100 "",
101 "",
102 "clientstack",
103 scene.Name,
104 StatType.Pull,
105 MeasuresOfInterest.AverageChangeOverTime,
106 stat => stat.Value = m_udpServer.IncomingPacketsProcessed,
107 StatVerbosity.Debug));
108  
109 StatsManager.RegisterStat(
110 new Stat(
111 "IncomingPacketsMalformedCount",
112 "Number of inbound UDP packets that could not be recognized as LL protocol packets.",
113 "",
114 "",
115 "clientstack",
116 scene.Name,
117 StatType.Pull,
118 MeasuresOfInterest.AverageChangeOverTime,
119 stat => stat.Value = m_udpServer.IncomingMalformedPacketCount,
120 StatVerbosity.Info));
121  
122 StatsManager.RegisterStat(
123 new Stat(
124 "IncomingPacketsOrphanedCount",
125 "Number of inbound packets that were not initial connections packets and could not be associated with a viewer.",
126 "",
127 "",
128 "clientstack",
129 scene.Name,
130 StatType.Pull,
131 MeasuresOfInterest.AverageChangeOverTime,
132 stat => stat.Value = m_udpServer.IncomingOrphanedPacketCount,
133 StatVerbosity.Info));
134  
135 StatsManager.RegisterStat(
136 new Stat(
137 "IncomingPacketsResentCount",
138 "Number of inbound packets that clients indicate are resends.",
139 "",
140 "",
141 "clientstack",
142 scene.Name,
143 StatType.Pull,
144 MeasuresOfInterest.AverageChangeOverTime,
145 stat => stat.Value = m_udpServer.IncomingPacketsResentCount,
146 StatVerbosity.Debug));
147  
148 StatsManager.RegisterStat(
149 new Stat(
150 "OutgoingUDPSendsCount",
151 "Number of UDP sends performed",
152 "",
153 "",
154 "clientstack",
155 scene.Name,
156 StatType.Pull,
157 MeasuresOfInterest.AverageChangeOverTime,
158 stat => stat.Value = m_udpServer.UdpSends,
159 StatVerbosity.Debug));
160  
161 StatsManager.RegisterStat(
162 new Stat(
163 "OutgoingPacketsResentCount",
164 "Number of packets resent because a client did not acknowledge receipt",
165 "",
166 "",
167 "clientstack",
168 scene.Name,
169 StatType.Pull,
170 MeasuresOfInterest.AverageChangeOverTime,
171 stat => stat.Value = m_udpServer.PacketsResentCount,
172 StatVerbosity.Debug));
173  
174 StatsManager.RegisterStat(
175 new Stat(
176 "AverageUDPProcessTime",
177 "Average number of milliseconds taken to process each incoming UDP packet in a sample.",
178 "This is for initial receive processing which is separate from the later client LL packet processing stage.",
179 "ms",
180 "clientstack",
181 scene.Name,
182 StatType.Pull,
183 MeasuresOfInterest.None,
184 stat => stat.Value = m_udpServer.AverageReceiveTicksForLastSamplePeriod / TimeSpan.TicksPerMillisecond,
185 // stat =>
186 // stat.Value = Math.Round(m_udpServer.AverageReceiveTicksForLastSamplePeriod / TimeSpan.TicksPerMillisecond, 7),
187 StatVerbosity.Debug));
188 }
189  
190 public bool HandlesRegion(Location x)
191 {
192 return m_udpServer.HandlesRegion(x);
193 }
194  
195 public void Start()
196 {
197 m_udpServer.Start();
198 }
199  
200 public void Stop()
201 {
202 m_udpServer.Stop();
203 }
204 }
205  
206 /// <summary>
207 /// The LLUDP server for a region. This handles incoming and outgoing
208 /// packets for all UDP connections to the region
209 /// </summary>
210 public class LLUDPServer : OpenSimUDPBase
211 {
212 private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
213  
214 /// <summary>Maximum transmission unit, or UDP packet size, for the LLUDP protocol</summary>
215 public const int MTU = 1400;
216  
217 /// <summary>Number of forced client logouts due to no receipt of packets before timeout.</summary>
218 public int ClientLogoutsDueToNoReceives { get; private set; }
219  
220 /// <summary>
221 /// Default packet debug level given to new clients
222 /// </summary>
223 public int DefaultClientPacketDebugLevel { get; set; }
224  
225 /// <summary>The measured resolution of Environment.TickCount</summary>
226 public readonly float TickCountResolution;
227  
228 /// <summary>Number of prim updates to put on the queue each time the
229 /// OnQueueEmpty event is triggered for updates</summary>
230 public readonly int PrimUpdatesPerCallback;
231  
232 /// <summary>Number of texture packets to put on the queue each time the
233 /// OnQueueEmpty event is triggered for textures</summary>
234 public readonly int TextureSendLimit;
235  
236 /// <summary>Handlers for incoming packets</summary>
237 //PacketEventDictionary packetEvents = new PacketEventDictionary();
238 /// <summary>Incoming packets that are awaiting handling</summary>
239 private OpenMetaverse.BlockingQueue<IncomingPacket> packetInbox = new OpenMetaverse.BlockingQueue<IncomingPacket>();
240  
241 /// <summary></summary>
242 //private UDPClientCollection m_clients = new UDPClientCollection();
243 /// <summary>Bandwidth throttle for this UDP server</summary>
244 protected TokenBucket m_throttle;
245  
246 /// <summary>Bandwidth throttle rates for this UDP server</summary>
247 public ThrottleRates ThrottleRates { get; private set; }
248  
249 /// <summary>Manages authentication for agent circuits</summary>
250 private AgentCircuitManager m_circuitManager;
251  
252 /// <summary>Reference to the scene this UDP server is attached to</summary>
253 protected Scene m_scene;
254  
255 /// <summary>The X/Y coordinates of the scene this UDP server is attached to</summary>
256 private Location m_location;
257  
258 /// <summary>The size of the receive buffer for the UDP socket. This value
259 /// is passed up to the operating system and used in the system networking
260 /// stack. Use zero to leave this value as the default</summary>
261 private int m_recvBufferSize;
262  
263 /// <summary>Flag to process packets asynchronously or synchronously</summary>
264 private bool m_asyncPacketHandling;
265  
266 /// <summary>Tracks whether or not a packet was sent each round so we know
267 /// whether or not to sleep</summary>
268 private bool m_packetSent;
269  
270 /// <summary>Environment.TickCount of the last time that packet stats were reported to the scene</summary>
271 private int m_elapsedMSSinceLastStatReport = 0;
272  
273 /// <summary>Environment.TickCount of the last time the outgoing packet handler executed</summary>
274 private int m_tickLastOutgoingPacketHandler;
275  
276 /// <summary>Keeps track of the number of elapsed milliseconds since the last time the outgoing packet handler looped</summary>
277 private int m_elapsedMSOutgoingPacketHandler;
278  
279 /// <summary>Keeps track of the number of 100 millisecond periods elapsed in the outgoing packet handler executed</summary>
280 private int m_elapsed100MSOutgoingPacketHandler;
281  
282 /// <summary>Keeps track of the number of 500 millisecond periods elapsed in the outgoing packet handler executed</summary>
283 private int m_elapsed500MSOutgoingPacketHandler;
284  
285 /// <summary>Flag to signal when clients should check for resends</summary>
286 protected bool m_resendUnacked;
287  
288 /// <summary>Flag to signal when clients should send ACKs</summary>
289 protected bool m_sendAcks;
290  
291 /// <summary>Flag to signal when clients should send pings</summary>
292 protected bool m_sendPing;
293  
294 /// <summary>
295 /// Event used to signal when queued packets are available for sending.
296 /// </summary>
297 /// <remarks>
298 /// This allows the outbound loop to only operate when there is data to send rather than continuously polling.
299 /// Some data is sent immediately and not queued. That data would not trigger this event.
300 /// </remarks>
301 private AutoResetEvent m_dataPresentEvent = new AutoResetEvent(false);
302  
303 private Pool<IncomingPacket> m_incomingPacketPool;
304  
305 /// <summary>
306 /// Stat for number of packets in the main pool awaiting use.
307 /// </summary>
308 private Stat m_poolCountStat;
309  
310 /// <summary>
311 /// Stat for number of packets in the inbound packet pool awaiting use.
312 /// </summary>
313 private Stat m_incomingPacketPoolStat;
314  
315 private int m_defaultRTO = 0;
316 private int m_maxRTO = 0;
317 private int m_ackTimeout = 0;
318 private int m_pausedAckTimeout = 0;
319 private bool m_disableFacelights = false;
320  
321 public Socket Server { get { return null; } }
322  
323 /// <summary>
324 /// Record how many packets have been resent
325 /// </summary>
326 internal int PacketsResentCount { get; set; }
327  
328 /// <summary>
329 /// Record how many packets have been sent
330 /// </summary>
331 internal int PacketsSentCount { get; set; }
332  
333 /// <summary>
334 /// Record how many incoming packets are indicated as resends by clients.
335 /// </summary>
336 internal int IncomingPacketsResentCount { get; set; }
337  
338 /// <summary>
339 /// Record how many inbound packets could not be recognized as LLUDP packets.
340 /// </summary>
341 public int IncomingMalformedPacketCount { get; private set; }
342  
343 /// <summary>
344 /// Record how many inbound packets could not be associated with a simulator circuit.
345 /// </summary>
346 public int IncomingOrphanedPacketCount { get; private set; }
347  
348 /// <summary>
349 /// Record current outgoing client for monitoring purposes.
350 /// </summary>
351 private IClientAPI m_currentOutgoingClient;
352  
353 /// <summary>
354 /// Recording current incoming client for monitoring purposes.
355 /// </summary>
356 private IClientAPI m_currentIncomingClient;
357  
358 public LLUDPServer(
359 IPAddress listenIP, ref uint port, int proxyPortOffsetParm, bool allow_alternate_port,
360 IConfigSource configSource, AgentCircuitManager circuitManager)
361 : base(listenIP, (int)port)
362 {
363 #region Environment.TickCount Measurement
364  
365 // Measure the resolution of Environment.TickCount
366 TickCountResolution = 0f;
367 for (int i = 0; i < 5; i++)
368 {
369 int start = Environment.TickCount;
370 int now = start;
371 while (now == start)
372 now = Environment.TickCount;
373 TickCountResolution += (float)(now - start) * 0.2f;
374 }
375 m_log.Info("[LLUDPSERVER]: Average Environment.TickCount resolution: " + TickCountResolution + "ms");
376 TickCountResolution = (float)Math.Ceiling(TickCountResolution);
377  
378 #endregion Environment.TickCount Measurement
379  
380 m_circuitManager = circuitManager;
381 int sceneThrottleBps = 0;
382 bool usePools = false;
383  
384 IConfig config = configSource.Configs["ClientStack.LindenUDP"];
385 if (config != null)
386 {
387 m_asyncPacketHandling = config.GetBoolean("async_packet_handling", true);
388 m_recvBufferSize = config.GetInt("client_socket_rcvbuf_size", 0);
389 sceneThrottleBps = config.GetInt("scene_throttle_max_bps", 0);
390  
391 PrimUpdatesPerCallback = config.GetInt("PrimUpdatesPerCallback", 100);
392 TextureSendLimit = config.GetInt("TextureSendLimit", 20);
393  
394 m_defaultRTO = config.GetInt("DefaultRTO", 0);
395 m_maxRTO = config.GetInt("MaxRTO", 0);
396 m_disableFacelights = config.GetBoolean("DisableFacelights", false);
397 m_ackTimeout = 1000 * config.GetInt("AckTimeout", 60);
398 m_pausedAckTimeout = 1000 * config.GetInt("PausedAckTimeout", 300);
399 }
400 else
401 {
402 PrimUpdatesPerCallback = 100;
403 TextureSendLimit = 20;
404 m_ackTimeout = 1000 * 60; // 1 minute
405 m_pausedAckTimeout = 1000 * 300; // 5 minutes
406 }
407  
408 // FIXME: This actually only needs to be done once since the PacketPool is shared across all servers.
409 // However, there is no harm in temporarily doing it multiple times.
410 IConfig packetConfig = configSource.Configs["PacketPool"];
411 if (packetConfig != null)
412 {
413 PacketPool.Instance.RecyclePackets = packetConfig.GetBoolean("RecyclePackets", true);
414 PacketPool.Instance.RecycleDataBlocks = packetConfig.GetBoolean("RecycleDataBlocks", true);
415 usePools = packetConfig.GetBoolean("RecycleBaseUDPPackets", usePools);
416 }
417  
418 #region BinaryStats
419 config = configSource.Configs["Statistics.Binary"];
420 m_shouldCollectStats = false;
421 if (config != null)
422 {
423 m_shouldCollectStats = config.GetBoolean("Enabled", false);
424 binStatsMaxFilesize = TimeSpan.FromSeconds(config.GetInt("packet_headers_period_seconds", 300));
425 binStatsDir = config.GetString("stats_dir", ".");
426 m_aggregatedBWStats = config.GetBoolean("aggregatedBWStats", false);
427 }
428 #endregion BinaryStats
429  
430 m_throttle = new TokenBucket(null, sceneThrottleBps);
431 ThrottleRates = new ThrottleRates(configSource);
432  
433 if (usePools)
434 EnablePools();
435 }
436  
437 public void Start()
438 {
439 StartInbound();
440 StartOutbound();
441  
442 m_elapsedMSSinceLastStatReport = Environment.TickCount;
443 }
444  
445 private void StartInbound()
446 {
447 m_log.InfoFormat(
448 "[LLUDPSERVER]: Starting inbound packet processing for the LLUDP server in {0} mode with UsePools = {1}",
449 m_asyncPacketHandling ? "asynchronous" : "synchronous", UsePools);
450  
451 base.StartInbound(m_recvBufferSize, m_asyncPacketHandling);
452  
453 // This thread will process the packets received that are placed on the packetInbox
454 Watchdog.StartThread(
455 IncomingPacketHandler,
456 string.Format("Incoming Packets ({0})", m_scene.RegionInfo.RegionName),
457 ThreadPriority.Normal,
458 false,
459 true,
460 GetWatchdogIncomingAlarmData,
461 Watchdog.DEFAULT_WATCHDOG_TIMEOUT_MS);
462 }
463  
464 private new void StartOutbound()
465 {
466 m_log.Info("[LLUDPSERVER]: Starting outbound packet processing for the LLUDP server");
467  
468 base.StartOutbound();
469  
470 Watchdog.StartThread(
471 OutgoingPacketHandler,
472 string.Format("Outgoing Packets ({0})", m_scene.RegionInfo.RegionName),
473 ThreadPriority.Normal,
474 false,
475 true,
476 GetWatchdogOutgoingAlarmData,
477 Watchdog.DEFAULT_WATCHDOG_TIMEOUT_MS);
478 }
479  
480 public void Stop()
481 {
482 m_log.Info("[LLUDPSERVER]: Shutting down the LLUDP server for " + m_scene.RegionInfo.RegionName);
483 base.StopOutbound();
484 base.StopInbound();
485 }
486  
487 protected override bool EnablePools()
488 {
489 if (!UsePools)
490 {
491 base.EnablePools();
492  
493 m_incomingPacketPool = new Pool<IncomingPacket>(() => new IncomingPacket(), 500);
494  
495 return true;
496 }
497  
498 return false;
499 }
500  
501 protected override bool DisablePools()
502 {
503 if (UsePools)
504 {
505 base.DisablePools();
506  
507 StatsManager.DeregisterStat(m_incomingPacketPoolStat);
508  
509 // We won't null out the pool to avoid a race condition with code that may be in the middle of using it.
510  
511 return true;
512 }
513  
514 return false;
515 }
516  
517 /// <summary>
518 /// This is a seperate method so that it can be called once we have an m_scene to distinguish different scene
519 /// stats.
520 /// </summary>
521 private void EnablePoolStats()
522 {
523 m_poolCountStat
524 = new Stat(
525 "UDPPacketBufferPoolCount",
526 "Objects within the UDPPacketBuffer pool",
527 "The number of objects currently stored within the UDPPacketBuffer pool",
528 "",
529 "clientstack",
530 m_scene.Name,
531 StatType.Pull,
532 stat => stat.Value = Pool.Count,
533 StatVerbosity.Debug);
534  
535 StatsManager.RegisterStat(m_poolCountStat);
536  
537 m_incomingPacketPoolStat
538 = new Stat(
539 "IncomingPacketPoolCount",
540 "Objects within incoming packet pool",
541 "The number of objects currently stored within the incoming packet pool",
542 "",
543 "clientstack",
544 m_scene.Name,
545 StatType.Pull,
546 stat => stat.Value = m_incomingPacketPool.Count,
547 StatVerbosity.Debug);
548  
549 StatsManager.RegisterStat(m_incomingPacketPoolStat);
550 }
551  
552 /// <summary>
553 /// Disables pool stats.
554 /// </summary>
555 private void DisablePoolStats()
556 {
557 StatsManager.DeregisterStat(m_poolCountStat);
558 m_poolCountStat = null;
559  
560 StatsManager.DeregisterStat(m_incomingPacketPoolStat);
561 m_incomingPacketPoolStat = null;
562 }
563  
564 /// <summary>
565 /// If the outgoing UDP thread times out, then return client that was being processed to help with debugging.
566 /// </summary>
567 /// <returns></returns>
568 private string GetWatchdogIncomingAlarmData()
569 {
570 return string.Format(
571 "Client is {0}",
572 m_currentIncomingClient != null ? m_currentIncomingClient.Name : "none");
573 }
574  
575 /// <summary>
576 /// If the outgoing UDP thread times out, then return client that was being processed to help with debugging.
577 /// </summary>
578 /// <returns></returns>
579 private string GetWatchdogOutgoingAlarmData()
580 {
581 return string.Format(
582 "Client is {0}",
583 m_currentOutgoingClient != null ? m_currentOutgoingClient.Name : "none");
584 }
585  
586 public void AddScene(IScene scene)
587 {
588 if (m_scene != null)
589 {
590 m_log.Error("[LLUDPSERVER]: AddScene() called on an LLUDPServer that already has a scene");
591 return;
592 }
593  
594 if (!(scene is Scene))
595 {
596 m_log.Error("[LLUDPSERVER]: AddScene() called with an unrecognized scene type " + scene.GetType());
597 return;
598 }
599  
600 m_scene = (Scene)scene;
601 m_location = new Location(m_scene.RegionInfo.RegionHandle);
602  
603 StatsManager.RegisterStat(
604 new Stat(
605 "InboxPacketsCount",
606 "Number of LL protocol packets waiting for the second stage of processing after initial receive.",
607 "Number of LL protocol packets waiting for the second stage of processing after initial receive.",
608 "",
609 "clientstack",
610 scene.Name,
611 StatType.Pull,
612 MeasuresOfInterest.AverageChangeOverTime,
613 stat => stat.Value = packetInbox.Count,
614 StatVerbosity.Debug));
615  
616 // XXX: These stats are also pool stats but we register them separately since they are currently not
617 // turned on and off by EnablePools()/DisablePools()
618 StatsManager.RegisterStat(
619 new PercentageStat(
620 "PacketsReused",
621 "Packets reused",
622 "Number of packets reused out of all requests to the packet pool",
623 "clientstack",
624 m_scene.Name,
625 StatType.Pull,
626 stat =>
627 { PercentageStat pstat = (PercentageStat)stat;
628 pstat.Consequent = PacketPool.Instance.PacketsRequested;
629 pstat.Antecedent = PacketPool.Instance.PacketsReused; },
630 StatVerbosity.Debug));
631  
632 StatsManager.RegisterStat(
633 new PercentageStat(
634 "PacketDataBlocksReused",
635 "Packet data blocks reused",
636 "Number of data blocks reused out of all requests to the packet pool",
637 "clientstack",
638 m_scene.Name,
639 StatType.Pull,
640 stat =>
641 { PercentageStat pstat = (PercentageStat)stat;
642 pstat.Consequent = PacketPool.Instance.BlocksRequested;
643 pstat.Antecedent = PacketPool.Instance.BlocksReused; },
644 StatVerbosity.Debug));
645  
646 StatsManager.RegisterStat(
647 new Stat(
648 "PacketsPoolCount",
649 "Objects within the packet pool",
650 "The number of objects currently stored within the packet pool",
651 "",
652 "clientstack",
653 m_scene.Name,
654 StatType.Pull,
655 stat => stat.Value = PacketPool.Instance.PacketsPooled,
656 StatVerbosity.Debug));
657  
658 StatsManager.RegisterStat(
659 new Stat(
660 "PacketDataBlocksPoolCount",
661 "Objects within the packet data block pool",
662 "The number of objects currently stored within the packet data block pool",
663 "",
664 "clientstack",
665 m_scene.Name,
666 StatType.Pull,
667 stat => stat.Value = PacketPool.Instance.BlocksPooled,
668 StatVerbosity.Debug));
669  
670 // We delay enabling pool stats to AddScene() instead of Initialize() so that we can distinguish pool stats by
671 // scene name
672 if (UsePools)
673 EnablePoolStats();
674  
675 MainConsole.Instance.Commands.AddCommand(
676 "Debug", false, "debug lludp packet",
677 "debug lludp packet [--default] <level> [<avatar-first-name> <avatar-last-name>]",
678 "Turn on packet debugging",
679 "If level > 255 then all incoming and outgoing packets are logged.\n"
680 + "If level <= 255 then incoming AgentUpdate and outgoing SimStats and SimulatorViewerTimeMessage packets are not logged.\n"
681 + "If level <= 200 then incoming RequestImage and outgoing ImagePacket, ImageData, LayerData and CoarseLocationUpdate packets are not logged.\n"
682 + "If level <= 100 then incoming ViewerEffect and AgentAnimation and outgoing ViewerEffect and AvatarAnimation packets are not logged.\n"
683 + "If level <= 50 then outgoing ImprovedTerseObjectUpdate packets are not logged.\n"
684 + "If level <= 0 then no packets are logged.\n"
685 + "If --default is specified then the level becomes the default logging level for all subsequent agents.\n"
686 + "In this case, you cannot also specify an avatar name.\n"
687 + "If an avatar name is given then only packets from that avatar are logged.",
688 HandlePacketCommand);
689  
690 MainConsole.Instance.Commands.AddCommand(
691 "Debug",
692 false,
693 "debug lludp start",
694 "debug lludp start <in|out|all>",
695 "Control LLUDP packet processing.",
696 "No effect if packet processing has already started.\n"
697 + "in - start inbound processing.\n"
698 + "out - start outbound processing.\n"
699 + "all - start in and outbound processing.\n",
700 HandleStartCommand);
701  
702 MainConsole.Instance.Commands.AddCommand(
703 "Debug",
704 false,
705 "debug lludp stop",
706 "debug lludp stop <in|out|all>",
707 "Stop LLUDP packet processing.",
708 "No effect if packet processing has already stopped.\n"
709 + "in - stop inbound processing.\n"
710 + "out - stop outbound processing.\n"
711 + "all - stop in and outbound processing.\n",
712 HandleStopCommand);
713  
714 MainConsole.Instance.Commands.AddCommand(
715 "Debug",
716 false,
717 "debug lludp pool",
718 "debug lludp pool <on|off>",
719 "Turn object pooling within the lludp component on or off.",
720 HandlePoolCommand);
721  
722 MainConsole.Instance.Commands.AddCommand(
723 "Debug",
724 false,
725 "debug lludp status",
726 "debug lludp status",
727 "Return status of LLUDP packet processing.",
728 HandleStatusCommand);
729  
730 MainConsole.Instance.Commands.AddCommand(
731 "Debug",
732 false,
733 "debug lludp toggle agentupdate",
734 "debug lludp toggle agentupdate",
735 "Toggle whether agentupdate packets are processed or simply discarded.",
736 HandleAgentUpdateCommand);
737 }
738  
739 private void HandlePacketCommand(string module, string[] args)
740 {
741 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
742 return;
743  
744 bool setAsDefaultLevel = false;
745 OptionSet optionSet = new OptionSet().Add("default", o => setAsDefaultLevel = o != null);
746 List<string> filteredArgs = optionSet.Parse(args);
747  
748 string name = null;
749  
750 if (filteredArgs.Count == 6)
751 {
752 if (!setAsDefaultLevel)
753 {
754 name = string.Format("{0} {1}", filteredArgs[4], filteredArgs[5]);
755 }
756 else
757 {
758 MainConsole.Instance.OutputFormat("ERROR: Cannot specify a user name when setting default logging level");
759 return;
760 }
761 }
762  
763 if (filteredArgs.Count > 3)
764 {
765 int newDebug;
766 if (int.TryParse(filteredArgs[3], out newDebug))
767 {
768 if (setAsDefaultLevel)
769 {
770 DefaultClientPacketDebugLevel = newDebug;
771 MainConsole.Instance.OutputFormat(
772 "Debug packet debug for new clients set to {0} in {1}", DefaultClientPacketDebugLevel, m_scene.Name);
773 }
774 else
775 {
776 m_scene.ForEachScenePresence(sp =>
777 {
778 if (name == null || sp.Name == name)
779 {
780 MainConsole.Instance.OutputFormat(
781 "Packet debug for {0} ({1}) set to {2} in {3}",
782 sp.Name, sp.IsChildAgent ? "child" : "root", newDebug, m_scene.Name);
783  
784 sp.ControllingClient.DebugPacketLevel = newDebug;
785 }
786 });
787 }
788 }
789 else
790 {
791 MainConsole.Instance.Output("Usage: debug lludp packet [--default] 0..255 [<first-name> <last-name>]");
792 }
793 }
794 }
795  
796 private void HandleStartCommand(string module, string[] args)
797 {
798 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
799 return;
800  
801 if (args.Length != 4)
802 {
803 MainConsole.Instance.Output("Usage: debug lludp start <in|out|all>");
804 return;
805 }
806  
807 string subCommand = args[3];
808  
809 if (subCommand == "in" || subCommand == "all")
810 StartInbound();
811  
812 if (subCommand == "out" || subCommand == "all")
813 StartOutbound();
814 }
815  
816 private void HandleStopCommand(string module, string[] args)
817 {
818 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
819 return;
820  
821 if (args.Length != 4)
822 {
823 MainConsole.Instance.Output("Usage: debug lludp stop <in|out|all>");
824 return;
825 }
826  
827 string subCommand = args[3];
828  
829 if (subCommand == "in" || subCommand == "all")
830 StopInbound();
831  
832 if (subCommand == "out" || subCommand == "all")
833 StopOutbound();
834 }
835  
836 private void HandlePoolCommand(string module, string[] args)
837 {
838 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
839 return;
840  
841 if (args.Length != 4)
842 {
843 MainConsole.Instance.Output("Usage: debug lludp pool <on|off>");
844 return;
845 }
846  
847 string enabled = args[3];
848  
849 if (enabled == "on")
850 {
851 if (EnablePools())
852 {
853 EnablePoolStats();
854 MainConsole.Instance.OutputFormat("Packet pools enabled on {0}", m_scene.Name);
855 }
856 }
857 else if (enabled == "off")
858 {
859 if (DisablePools())
860 {
861 DisablePoolStats();
862 MainConsole.Instance.OutputFormat("Packet pools disabled on {0}", m_scene.Name);
863 }
864 }
865 else
866 {
867 MainConsole.Instance.Output("Usage: debug lludp pool <on|off>");
868 }
869 }
870  
871 bool m_discardAgentUpdates;
872  
873 private void HandleAgentUpdateCommand(string module, string[] args)
874 {
875 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
876 return;
877  
878 m_discardAgentUpdates = !m_discardAgentUpdates;
879  
880 MainConsole.Instance.OutputFormat(
881 "Discard AgentUpdates now {0} for {1}", m_discardAgentUpdates, m_scene.Name);
882 }
883  
884 private void HandleStatusCommand(string module, string[] args)
885 {
886 if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_scene)
887 return;
888  
889 MainConsole.Instance.OutputFormat(
890 "IN LLUDP packet processing for {0} is {1}", m_scene.Name, IsRunningInbound ? "enabled" : "disabled");
891  
892 MainConsole.Instance.OutputFormat(
893 "OUT LLUDP packet processing for {0} is {1}", m_scene.Name, IsRunningOutbound ? "enabled" : "disabled");
894  
895 MainConsole.Instance.OutputFormat("LLUDP pools in {0} are {1}", m_scene.Name, UsePools ? "on" : "off");
896  
897 MainConsole.Instance.OutputFormat(
898 "Packet debug level for new clients is {0}", DefaultClientPacketDebugLevel);
899 }
900  
901 public bool HandlesRegion(Location x)
902 {
903 return x == m_location;
904 }
905  
906 // public void BroadcastPacket(Packet packet, ThrottleOutPacketType category, bool sendToPausedAgents, bool allowSplitting)
907 // {
908 // // CoarseLocationUpdate and AvatarGroupsReply packets cannot be split in an automated way
909 // if ((packet.Type == PacketType.CoarseLocationUpdate || packet.Type == PacketType.AvatarGroupsReply) && allowSplitting)
910 // allowSplitting = false;
911 //
912 // if (allowSplitting && packet.HasVariableBlocks)
913 // {
914 // byte[][] datas = packet.ToBytesMultiple();
915 // int packetCount = datas.Length;
916 //
917 // if (packetCount < 1)
918 // m_log.Error("[LLUDPSERVER]: Failed to split " + packet.Type + " with estimated length " + packet.Length);
919 //
920 // for (int i = 0; i < packetCount; i++)
921 // {
922 // byte[] data = datas[i];
923 // m_scene.ForEachClient(
924 // delegate(IClientAPI client)
925 // {
926 // if (client is LLClientView)
927 // SendPacketData(((LLClientView)client).UDPClient, data, packet.Type, category, null);
928 // }
929 // );
930 // }
931 // }
932 // else
933 // {
934 // byte[] data = packet.ToBytes();
935 // m_scene.ForEachClient(
936 // delegate(IClientAPI client)
937 // {
938 // if (client is LLClientView)
939 // SendPacketData(((LLClientView)client).UDPClient, data, packet.Type, category, null);
940 // }
941 // );
942 // }
943 // }
944  
945 /// <summary>
946 /// Start the process of sending a packet to the client.
947 /// </summary>
948 /// <param name="udpClient"></param>
949 /// <param name="packet"></param>
950 /// <param name="category"></param>
951 /// <param name="allowSplitting"></param>
952 /// <param name="method">
953 /// The method to call if the packet is not acked by the client. If null, then a standard
954 /// resend of the packet is done.
955 /// </param>
956 public virtual void SendPacket(
957 LLUDPClient udpClient, Packet packet, ThrottleOutPacketType category, bool allowSplitting, UnackedPacketMethod method)
958 {
959 // CoarseLocationUpdate packets cannot be split in an automated way
960 if (packet.Type == PacketType.CoarseLocationUpdate && allowSplitting)
961 allowSplitting = false;
962  
963 bool packetQueued = false;
964  
965 if (allowSplitting && packet.HasVariableBlocks)
966 {
967 byte[][] datas = packet.ToBytesMultiple();
968 int packetCount = datas.Length;
969  
970 if (packetCount < 1)
971 m_log.Error("[LLUDPSERVER]: Failed to split " + packet.Type + " with estimated length " + packet.Length);
972  
973 for (int i = 0; i < packetCount; i++)
974 {
975 byte[] data = datas[i];
976  
977 if (!SendPacketData(udpClient, data, packet.Type, category, method))
978 packetQueued = true;
979 }
980 }
981 else
982 {
983 byte[] data = packet.ToBytes();
984 packetQueued = SendPacketData(udpClient, data, packet.Type, category, method);
985 }
986  
987 PacketPool.Instance.ReturnPacket(packet);
988  
989 if (packetQueued)
990 m_dataPresentEvent.Set();
991 }
992  
993 /// <summary>
994 /// Start the process of sending a packet to the client.
995 /// </summary>
996 /// <param name="udpClient"></param>
997 /// <param name="data"></param>
998 /// <param name="type"></param>
999 /// <param name="category"></param>
1000 /// <param name="method">
1001 /// The method to call if the packet is not acked by the client. If null, then a standard
1002 /// resend of the packet is done.
1003 /// </param>
1004 /// <returns>true if the data was sent immediately, false if it was queued for sending</returns>
1005 public bool SendPacketData(
1006 LLUDPClient udpClient, byte[] data, PacketType type, ThrottleOutPacketType category, UnackedPacketMethod method)
1007 {
1008 int dataLength = data.Length;
1009 bool doZerocode = (data[0] & Helpers.MSG_ZEROCODED) != 0;
1010 bool doCopy = true;
1011  
1012 // Frequency analysis of outgoing packet sizes shows a large clump of packets at each end of the spectrum.
1013 // The vast majority of packets are less than 200 bytes, although due to asset transfers and packet splitting
1014 // there are a decent number of packets in the 1000-1140 byte range. We allocate one of two sizes of data here
1015 // to accomodate for both common scenarios and provide ample room for ACK appending in both
1016 int bufferSize = (dataLength > 180) ? LLUDPServer.MTU : 200;
1017  
1018 UDPPacketBuffer buffer = new UDPPacketBuffer(udpClient.RemoteEndPoint, bufferSize);
1019  
1020 // Zerocode if needed
1021 if (doZerocode)
1022 {
1023 try
1024 {
1025 dataLength = Helpers.ZeroEncode(data, dataLength, buffer.Data);
1026 doCopy = false;
1027 }
1028 catch (IndexOutOfRangeException)
1029 {
1030 // The packet grew larger than the bufferSize while zerocoding.
1031 // Remove the MSG_ZEROCODED flag and send the unencoded data
1032 // instead
1033 m_log.Debug("[LLUDPSERVER]: Packet exceeded buffer size during zerocoding for " + type + ". DataLength=" + dataLength +
1034 " and BufferLength=" + buffer.Data.Length + ". Removing MSG_ZEROCODED flag");
1035 data[0] = (byte)(data[0] & ~Helpers.MSG_ZEROCODED);
1036 }
1037 }
1038  
1039 // If the packet data wasn't already copied during zerocoding, copy it now
1040 if (doCopy)
1041 {
1042 if (dataLength <= buffer.Data.Length)
1043 {
1044 Buffer.BlockCopy(data, 0, buffer.Data, 0, dataLength);
1045 }
1046 else
1047 {
1048 bufferSize = dataLength;
1049 buffer = new UDPPacketBuffer(udpClient.RemoteEndPoint, bufferSize);
1050  
1051 // m_log.Error("[LLUDPSERVER]: Packet exceeded buffer size! This could be an indication of packet assembly not obeying the MTU. Type=" +
1052 // type + ", DataLength=" + dataLength + ", BufferLength=" + buffer.Data.Length + ". Dropping packet");
1053 Buffer.BlockCopy(data, 0, buffer.Data, 0, dataLength);
1054 }
1055 }
1056  
1057 buffer.DataLength = dataLength;
1058  
1059 #region Queue or Send
1060  
1061 OutgoingPacket outgoingPacket = new OutgoingPacket(udpClient, buffer, category, null);
1062 // If we were not provided a method for handling unacked, use the UDPServer default method
1063 outgoingPacket.UnackedMethod = ((method == null) ? delegate(OutgoingPacket oPacket) { ResendUnacked(oPacket); } : method);
1064  
1065 // If a Linden Lab 1.23.5 client receives an update packet after a kill packet for an object, it will
1066 // continue to display the deleted object until relog. Therefore, we need to always queue a kill object
1067 // packet so that it isn't sent before a queued update packet.
1068 bool requestQueue = type == PacketType.KillObject;
1069 if (!outgoingPacket.Client.EnqueueOutgoing(outgoingPacket, requestQueue))
1070 {
1071 SendPacketFinal(outgoingPacket);
1072 return true;
1073 }
1074 else
1075 {
1076 return false;
1077 }
1078  
1079 #endregion Queue or Send
1080 }
1081  
1082 public void SendAcks(LLUDPClient udpClient)
1083 {
1084 uint ack;
1085  
1086 if (udpClient.PendingAcks.Dequeue(out ack))
1087 {
1088 List<PacketAckPacket.PacketsBlock> blocks = new List<PacketAckPacket.PacketsBlock>();
1089 PacketAckPacket.PacketsBlock block = new PacketAckPacket.PacketsBlock();
1090 block.ID = ack;
1091 blocks.Add(block);
1092  
1093 while (udpClient.PendingAcks.Dequeue(out ack))
1094 {
1095 block = new PacketAckPacket.PacketsBlock();
1096 block.ID = ack;
1097 blocks.Add(block);
1098 }
1099  
1100 PacketAckPacket packet = new PacketAckPacket();
1101 packet.Header.Reliable = false;
1102 packet.Packets = blocks.ToArray();
1103  
1104 SendPacket(udpClient, packet, ThrottleOutPacketType.Unknown, true, null);
1105 }
1106 }
1107  
1108 public void SendPing(LLUDPClient udpClient)
1109 {
1110 StartPingCheckPacket pc = (StartPingCheckPacket)PacketPool.Instance.GetPacket(PacketType.StartPingCheck);
1111 pc.Header.Reliable = false;
1112  
1113 pc.PingID.PingID = (byte)udpClient.CurrentPingSequence++;
1114 // We *could* get OldestUnacked, but it would hurt performance and not provide any benefit
1115 pc.PingID.OldestUnacked = 0;
1116  
1117 SendPacket(udpClient, pc, ThrottleOutPacketType.Unknown, false, null);
1118 }
1119  
1120 public void CompletePing(LLUDPClient udpClient, byte pingID)
1121 {
1122 CompletePingCheckPacket completePing = new CompletePingCheckPacket();
1123 completePing.PingID.PingID = pingID;
1124 SendPacket(udpClient, completePing, ThrottleOutPacketType.Unknown, false, null);
1125 }
1126  
1127 public void HandleUnacked(LLClientView client)
1128 {
1129 LLUDPClient udpClient = client.UDPClient;
1130  
1131 if (!udpClient.IsConnected)
1132 return;
1133  
1134 // Disconnect an agent if no packets are received for some time
1135 int timeoutTicks = m_ackTimeout;
1136  
1137 // Allow more slack if the client is "paused" eg file upload dialogue is open
1138 // Some sort of limit is needed in case the client crashes, loses its network connection
1139 // or some other disaster prevents it from sendung the AgentResume
1140 if (udpClient.IsPaused)
1141 timeoutTicks = m_pausedAckTimeout;
1142  
1143 if (client.IsActive &&
1144 (Environment.TickCount & Int32.MaxValue) - udpClient.TickLastPacketReceived > timeoutTicks)
1145 {
1146 // We must set IsActive synchronously so that we can stop the packet loop reinvoking this method, even
1147 // though it's set later on by LLClientView.Close()
1148 client.IsActive = false;
1149  
1150 // Fire this out on a different thread so that we don't hold up outgoing packet processing for
1151 // everybody else if this is being called due to an ack timeout.
1152 // This is the same as processing as the async process of a logout request.
1153 Util.FireAndForget(o => DeactivateClientDueToTimeout(client, timeoutTicks));
1154  
1155 return;
1156 }
1157  
1158 // Get a list of all of the packets that have been sitting unacked longer than udpClient.RTO
1159 List<OutgoingPacket> expiredPackets = udpClient.NeedAcks.GetExpiredPackets(udpClient.RTO);
1160  
1161 if (expiredPackets != null)
1162 {
1163 //m_log.Debug("[LLUDPSERVER]: Handling " + expiredPackets.Count + " packets to " + udpClient.AgentID + ", RTO=" + udpClient.RTO);
1164 // Exponential backoff of the retransmission timeout
1165 udpClient.BackoffRTO();
1166 for (int i = 0; i < expiredPackets.Count; ++i)
1167 expiredPackets[i].UnackedMethod(expiredPackets[i]);
1168 }
1169 }
1170  
1171 public void ResendUnacked(OutgoingPacket outgoingPacket)
1172 {
1173 //m_log.DebugFormat("[LLUDPSERVER]: Resending packet #{0} (attempt {1}), {2}ms have passed",
1174 // outgoingPacket.SequenceNumber, outgoingPacket.ResendCount, Environment.TickCount - outgoingPacket.TickCount);
1175  
1176 // Set the resent flag
1177 outgoingPacket.Buffer.Data[0] = (byte)(outgoingPacket.Buffer.Data[0] | Helpers.MSG_RESENT);
1178 outgoingPacket.Category = ThrottleOutPacketType.Resend;
1179  
1180 // Bump up the resend count on this packet
1181 Interlocked.Increment(ref outgoingPacket.ResendCount);
1182  
1183 // Requeue or resend the packet
1184 if (!outgoingPacket.Client.EnqueueOutgoing(outgoingPacket, false))
1185 SendPacketFinal(outgoingPacket);
1186 }
1187  
1188 public void Flush(LLUDPClient udpClient)
1189 {
1190 // FIXME: Implement?
1191 }
1192  
1193 /// <summary>
1194 /// Actually send a packet to a client.
1195 /// </summary>
1196 /// <param name="outgoingPacket"></param>
1197 internal void SendPacketFinal(OutgoingPacket outgoingPacket)
1198 {
1199 UDPPacketBuffer buffer = outgoingPacket.Buffer;
1200 byte flags = buffer.Data[0];
1201 bool isResend = (flags & Helpers.MSG_RESENT) != 0;
1202 bool isReliable = (flags & Helpers.MSG_RELIABLE) != 0;
1203 bool isZerocoded = (flags & Helpers.MSG_ZEROCODED) != 0;
1204 LLUDPClient udpClient = outgoingPacket.Client;
1205  
1206 if (!udpClient.IsConnected)
1207 return;
1208  
1209 #region ACK Appending
1210  
1211 int dataLength = buffer.DataLength;
1212  
1213 // NOTE: I'm seeing problems with some viewers when ACKs are appended to zerocoded packets so I've disabled that here
1214 if (!isZerocoded)
1215 {
1216 // Keep appending ACKs until there is no room left in the buffer or there are
1217 // no more ACKs to append
1218 uint ackCount = 0;
1219 uint ack;
1220 while (dataLength + 5 < buffer.Data.Length && udpClient.PendingAcks.Dequeue(out ack))
1221 {
1222 Utils.UIntToBytesBig(ack, buffer.Data, dataLength);
1223 dataLength += 4;
1224 ++ackCount;
1225 }
1226  
1227 if (ackCount > 0)
1228 {
1229 // Set the last byte of the packet equal to the number of appended ACKs
1230 buffer.Data[dataLength++] = (byte)ackCount;
1231 // Set the appended ACKs flag on this packet
1232 buffer.Data[0] = (byte)(buffer.Data[0] | Helpers.MSG_APPENDED_ACKS);
1233 }
1234 }
1235  
1236 buffer.DataLength = dataLength;
1237  
1238 #endregion ACK Appending
1239  
1240 #region Sequence Number Assignment
1241  
1242 if (!isResend)
1243 {
1244 // Not a resend, assign a new sequence number
1245 uint sequenceNumber = (uint)Interlocked.Increment(ref udpClient.CurrentSequence);
1246 Utils.UIntToBytesBig(sequenceNumber, buffer.Data, 1);
1247 outgoingPacket.SequenceNumber = sequenceNumber;
1248  
1249 if (isReliable)
1250 {
1251 // Add this packet to the list of ACK responses we are waiting on from the server
1252 udpClient.NeedAcks.Add(outgoingPacket);
1253 }
1254 }
1255 else
1256 {
1257 Interlocked.Increment(ref udpClient.PacketsResent);
1258  
1259 // We're not going to worry about interlock yet since its not currently critical that this total count
1260 // is 100% correct
1261 PacketsResentCount++;
1262 }
1263  
1264 #endregion Sequence Number Assignment
1265  
1266 // Stats tracking
1267 Interlocked.Increment(ref udpClient.PacketsSent);
1268  
1269 // We're not going to worry about interlock yet since its not currently critical that this total count
1270 // is 100% correct
1271 PacketsSentCount++;
1272  
1273 // Put the UDP payload on the wire
1274 AsyncBeginSend(buffer);
1275  
1276 // Keep track of when this packet was sent out (right now)
1277 outgoingPacket.TickCount = Environment.TickCount & Int32.MaxValue;
1278 }
1279  
1280 private void RecordMalformedInboundPacket(IPEndPoint endPoint)
1281 {
1282 // if (m_malformedCount < 100)
1283 // m_log.DebugFormat("[LLUDPSERVER]: Dropped malformed packet: " + e.ToString());
1284  
1285 IncomingMalformedPacketCount++;
1286  
1287 if ((IncomingMalformedPacketCount % 10000) == 0)
1288 m_log.WarnFormat(
1289 "[LLUDPSERVER]: Received {0} malformed packets so far, probable network attack. Last was from {1}",
1290 IncomingMalformedPacketCount, endPoint);
1291 }
1292  
1293 public override void PacketReceived(UDPPacketBuffer buffer)
1294 {
1295 // Debugging/Profiling
1296 //try { Thread.CurrentThread.Name = "PacketReceived (" + m_scene.RegionInfo.RegionName + ")"; }
1297 //catch (Exception) { }
1298 // m_log.DebugFormat(
1299 // "[LLUDPSERVER]: Packet received from {0} in {1}", buffer.RemoteEndPoint, m_scene.RegionInfo.RegionName);
1300  
1301 LLUDPClient udpClient = null;
1302 Packet packet = null;
1303 int packetEnd = buffer.DataLength - 1;
1304 IPEndPoint endPoint = (IPEndPoint)buffer.RemoteEndPoint;
1305  
1306 #region Decoding
1307  
1308 if (buffer.DataLength < 7)
1309 {
1310 // m_log.WarnFormat(
1311 // "[LLUDPSERVER]: Dropping undersized packet with {0} bytes received from {1} in {2}",
1312 // buffer.DataLength, buffer.RemoteEndPoint, m_scene.RegionInfo.RegionName);
1313  
1314 RecordMalformedInboundPacket(endPoint);
1315  
1316 return; // Drop undersized packet
1317 }
1318  
1319 int headerLen = 7;
1320 if (buffer.Data[6] == 0xFF)
1321 {
1322 if (buffer.Data[7] == 0xFF)
1323 headerLen = 10;
1324 else
1325 headerLen = 8;
1326 }
1327  
1328 if (buffer.DataLength < headerLen)
1329 {
1330 // m_log.WarnFormat(
1331 // "[LLUDPSERVER]: Dropping packet with malformed header received from {0} in {1}",
1332 // buffer.RemoteEndPoint, m_scene.RegionInfo.RegionName);
1333  
1334 RecordMalformedInboundPacket(endPoint);
1335  
1336 return; // Malformed header
1337 }
1338  
1339 try
1340 {
1341 // packet = Packet.BuildPacket(buffer.Data, ref packetEnd,
1342 // // Only allocate a buffer for zerodecoding if the packet is zerocoded
1343 // ((buffer.Data[0] & Helpers.MSG_ZEROCODED) != 0) ? new byte[4096] : null);
1344 // If OpenSimUDPBase.UsePool == true (which is currently separate from the PacketPool) then we
1345 // assume that packet construction does not retain a reference to byte[] buffer.Data (instead, all
1346 // bytes are copied out).
1347 packet = PacketPool.Instance.GetPacket(buffer.Data, ref packetEnd,
1348 // Only allocate a buffer for zerodecoding if the packet is zerocoded
1349 ((buffer.Data[0] & Helpers.MSG_ZEROCODED) != 0) ? new byte[4096] : null);
1350 }
1351 catch (Exception e)
1352 {
1353 if (IncomingMalformedPacketCount < 100)
1354 m_log.DebugFormat("[LLUDPSERVER]: Dropped malformed packet: " + e.ToString());
1355 }
1356  
1357 // Fail-safe check
1358 if (packet == null)
1359 {
1360 if (IncomingMalformedPacketCount < 100)
1361 {
1362 m_log.WarnFormat("[LLUDPSERVER]: Malformed data, cannot parse {0} byte packet from {1}, data {2}:",
1363 buffer.DataLength, buffer.RemoteEndPoint, Utils.BytesToHexString(buffer.Data, buffer.DataLength, null));
1364 }
1365  
1366 RecordMalformedInboundPacket(endPoint);
1367  
1368 return;
1369 }
1370  
1371 #endregion Decoding
1372  
1373 #region Packet to Client Mapping
1374  
1375 // UseCircuitCode handling
1376 if (packet.Type == PacketType.UseCircuitCode)
1377 {
1378 // We need to copy the endpoint so that it doesn't get changed when another thread reuses the
1379 // buffer.
1380 object[] array = new object[] { new IPEndPoint(endPoint.Address, endPoint.Port), packet };
1381  
1382 Util.FireAndForget(HandleUseCircuitCode, array);
1383  
1384 return;
1385 }
1386 else if (packet.Type == PacketType.CompleteAgentMovement)
1387 {
1388 // Send ack straight away to let the viewer know that we got it.
1389 SendAckImmediate(endPoint, packet.Header.Sequence);
1390  
1391 // We need to copy the endpoint so that it doesn't get changed when another thread reuses the
1392 // buffer.
1393 object[] array = new object[] { new IPEndPoint(endPoint.Address, endPoint.Port), packet };
1394  
1395 Util.FireAndForget(HandleCompleteMovementIntoRegion, array);
1396  
1397 return;
1398 }
1399  
1400 // Determine which agent this packet came from
1401 IClientAPI client;
1402 if (!m_scene.TryGetClient(endPoint, out client) || !(client is LLClientView))
1403 {
1404 //m_log.Debug("[LLUDPSERVER]: Received a " + packet.Type + " packet from an unrecognized source: " + address + " in " + m_scene.RegionInfo.RegionName);
1405  
1406 IncomingOrphanedPacketCount++;
1407  
1408 if ((IncomingOrphanedPacketCount % 10000) == 0)
1409 m_log.WarnFormat(
1410 "[LLUDPSERVER]: Received {0} orphaned packets so far. Last was from {1}",
1411 IncomingOrphanedPacketCount, endPoint);
1412  
1413 return;
1414 }
1415  
1416 udpClient = ((LLClientView)client).UDPClient;
1417  
1418 if (!udpClient.IsConnected)
1419 return;
1420  
1421 #endregion Packet to Client Mapping
1422  
1423 // Stats tracking
1424 Interlocked.Increment(ref udpClient.PacketsReceived);
1425  
1426 int now = Environment.TickCount & Int32.MaxValue;
1427 udpClient.TickLastPacketReceived = now;
1428  
1429 #region ACK Receiving
1430  
1431 // Handle appended ACKs
1432 if (packet.Header.AppendedAcks && packet.Header.AckList != null)
1433 {
1434 // m_log.DebugFormat(
1435 // "[LLUDPSERVER]: Handling {0} appended acks from {1} in {2}",
1436 // packet.Header.AckList.Length, client.Name, m_scene.Name);
1437  
1438 for (int i = 0; i < packet.Header.AckList.Length; i++)
1439 udpClient.NeedAcks.Acknowledge(packet.Header.AckList[i], now, packet.Header.Resent);
1440 }
1441  
1442 // Handle PacketAck packets
1443 if (packet.Type == PacketType.PacketAck)
1444 {
1445 PacketAckPacket ackPacket = (PacketAckPacket)packet;
1446  
1447 // m_log.DebugFormat(
1448 // "[LLUDPSERVER]: Handling {0} packet acks for {1} in {2}",
1449 // ackPacket.Packets.Length, client.Name, m_scene.Name);
1450  
1451 for (int i = 0; i < ackPacket.Packets.Length; i++)
1452 udpClient.NeedAcks.Acknowledge(ackPacket.Packets[i].ID, now, packet.Header.Resent);
1453  
1454 // We don't need to do anything else with PacketAck packets
1455 return;
1456 }
1457  
1458 #endregion ACK Receiving
1459  
1460 #region ACK Sending
1461  
1462 if (packet.Header.Reliable)
1463 {
1464 // m_log.DebugFormat(
1465 // "[LLUDPSERVER]: Adding ack request for {0} {1} from {2} in {3}",
1466 // packet.Type, packet.Header.Sequence, client.Name, m_scene.Name);
1467  
1468 udpClient.PendingAcks.Enqueue(packet.Header.Sequence);
1469  
1470 // This is a somewhat odd sequence of steps to pull the client.BytesSinceLastACK value out,
1471 // add the current received bytes to it, test if 2*MTU bytes have been sent, if so remove
1472 // 2*MTU bytes from the value and send ACKs, and finally add the local value back to
1473 // client.BytesSinceLastACK. Lockless thread safety
1474 int bytesSinceLastACK = Interlocked.Exchange(ref udpClient.BytesSinceLastACK, 0);
1475 bytesSinceLastACK += buffer.DataLength;
1476 if (bytesSinceLastACK > LLUDPServer.MTU * 2)
1477 {
1478 bytesSinceLastACK -= LLUDPServer.MTU * 2;
1479 SendAcks(udpClient);
1480 }
1481 Interlocked.Add(ref udpClient.BytesSinceLastACK, bytesSinceLastACK);
1482 }
1483  
1484 #endregion ACK Sending
1485  
1486 #region Incoming Packet Accounting
1487  
1488 // We're not going to worry about interlock yet since its not currently critical that this total count
1489 // is 100% correct
1490 if (packet.Header.Resent)
1491 IncomingPacketsResentCount++;
1492  
1493 // Check the archive of received reliable packet IDs to see whether we already received this packet
1494 if (packet.Header.Reliable && !udpClient.PacketArchive.TryEnqueue(packet.Header.Sequence))
1495 {
1496 if (packet.Header.Resent)
1497 m_log.DebugFormat(
1498 "[LLUDPSERVER]: Received a resend of already processed packet #{0}, type {1} from {2}",
1499 packet.Header.Sequence, packet.Type, client.Name);
1500 else
1501 m_log.WarnFormat(
1502 "[LLUDPSERVER]: Received a duplicate (not marked as resend) of packet #{0}, type {1} from {2}",
1503 packet.Header.Sequence, packet.Type, client.Name);
1504  
1505 // Avoid firing a callback twice for the same packet
1506 return;
1507 }
1508  
1509 #endregion Incoming Packet Accounting
1510  
1511 #region BinaryStats
1512 LogPacketHeader(true, udpClient.CircuitCode, 0, packet.Type, (ushort)packet.Length);
1513 #endregion BinaryStats
1514  
1515 if (packet.Type == PacketType.AgentUpdate)
1516 {
1517 if (m_discardAgentUpdates)
1518 return;
1519  
1520 ((LLClientView)client).TotalAgentUpdates++;
1521  
1522 AgentUpdatePacket agentUpdate = (AgentUpdatePacket)packet;
1523  
1524 LLClientView llClient = client as LLClientView;
1525 if (agentUpdate.AgentData.SessionID != client.SessionId
1526 || agentUpdate.AgentData.AgentID != client.AgentId
1527 || !(llClient == null || llClient.CheckAgentUpdateSignificance(agentUpdate.AgentData)) )
1528 {
1529 PacketPool.Instance.ReturnPacket(packet);
1530 return;
1531 }
1532 }
1533  
1534 #region Ping Check Handling
1535  
1536 if (packet.Type == PacketType.StartPingCheck)
1537 {
1538 // m_log.DebugFormat("[LLUDPSERVER]: Handling ping from {0} in {1}", client.Name, m_scene.Name);
1539  
1540 // We don't need to do anything else with ping checks
1541 StartPingCheckPacket startPing = (StartPingCheckPacket)packet;
1542 CompletePing(udpClient, startPing.PingID.PingID);
1543  
1544 if ((Environment.TickCount - m_elapsedMSSinceLastStatReport) >= 3000)
1545 {
1546 udpClient.SendPacketStats();
1547 m_elapsedMSSinceLastStatReport = Environment.TickCount;
1548 }
1549 return;
1550 }
1551 else if (packet.Type == PacketType.CompletePingCheck)
1552 {
1553 // We don't currently track client ping times
1554 return;
1555 }
1556  
1557 #endregion Ping Check Handling
1558  
1559 IncomingPacket incomingPacket;
1560  
1561 // Inbox insertion
1562 if (UsePools)
1563 {
1564 incomingPacket = m_incomingPacketPool.GetObject();
1565 incomingPacket.Client = (LLClientView)client;
1566 incomingPacket.Packet = packet;
1567 }
1568 else
1569 {
1570 incomingPacket = new IncomingPacket((LLClientView)client, packet);
1571 }
1572  
1573 packetInbox.Enqueue(incomingPacket);
1574 }
1575  
1576 #region BinaryStats
1577  
1578 public class PacketLogger
1579 {
1580 public DateTime StartTime;
1581 public string Path = null;
1582 public System.IO.BinaryWriter Log = null;
1583 }
1584  
1585 public static PacketLogger PacketLog;
1586  
1587 protected static bool m_shouldCollectStats = false;
1588 // Number of seconds to log for
1589 static TimeSpan binStatsMaxFilesize = TimeSpan.FromSeconds(300);
1590 static object binStatsLogLock = new object();
1591 static string binStatsDir = "";
1592  
1593 //for Aggregated In/Out BW logging
1594 static bool m_aggregatedBWStats = false;
1595 static long m_aggregatedBytesIn = 0;
1596 static long m_aggregatedByestOut = 0;
1597 static object aggBWStatsLock = new object();
1598  
1599 public static long AggregatedLLUDPBytesIn
1600 {
1601 get { return m_aggregatedBytesIn; }
1602 }
1603 public static long AggregatedLLUDPBytesOut
1604 {
1605 get {return m_aggregatedByestOut;}
1606 }
1607  
1608 public static void LogPacketHeader(bool incoming, uint circuit, byte flags, PacketType packetType, ushort size)
1609 {
1610 if (m_aggregatedBWStats)
1611 {
1612 lock (aggBWStatsLock)
1613 {
1614 if (incoming)
1615 m_aggregatedBytesIn += size;
1616 else
1617 m_aggregatedByestOut += size;
1618 }
1619 }
1620  
1621 if (!m_shouldCollectStats) return;
1622  
1623 // Binary logging format is TTTTTTTTCCCCFPPPSS, T=Time, C=Circuit, F=Flags, P=PacketType, S=size
1624  
1625 // Put the incoming bit into the least significant bit of the flags byte
1626 if (incoming)
1627 flags |= 0x01;
1628 else
1629 flags &= 0xFE;
1630  
1631 // Put the flags byte into the most significant bits of the type integer
1632 uint type = (uint)packetType;
1633 type |= (uint)flags << 24;
1634  
1635 // m_log.Debug("1 LogPacketHeader(): Outside lock");
1636 lock (binStatsLogLock)
1637 {
1638 DateTime now = DateTime.Now;
1639  
1640 // m_log.Debug("2 LogPacketHeader(): Inside lock. now is " + now.Ticks);
1641 try
1642 {
1643 if (PacketLog == null || (now > PacketLog.StartTime + binStatsMaxFilesize))
1644 {
1645 if (PacketLog != null && PacketLog.Log != null)
1646 {
1647 PacketLog.Log.Close();
1648 }
1649  
1650 // First log file or time has expired, start writing to a new log file
1651 PacketLog = new PacketLogger();
1652 PacketLog.StartTime = now;
1653 PacketLog.Path = (binStatsDir.Length > 0 ? binStatsDir + System.IO.Path.DirectorySeparatorChar.ToString() : "")
1654 + String.Format("packets-{0}.log", now.ToString("yyyyMMddHHmmss"));
1655 PacketLog.Log = new BinaryWriter(File.Open(PacketLog.Path, FileMode.Append, FileAccess.Write));
1656 }
1657  
1658 // Serialize the data
1659 byte[] output = new byte[18];
1660 Buffer.BlockCopy(BitConverter.GetBytes(now.Ticks), 0, output, 0, 8);
1661 Buffer.BlockCopy(BitConverter.GetBytes(circuit), 0, output, 8, 4);
1662 Buffer.BlockCopy(BitConverter.GetBytes(type), 0, output, 12, 4);
1663 Buffer.BlockCopy(BitConverter.GetBytes(size), 0, output, 16, 2);
1664  
1665 // Write the serialized data to disk
1666 if (PacketLog != null && PacketLog.Log != null)
1667 PacketLog.Log.Write(output);
1668 }
1669 catch (Exception ex)
1670 {
1671 m_log.Error("Packet statistics gathering failed: " + ex.Message, ex);
1672 if (PacketLog.Log != null)
1673 {
1674 PacketLog.Log.Close();
1675 }
1676 PacketLog = null;
1677 }
1678 }
1679 }
1680  
1681 #endregion BinaryStats
1682  
1683 private void HandleUseCircuitCode(object o)
1684 {
1685 IPEndPoint endPoint = null;
1686 IClientAPI client = null;
1687  
1688 try
1689 {
1690 // DateTime startTime = DateTime.Now;
1691 object[] array = (object[])o;
1692 endPoint = (IPEndPoint)array[0];
1693 UseCircuitCodePacket uccp = (UseCircuitCodePacket)array[1];
1694  
1695 m_log.DebugFormat(
1696 "[LLUDPSERVER]: Handling UseCircuitCode request for circuit {0} to {1} from IP {2}",
1697 uccp.CircuitCode.Code, m_scene.RegionInfo.RegionName, endPoint);
1698  
1699 AuthenticateResponse sessionInfo;
1700 if (IsClientAuthorized(uccp, out sessionInfo))
1701 {
1702 // Begin the process of adding the client to the simulator
1703 client
1704 = AddClient(
1705 uccp.CircuitCode.Code,
1706 uccp.CircuitCode.ID,
1707 uccp.CircuitCode.SessionID,
1708 endPoint,
1709 sessionInfo);
1710  
1711 // Send ack straight away to let the viewer know that the connection is active.
1712 // The client will be null if it already exists (e.g. if on a region crossing the client sends a use
1713 // circuit code to the existing child agent. This is not particularly obvious.
1714 SendAckImmediate(endPoint, uccp.Header.Sequence);
1715  
1716 // We only want to send initial data to new clients, not ones which are being converted from child to root.
1717 if (client != null)
1718 {
1719 AgentCircuitData aCircuit = m_scene.AuthenticateHandler.GetAgentCircuitData(uccp.CircuitCode.Code);
1720 bool tp = (aCircuit.teleportFlags > 0);
1721 // Let's delay this for TP agents, otherwise the viewer doesn't know where to get resources from
1722 if (!tp)
1723 client.SceneAgent.SendInitialDataToMe();
1724 }
1725 }
1726 else
1727 {
1728 // Don't create clients for unauthorized requesters.
1729 m_log.WarnFormat(
1730 "[LLUDPSERVER]: Ignoring connection request for {0} to {1} with unknown circuit code {2} from IP {3}",
1731 uccp.CircuitCode.ID, m_scene.RegionInfo.RegionName, uccp.CircuitCode.Code, endPoint);
1732 }
1733  
1734 // m_log.DebugFormat(
1735 // "[LLUDPSERVER]: Handling UseCircuitCode request from {0} took {1}ms",
1736 // buffer.RemoteEndPoint, (DateTime.Now - startTime).Milliseconds);
1737  
1738 }
1739 catch (Exception e)
1740 {
1741 m_log.ErrorFormat(
1742 "[LLUDPSERVER]: UseCircuitCode handling from endpoint {0}, client {1} {2} failed. Exception {3}{4}",
1743 endPoint != null ? endPoint.ToString() : "n/a",
1744 client != null ? client.Name : "unknown",
1745 client != null ? client.AgentId.ToString() : "unknown",
1746 e.Message,
1747 e.StackTrace);
1748 }
1749 }
1750  
1751 private void HandleCompleteMovementIntoRegion(object o)
1752 {
1753 IPEndPoint endPoint = null;
1754 IClientAPI client = null;
1755  
1756 try
1757 {
1758 object[] array = (object[])o;
1759 endPoint = (IPEndPoint)array[0];
1760 CompleteAgentMovementPacket packet = (CompleteAgentMovementPacket)array[1];
1761  
1762 m_log.DebugFormat(
1763 "[LLUDPSERVER]: Handling CompleteAgentMovement request from {0} in {1}", endPoint, m_scene.Name);
1764  
1765 // Determine which agent this packet came from
1766 // We need to wait here because in when using the OpenSimulator V2 teleport protocol to travel to a destination
1767 // simulator with no existing child presence, the viewer (at least LL 3.3.4) will send UseCircuitCode
1768 // and then CompleteAgentMovement immediately without waiting for an ack. As we are now handling these
1769 // packets asynchronously, we need to account for this thread proceeding more quickly than the
1770 // UseCircuitCode thread.
1771 int count = 40;
1772 while (count-- > 0)
1773 {
1774 if (m_scene.TryGetClient(endPoint, out client))
1775 {
1776 if (!client.IsActive)
1777 {
1778 // This check exists to catch a condition where the client has been closed by another thread
1779 // but has not yet been removed from the client manager (and possibly a new connection has
1780 // not yet been established).
1781 m_log.DebugFormat(
1782 "[LLUDPSERVER]: Received a CompleteAgentMovement from {0} for {1} in {2} but client is not active yet. Waiting.",
1783 endPoint, client.Name, m_scene.Name);
1784 }
1785 else if (client.SceneAgent == null)
1786 {
1787 // This check exists to catch a condition where the new client has been added to the client
1788 // manager but the SceneAgent has not yet been set in Scene.AddNewAgent(). If we are too
1789 // eager, then the new ScenePresence may not have registered a listener for this messsage
1790 // before we try to process it.
1791 // XXX: A better long term fix may be to add the SceneAgent before the client is added to
1792 // the client manager
1793 m_log.DebugFormat(
1794 "[LLUDPSERVER]: Received a CompleteAgentMovement from {0} for {1} in {2} but client SceneAgent not set yet. Waiting.",
1795 endPoint, client.Name, m_scene.Name);
1796 }
1797 else
1798 {
1799 break;
1800 }
1801 }
1802 else
1803 {
1804 m_log.DebugFormat(
1805 "[LLUDPSERVER]: Received a CompleteAgentMovement from {0} in {1} but no client exists yet. Waiting.",
1806 endPoint, m_scene.Name);
1807 }
1808  
1809 Thread.Sleep(200);
1810 }
1811  
1812 if (client == null)
1813 {
1814 m_log.DebugFormat(
1815 "[LLUDPSERVER]: No client found for CompleteAgentMovement from {0} in {1} after wait. Dropping.",
1816 endPoint, m_scene.Name);
1817  
1818 return;
1819 }
1820 else if (!client.IsActive || client.SceneAgent == null)
1821 {
1822 // This check exists to catch a condition where the client has been closed by another thread
1823 // but has not yet been removed from the client manager.
1824 // The packet could be simply ignored but it is useful to know if this condition occurred for other debugging
1825 // purposes.
1826 m_log.DebugFormat(
1827 "[LLUDPSERVER]: Received a CompleteAgentMovement from {0} for {1} in {2} but client is not active after wait. Dropping.",
1828 endPoint, client.Name, m_scene.Name);
1829  
1830 return;
1831 }
1832  
1833 IncomingPacket incomingPacket1;
1834  
1835 // Inbox insertion
1836 if (UsePools)
1837 {
1838 incomingPacket1 = m_incomingPacketPool.GetObject();
1839 incomingPacket1.Client = (LLClientView)client;
1840 incomingPacket1.Packet = packet;
1841 }
1842 else
1843 {
1844 incomingPacket1 = new IncomingPacket((LLClientView)client, packet);
1845 }
1846  
1847 packetInbox.Enqueue(incomingPacket1);
1848 }
1849 catch (Exception e)
1850 {
1851 m_log.ErrorFormat(
1852 "[LLUDPSERVER]: CompleteAgentMovement handling from endpoint {0}, client {1} {2} failed. Exception {3}{4}",
1853 endPoint != null ? endPoint.ToString() : "n/a",
1854 client != null ? client.Name : "unknown",
1855 client != null ? client.AgentId.ToString() : "unknown",
1856 e.Message,
1857 e.StackTrace);
1858 }
1859 }
1860  
1861 /// <summary>
1862 /// Send an ack immediately to the given endpoint.
1863 /// </summary>
1864 /// <remarks>
1865 /// FIXME: Might be possible to use SendPacketData() like everything else, but this will require refactoring so
1866 /// that we can obtain the UDPClient easily at this point.
1867 /// </remarks>
1868 /// <param name="remoteEndpoint"></param>
1869 /// <param name="sequenceNumber"></param>
1870 private void SendAckImmediate(IPEndPoint remoteEndpoint, uint sequenceNumber)
1871 {
1872 PacketAckPacket ack = new PacketAckPacket();
1873 ack.Header.Reliable = false;
1874 ack.Packets = new PacketAckPacket.PacketsBlock[1];
1875 ack.Packets[0] = new PacketAckPacket.PacketsBlock();
1876 ack.Packets[0].ID = sequenceNumber;
1877  
1878 SendAckImmediate(remoteEndpoint, ack);
1879 }
1880  
1881 public virtual void SendAckImmediate(IPEndPoint remoteEndpoint, PacketAckPacket ack)
1882 {
1883 byte[] packetData = ack.ToBytes();
1884 int length = packetData.Length;
1885  
1886 UDPPacketBuffer buffer = new UDPPacketBuffer(remoteEndpoint, length);
1887 buffer.DataLength = length;
1888  
1889 Buffer.BlockCopy(packetData, 0, buffer.Data, 0, length);
1890  
1891 AsyncBeginSend(buffer);
1892 }
1893  
1894 private bool IsClientAuthorized(UseCircuitCodePacket useCircuitCode, out AuthenticateResponse sessionInfo)
1895 {
1896 UUID agentID = useCircuitCode.CircuitCode.ID;
1897 UUID sessionID = useCircuitCode.CircuitCode.SessionID;
1898 uint circuitCode = useCircuitCode.CircuitCode.Code;
1899  
1900 sessionInfo = m_circuitManager.AuthenticateSession(sessionID, agentID, circuitCode);
1901 return sessionInfo.Authorised;
1902 }
1903  
1904 /// <summary>
1905 /// Add a client.
1906 /// </summary>
1907 /// <param name="circuitCode"></param>
1908 /// <param name="agentID"></param>
1909 /// <param name="sessionID"></param>
1910 /// <param name="remoteEndPoint"></param>
1911 /// <param name="sessionInfo"></param>
1912 /// <returns>The client if it was added. Null if the client already existed.</returns>
1913 protected virtual IClientAPI AddClient(
1914 uint circuitCode, UUID agentID, UUID sessionID, IPEndPoint remoteEndPoint, AuthenticateResponse sessionInfo)
1915 {
1916 IClientAPI client = null;
1917  
1918 // We currently synchronize this code across the whole scene to avoid issues such as
1919 // http://opensimulator.org/mantis/view.php?id=5365 However, once locking per agent circuit can be done
1920 // consistently, this lock could probably be removed.
1921 lock (this)
1922 {
1923 if (!m_scene.TryGetClient(agentID, out client))
1924 {
1925 LLUDPClient udpClient = new LLUDPClient(this, ThrottleRates, m_throttle, circuitCode, agentID, remoteEndPoint, m_defaultRTO, m_maxRTO);
1926  
1927 client = new LLClientView(m_scene, this, udpClient, sessionInfo, agentID, sessionID, circuitCode);
1928 client.OnLogout += LogoutHandler;
1929 client.DebugPacketLevel = DefaultClientPacketDebugLevel;
1930  
1931 ((LLClientView)client).DisableFacelights = m_disableFacelights;
1932  
1933 client.Start();
1934 }
1935 }
1936  
1937 return client;
1938 }
1939  
1940 /// <summary>
1941 /// Deactivates the client if we don't receive any packets within a certain amount of time (default 60 seconds).
1942 /// </summary>
1943 /// <remarks>
1944 /// If a connection is active then we will always receive packets even if nothing else is happening, due to
1945 /// regular client pings.
1946 /// </remarks>
1947 /// <param name='client'></param>
1948 /// <param name='timeoutTicks'></param>
1949 private void DeactivateClientDueToTimeout(LLClientView client, int timeoutTicks)
1950 {
1951 lock (client.CloseSyncLock)
1952 {
1953 ClientLogoutsDueToNoReceives++;
1954  
1955 m_log.WarnFormat(
1956 "[LLUDPSERVER]: No packets received from {0} agent of {1} for {2}ms in {3}. Disconnecting.",
1957 client.SceneAgent.IsChildAgent ? "child" : "root", client.Name, timeoutTicks, m_scene.Name);
1958  
1959 if (!client.SceneAgent.IsChildAgent)
1960 client.Kick("Simulator logged you out due to connection timeout.");
1961 }
1962  
1963 m_scene.CloseAgent(client.AgentId, true);
1964 }
1965  
1966 private void IncomingPacketHandler()
1967 {
1968 // Set this culture for the thread that incoming packets are received
1969 // on to en-US to avoid number parsing issues
1970 Culture.SetCurrentCulture();
1971  
1972 while (IsRunningInbound)
1973 {
1974 try
1975 {
1976 IncomingPacket incomingPacket = null;
1977  
1978 /*
1979 // HACK: This is a test to try and rate limit packet handling on Mono.
1980 // If it works, a more elegant solution can be devised
1981 if (Util.FireAndForgetCount() < 2)
1982 {
1983 //m_log.Debug("[LLUDPSERVER]: Incoming packet handler is sleeping");
1984 Thread.Sleep(30);
1985 }
1986 */
1987  
1988 if (packetInbox.Dequeue(100, ref incomingPacket))
1989 {
1990 ProcessInPacket(incomingPacket);//, incomingPacket); Util.FireAndForget(ProcessInPacket, incomingPacket);
1991  
1992 if (UsePools)
1993 m_incomingPacketPool.ReturnObject(incomingPacket);
1994 }
1995 }
1996 catch (Exception ex)
1997 {
1998 m_log.Error("[LLUDPSERVER]: Error in the incoming packet handler loop: " + ex.Message, ex);
1999 }
2000  
2001 Watchdog.UpdateThread();
2002 }
2003  
2004 if (packetInbox.Count > 0)
2005 m_log.Warn("[LLUDPSERVER]: IncomingPacketHandler is shutting down, dropping " + packetInbox.Count + " packets");
2006 packetInbox.Clear();
2007  
2008 Watchdog.RemoveThread();
2009 }
2010  
2011 private void OutgoingPacketHandler()
2012 {
2013 // Set this culture for the thread that outgoing packets are sent
2014 // on to en-US to avoid number parsing issues
2015 Culture.SetCurrentCulture();
2016  
2017 // Typecast the function to an Action<IClientAPI> once here to avoid allocating a new
2018 // Action generic every round
2019 Action<IClientAPI> clientPacketHandler = ClientOutgoingPacketHandler;
2020  
2021 while (base.IsRunningOutbound)
2022 {
2023 try
2024 {
2025 m_packetSent = false;
2026  
2027 #region Update Timers
2028  
2029 m_resendUnacked = false;
2030 m_sendAcks = false;
2031 m_sendPing = false;
2032  
2033 // Update elapsed time
2034 int thisTick = Environment.TickCount & Int32.MaxValue;
2035 if (m_tickLastOutgoingPacketHandler > thisTick)
2036 m_elapsedMSOutgoingPacketHandler += ((Int32.MaxValue - m_tickLastOutgoingPacketHandler) + thisTick);
2037 else
2038 m_elapsedMSOutgoingPacketHandler += (thisTick - m_tickLastOutgoingPacketHandler);
2039  
2040 m_tickLastOutgoingPacketHandler = thisTick;
2041  
2042 // Check for pending outgoing resends every 100ms
2043 if (m_elapsedMSOutgoingPacketHandler >= 100)
2044 {
2045 m_resendUnacked = true;
2046 m_elapsedMSOutgoingPacketHandler = 0;
2047 m_elapsed100MSOutgoingPacketHandler += 1;
2048 }
2049  
2050 // Check for pending outgoing ACKs every 500ms
2051 if (m_elapsed100MSOutgoingPacketHandler >= 5)
2052 {
2053 m_sendAcks = true;
2054 m_elapsed100MSOutgoingPacketHandler = 0;
2055 m_elapsed500MSOutgoingPacketHandler += 1;
2056 }
2057  
2058 // Send pings to clients every 5000ms
2059 if (m_elapsed500MSOutgoingPacketHandler >= 10)
2060 {
2061 m_sendPing = true;
2062 m_elapsed500MSOutgoingPacketHandler = 0;
2063 }
2064  
2065 #endregion Update Timers
2066  
2067 // Use this for emergency monitoring -- bug hunting
2068 //if (m_scene.EmergencyMonitoring)
2069 // clientPacketHandler = MonitoredClientOutgoingPacketHandler;
2070 //else
2071 // clientPacketHandler = ClientOutgoingPacketHandler;
2072  
2073 // Handle outgoing packets, resends, acknowledgements, and pings for each
2074 // client. m_packetSent will be set to true if a packet is sent
2075 m_scene.ForEachClient(clientPacketHandler);
2076  
2077 m_currentOutgoingClient = null;
2078  
2079 // If nothing was sent, sleep for the minimum amount of time before a
2080 // token bucket could get more tokens
2081 //if (!m_packetSent)
2082 // Thread.Sleep((int)TickCountResolution);
2083 //
2084 // Instead, now wait for data present to be explicitly signalled. Evidence so far is that with
2085 // modern mono it reduces CPU base load since there is no more continuous polling.
2086 if (!m_packetSent)
2087 m_dataPresentEvent.WaitOne(100);
2088  
2089 Watchdog.UpdateThread();
2090 }
2091 catch (Exception ex)
2092 {
2093 m_log.Error("[LLUDPSERVER]: OutgoingPacketHandler loop threw an exception: " + ex.Message, ex);
2094 }
2095 }
2096  
2097 Watchdog.RemoveThread();
2098 }
2099  
2100 protected void ClientOutgoingPacketHandler(IClientAPI client)
2101 {
2102 m_currentOutgoingClient = client;
2103  
2104 try
2105 {
2106 if (client is LLClientView)
2107 {
2108 LLClientView llClient = (LLClientView)client;
2109 LLUDPClient udpClient = llClient.UDPClient;
2110  
2111 if (udpClient.IsConnected)
2112 {
2113 if (m_resendUnacked)
2114 HandleUnacked(llClient);
2115  
2116 if (m_sendAcks)
2117 SendAcks(udpClient);
2118  
2119 if (m_sendPing)
2120 SendPing(udpClient);
2121  
2122 // Dequeue any outgoing packets that are within the throttle limits
2123 if (udpClient.DequeueOutgoing())
2124 m_packetSent = true;
2125 }
2126 }
2127 }
2128 catch (Exception ex)
2129 {
2130 m_log.Error(
2131 string.Format("[LLUDPSERVER]: OutgoingPacketHandler iteration for {0} threw ", client.Name), ex);
2132 }
2133 }
2134  
2135 #region Emergency Monitoring
2136 // Alternative packet handler fuull of instrumentation
2137 // Handy for hunting bugs
2138 private Stopwatch watch1 = new Stopwatch();
2139 private Stopwatch watch2 = new Stopwatch();
2140  
2141 private float avgProcessingTicks = 0;
2142 private float avgResendUnackedTicks = 0;
2143 private float avgSendAcksTicks = 0;
2144 private float avgSendPingTicks = 0;
2145 private float avgDequeueTicks = 0;
2146 private long nticks = 0;
2147 private long nticksUnack = 0;
2148 private long nticksAck = 0;
2149 private long nticksPing = 0;
2150 private int npacksSent = 0;
2151 private int npackNotSent = 0;
2152  
2153 /// <summary>
2154 /// Number of inbound packets processed since startup.
2155 /// </summary>
2156 public long IncomingPacketsProcessed { get; private set; }
2157  
2158 private void MonitoredClientOutgoingPacketHandler(IClientAPI client)
2159 {
2160 nticks++;
2161 watch1.Start();
2162 m_currentOutgoingClient = client;
2163  
2164 try
2165 {
2166 if (client is LLClientView)
2167 {
2168 LLClientView llClient = (LLClientView)client;
2169 LLUDPClient udpClient = llClient.UDPClient;
2170  
2171 if (udpClient.IsConnected)
2172 {
2173 if (m_resendUnacked)
2174 {
2175 nticksUnack++;
2176 watch2.Start();
2177  
2178 HandleUnacked(llClient);
2179  
2180 watch2.Stop();
2181 avgResendUnackedTicks = (nticksUnack - 1)/(float)nticksUnack * avgResendUnackedTicks + (watch2.ElapsedTicks / (float)nticksUnack);
2182 watch2.Reset();
2183 }
2184  
2185 if (m_sendAcks)
2186 {
2187 nticksAck++;
2188 watch2.Start();
2189  
2190 SendAcks(udpClient);
2191  
2192 watch2.Stop();
2193 avgSendAcksTicks = (nticksAck - 1) / (float)nticksAck * avgSendAcksTicks + (watch2.ElapsedTicks / (float)nticksAck);
2194 watch2.Reset();
2195 }
2196  
2197 if (m_sendPing)
2198 {
2199 nticksPing++;
2200 watch2.Start();
2201  
2202 SendPing(udpClient);
2203  
2204 watch2.Stop();
2205 avgSendPingTicks = (nticksPing - 1) / (float)nticksPing * avgSendPingTicks + (watch2.ElapsedTicks / (float)nticksPing);
2206 watch2.Reset();
2207 }
2208  
2209 watch2.Start();
2210 // Dequeue any outgoing packets that are within the throttle limits
2211 if (udpClient.DequeueOutgoing())
2212 {
2213 m_packetSent = true;
2214 npacksSent++;
2215 }
2216 else
2217 {
2218 npackNotSent++;
2219 }
2220  
2221 watch2.Stop();
2222 avgDequeueTicks = (nticks - 1) / (float)nticks * avgDequeueTicks + (watch2.ElapsedTicks / (float)nticks);
2223 watch2.Reset();
2224  
2225 }
2226 else
2227 {
2228 m_log.WarnFormat("[LLUDPSERVER]: Client is not connected");
2229 }
2230 }
2231 }
2232 catch (Exception ex)
2233 {
2234 m_log.Error("[LLUDPSERVER]: OutgoingPacketHandler iteration for " + client.Name +
2235 " threw an exception: " + ex.Message, ex);
2236 }
2237 watch1.Stop();
2238 avgProcessingTicks = (nticks - 1) / (float)nticks * avgProcessingTicks + (watch1.ElapsedTicks / (float)nticks);
2239 watch1.Reset();
2240  
2241 // reuse this -- it's every ~100ms
2242 if (m_scene.EmergencyMonitoring && nticks % 100 == 0)
2243 {
2244 m_log.InfoFormat("[LLUDPSERVER]: avg processing ticks: {0} avg unacked: {1} avg acks: {2} avg ping: {3} avg dequeue: {4} (TickCountRes: {5} sent: {6} notsent: {7})",
2245 avgProcessingTicks, avgResendUnackedTicks, avgSendAcksTicks, avgSendPingTicks, avgDequeueTicks, TickCountResolution, npacksSent, npackNotSent);
2246 npackNotSent = npacksSent = 0;
2247 }
2248  
2249 }
2250  
2251 #endregion
2252  
2253 private void ProcessInPacket(IncomingPacket incomingPacket)
2254 {
2255 Packet packet = incomingPacket.Packet;
2256 LLClientView client = incomingPacket.Client;
2257  
2258 if (client.IsActive)
2259 {
2260 m_currentIncomingClient = client;
2261  
2262 try
2263 {
2264 // Process this packet
2265 client.ProcessInPacket(packet);
2266 }
2267 catch (ThreadAbortException)
2268 {
2269 // If something is trying to abort the packet processing thread, take that as a hint that it's time to shut down
2270 m_log.Info("[LLUDPSERVER]: Caught a thread abort, shutting down the LLUDP server");
2271 Stop();
2272 }
2273 catch (Exception e)
2274 {
2275 // Don't let a failure in an individual client thread crash the whole sim.
2276 m_log.Error(
2277 string.Format(
2278 "[LLUDPSERVER]: Client packet handler for {0} for packet {1} threw ",
2279 client.Name, packet.Type),
2280 e);
2281 }
2282 finally
2283 {
2284 m_currentIncomingClient = null;
2285 }
2286 }
2287 else
2288 {
2289 m_log.DebugFormat(
2290 "[LLUDPSERVER]: Dropped incoming {0} for dead client {1} in {2}",
2291 packet.Type, client.Name, m_scene.RegionInfo.RegionName);
2292 }
2293  
2294 IncomingPacketsProcessed++;
2295 }
2296  
2297 protected void LogoutHandler(IClientAPI client)
2298 {
2299 client.SendLogoutPacket();
2300  
2301 if (!client.IsLoggingOut)
2302 {
2303 client.IsLoggingOut = true;
2304 m_scene.CloseAgent(client.AgentId, false);
2305 }
2306 }
2307 }
2308 }