clockwerk-opensim-stable – Blame information for rev 1

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