Fix MDC sessionId passing, annotate ping message

common/src/main/scala/net/psforever/packet/game/PingMsg.scala

@@ -7,10 +7,10 @@ import scodec.codecs._
 
 /** Sent periodically by the PlanetSide client when connected to the Login server. Not encrypted
   *
-  * @param unk1
-  * @param unk2
+  * @param serverSlot Which server on the server display is the ping referring to
+  * @param ticks The number of ticks. Usually just reflected back to the client
   */
-final case class PingMsg(unk1 : Long, unk2 : Long) extends PlanetSideGamePacket {
+final case class PingMsg(serverSlot : Long, ticks : Long) extends PlanetSideGamePacket {
   type Packet = PingMsg
   def opcode = GamePacketOpcode.PingMsg
   def encode = PingMsg.encode(this)
@@ -18,7 +18,7 @@ final case class PingMsg(unk1 : Long, unk2 : Long) extends PlanetSideGamePacket
 
 object PingMsg extends Marshallable[PingMsg] {
   implicit val codec : Codec[PingMsg] = (
-    ("unk1" | uint32L) ::
-      ("unk2" | uint32L)
+    ("server_slot" | uint32L) ::
+      ("ticks" | uint32L)
     ).as[PingMsg]
 }

config/logback.xml

@@ -1,9 +1,5 @@
-<configuration>
+<configuration scan="true" scanPeriod="10 seconds">
   <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
-    <!-- encoders are assigned the type
-         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default
-         http://logback.qos.ch/manual/layouts.html#ClassicPatternLayout
-         -->
     <encoder>
       <pattern>[%highlight(%5level)] %logger{35} - %msg%n</pattern>
     </encoder>
@@ -12,27 +8,28 @@
     </filter>
   </appender>
 
-  <appender name="FILE-TRACE" class="ch.qos.logback.core.FileAppender">
-    <file>pslogin-trace.log</file>
-    <encoder>
-      <pattern>%date{ISO8601} [%thread] %-5level %X %logger{35} - %msg%n</pattern>
-    </encoder>
-    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-      <level>TRACE</level>
-    </filter>
-  </appender>
-
   <appender name="FILE-DEBUG" class="ch.qos.logback.core.FileAppender">
     <file>pslogin-debug.log</file>
     <encoder>
-      <pattern>%date{ISO8601} %-5level %X %logger{35} - %msg%n</pattern>
+      <pattern>%date{ISO8601} %5level "%X" %logger{35} - %msg%n</pattern>
     </encoder>
     <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
       <level>DEBUG</level>
     </filter>
   </appender>
 
-  <root level="INFO">
+  <appender name="FILE-TRACE" class="ch.qos.logback.core.FileAppender">
+    <file>pslogin-trace.log</file>
+    <encoder>
+      <pattern>%date{ISO8601} [%thread] %5level "%X" %logger{35} - %msg%n</pattern>
+    </encoder>
+    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
+      <level>OFF</level>
+      <!--<level>TRACE</level>-->
+    </filter>
+  </appender>
+
+  <root level="TRACE">
     <appender-ref ref="STDOUT" />
     <appender-ref ref="FILE-TRACE" />
     <appender-ref ref="FILE-DEBUG" />

pslogin/src/main/scala/CryptoSessionActor.scala

@@ -14,6 +14,8 @@ import java.security.SecureRandom
 import net.psforever.packet.control.{ClientStart, ServerStart}
 import net.psforever.packet.crypto._
 import net.psforever.packet.game.PingMsg
+import org.log4s.MDC
+import MDCContextAware.Implicits._
 
 /**
   * Actor that stores crypto state for a connection, appropriately encrypts and decrypts packets,
@@ -22,6 +24,7 @@ import net.psforever.packet.game.PingMsg
 class CryptoSessionActor extends Actor with MDCContextAware {
   private[this] val log = org.log4s.getLogger
 
+  var sessionId : Long = 0
   var leftRef : ActorRef = ActorRef.noSender
   var rightRef : ActorRef = ActorRef.noSender
 
@@ -46,13 +49,14 @@ class CryptoSessionActor extends Actor with MDCContextAware {
   def receive = Initializing
 
   def Initializing : Receive = {
-    case HelloFriend(right) =>
+    case HelloFriend(sessionId, right) =>
       import MDCContextAware.Implicits._
+      this.sessionId = sessionId
       leftRef = sender()
       rightRef = right.asInstanceOf[ActorRef]
 
       // who ever we send to has to send something back to us
-      rightRef !> HelloFriend(self)
+      rightRef !> HelloFriend(sessionId, self)
 
       log.trace(s"Left sender ${leftRef.path.name}")
 
@@ -78,14 +82,14 @@ class CryptoSessionActor extends Actor with MDCContextAware {
           }
         case Failure(e) =>
           // There is a special case where no crypto is being used.
-          // The only packet coming through looks like PingMsg
-
+          // The only packet coming through looks like PingMsg. This is a hardcoded
+          // feature of the client @ 0x005FD618
           PacketCoding.DecodePacket(msg) match {
             case Successful(packet) =>
               packet match {
-                case ping @ PingMsg(unk1, unk2) =>
-                  // TODO: figure out how to get ping to show up on the planetside client
-                  //sendResponse(PingMsg(unk2, unk1))
+                case ping @ PingMsg(_, _) =>
+                  // reflect the packet back to the sender
+                  sendResponse(ping)
                 case default => log.error(s"Unexpected non-crypto packet type ${packet} in state NewClient")
               }
             case Failure(e) =>
@@ -238,7 +242,7 @@ class CryptoSessionActor extends Actor with MDCContextAware {
               case encPacket @ EncryptedPacket(seq, _) =>
                 PacketCoding.decryptPacket(cryptoState.get, encPacket) match {
                   case Successful(packet) =>
-                    self ! packet
+                    self !> packet
                   case Failure(e) =>
                     log.error("Failed to decode encrypted packet: " + e)
                 }
@@ -292,7 +296,6 @@ class CryptoSessionActor extends Actor with MDCContextAware {
   def handleEstablishedPacket(from : ActorRef, cont : PlanetSidePacketContainer) = {
     // we are processing a packet we decrypted
     if(from == self) {
-      import MDCContextAware.Implicits._
       rightRef !> cont
     } else if(from == rightRef) { // processing a completed packet from the right. encrypt
       val packet = PacketCoding.encryptPacket(cryptoState.get, cont).require
@@ -312,7 +315,10 @@ class CryptoSessionActor extends Actor with MDCContextAware {
         ByteVector.empty
       case Successful(v) =>
         val bytes = v.toByteVector
-        leftRef ! ResponsePacket(bytes)
+
+        MDC("sessionId") = sessionId.toString
+        leftRef !> ResponsePacket(bytes)
+
         bytes
     }
   }
@@ -327,7 +333,10 @@ class CryptoSessionActor extends Actor with MDCContextAware {
         ByteVector.empty
       case Successful(v) =>
         val bytes = v.toByteVector
-        leftRef ! ResponsePacket(bytes)
+
+        MDC("sessionId") = sessionId.toString
+        leftRef !> ResponsePacket(bytes)
+
         bytes
     }
   }

pslogin/src/main/scala/LoginSessionActor.scala

@@ -5,8 +5,10 @@ import akka.actor.{Actor, ActorRef, MDCContextAware}
 import net.psforever.packet.{PlanetSideGamePacket, _}
 import net.psforever.packet.control._
 import net.psforever.packet.game._
+import org.log4s.MDC
 import scodec.Attempt.{Failure, Successful}
 import scodec.bits._
+import MDCContextAware.Implicits._
 
 import scala.util.Random
 
@@ -15,13 +17,15 @@ class LoginSessionActor extends Actor with MDCContextAware {
 
   private case class UpdateServerList()
 
+  var sessionId : Long = 0
   var leftRef : ActorRef = ActorRef.noSender
   var rightRef : ActorRef = ActorRef.noSender
 
   def receive = Initializing
 
   def Initializing : Receive = {
-    case HelloFriend(right) =>
+    case HelloFriend(sessionId, right) =>
+      this.sessionId = sessionId
       leftRef = sender()
       rightRef = right.asInstanceOf[ActorRef]
 
@@ -33,7 +37,7 @@ class LoginSessionActor extends Actor with MDCContextAware {
 
   def Started : Receive = {
     case UpdateServerList() =>
-      updateServerList
+      updateServerList()
     case ctrl @ ControlPacket(_, _) =>
       handlePktContainer(ctrl)
     case game @ GamePacket(_, _, _) =>
@@ -74,7 +78,6 @@ class LoginSessionActor extends Actor with MDCContextAware {
         val serverTick = Math.abs(System.nanoTime().toInt) // limit the size to prevent encoding error
         sendResponse(PacketCoding.CreateControlPacket(ControlSyncResp(diff, serverTick,
           fa, fb, fb, fa)))
-
       case MultiPacket(packets) =>
         packets.foreach { pkt =>
           PacketCoding.DecodePacket(pkt) match {
@@ -109,7 +112,7 @@ class LoginSessionActor extends Actor with MDCContextAware {
           0, 1, 2, 685276011, username, 0, false)
 
         sendResponse(PacketCoding.CreateGamePacket(0, response))
-        updateServerList
+        updateServerList()
       case ConnectToWorldRequestMessage(name, _, _, _, _, _, _) =>
         log.info(s"Connect to world request for '${name}'")
 
@@ -118,7 +121,7 @@ class LoginSessionActor extends Actor with MDCContextAware {
       case default => log.debug(s"Unhandled GamePacket ${pkt}")
   }
 
-  def updateServerList = {
+  def updateServerList() = {
     val msg = VNLWorldStatusMessage("Welcome to PlanetSide! ",
       Vector(
         WorldInformation(serverName, WorldStatus.Up, ServerType.Released,
@@ -135,11 +138,15 @@ class LoginSessionActor extends Actor with MDCContextAware {
 
   def sendResponse(cont : PlanetSidePacketContainer) = {
     log.trace("LOGIN SEND: " + cont)
-    rightRef ! cont
+
+    MDC("sessionId") = sessionId.toString
+    rightRef !> cont
   }
 
   def sendRawResponse(pkt : ByteVector) = {
     log.trace("LOGIN SEND RAW: " + pkt)
-    rightRef ! RawPacket(pkt)
+
+    MDC("sessionId") = sessionId.toString
+    rightRef !> RawPacket(pkt)
   }
 }

pslogin/src/main/scala/MDCContextAware.scala

@@ -15,7 +15,7 @@ trait MDCContextAware extends Actor with ActorLogging  {
     val orig = MDC.getCopyOfContextMap
     try {
       msg match {
-        case MdcMsg(mdc, origMsg) =>
+        case mdcObj @ MdcMsg(mdc, origMsg) =>
           if (mdc != null)
             MDC.setContextMap(mdc)
           else

pslogin/src/main/scala/SessionRouter.scala

@@ -49,7 +49,7 @@ class SessionRouter(pipeline : List[SessionPipeline]) extends Actor with MDCCont
     *      ^              |          ^           |        ^                 |
     *      |     write()  |          |  encrypt  |        |   response      |
     *      +--------------+          +-----------+        +-----------------+
-   */
+    **/
 
   def receive = initializing
 
@@ -84,35 +84,35 @@ class SessionRouter(pipeline : List[SessionPipeline]) extends Actor with MDCCont
         log.info("New session from " + from.toString)
 
         // send the initial message with MDC context (give the session ID to the lower layers)
-        sessionById{session.id}.startOfPipe !> HelloFriend(sessionById{session.id}.nextOfStart)
+        sessionById{session.id}.startOfPipe !> HelloFriend(session.id, sessionById{session.id}.nextOfStart)
         sessionById{session.id}.startOfPipe !> RawPacket(msg)
 
         MDC.clear()
       }
     case ResponsePacket(msg) =>
       val session = sessionByActor.get(sender())
-
-      // drop any old queued messages from old actors
-      //if(session.isDefined) {
+      if(session.isDefined) {
         log.trace(s"Sending response ${msg}")
 
         inputRef ! SendPacket(msg, session.get.address)
-      //}
+      } else {
+        log.error("Dropped old response packet from session actor " + sender().path.name)
+      }
     case Terminated(actor) =>
       val terminatedSession = sessionByActor.get(actor)
 
       if(terminatedSession.isDefined) {
         removeSessionById(terminatedSession.get.id, s"${actor.path.name} died")
+      } else {
+        log.error("Received an invalid actor Termination from " + actor.path.name)
       }
     case default =>
-      log.error(s"Unknown message $default")
+      log.error(s"Unknown message $default from " + sender().path)
   }
 
   def createNewSession(address : InetSocketAddress) = {
     val id = newSessionId
 
-
-
     // inflate the pipeline
     val actors = pipeline.map { actor =>
       val a = context.actorOf(actor.props, actor.nameTemplate + id.toString)
@@ -120,21 +120,13 @@ class SessionRouter(pipeline : List[SessionPipeline]) extends Actor with MDCCont
       a
     }
 
-    /*val cryptoSession = context.actorOf(Props[CryptoSessionActor],
-      "crypto-session-" + id.toString)
-    val loginSession = context.actorOf(Props[LoginSessionActor],
-      "login-session-" + id.toString)*/
-
-    //context.watch(cryptoSession)
-    //context.watch(loginSession)
-
     SessionState(id, address, actors)
   }
 
   def removeSessionById(id : Long, reason : String) : Unit = {
     val sessionOption = sessionById.get(id)
 
-    if(!sessionOption.isDefined)
+    if(sessionOption.isEmpty)
       return
 
     val session = sessionOption.get
@@ -142,7 +134,7 @@ class SessionRouter(pipeline : List[SessionPipeline]) extends Actor with MDCCont
     // TODO: add some sort of delay to prevent old session packets from coming through
     // kill all session specific actors
     session.pipeline.foreach(_ ! PoisonPill)
-    session.pipeline.foreach(sessionByActor remove _)
+    session.pipeline.foreach(sessionByActor remove)
     sessionById.remove(id)
     idBySocket.remove(session.address)
 

pslogin/src/main/scala/UdpListener.scala

@@ -11,7 +11,7 @@ import akka.util.ByteString
 final case class ReceivedPacket(msg : ByteVector, from : InetSocketAddress)
 final case class SendPacket(msg : ByteVector, to : InetSocketAddress)
 final case class Hello()
-final case class HelloFriend(next: ActorRef)
+final case class HelloFriend(sessionId : Long, next: ActorRef)
 
 class UdpListener(nextActorProps : Props, nextActorName : String, address : InetAddress, port : Int) extends Actor {
   private val log = org.log4s.getLogger(self.path.name)

pslogin/src/main/scala/WorldSessionActor.scala

@@ -7,19 +7,23 @@ import net.psforever.packet.control._
 import net.psforever.packet.game._
 import scodec.Attempt.{Failure, Successful}
 import scodec.bits._
+import org.log4s.MDC
+import MDCContextAware.Implicits._
 
 class WorldSessionActor extends Actor with MDCContextAware {
   private[this] val log = org.log4s.getLogger
 
   private case class PokeClient()
 
+  var sessionId : Long = 0
   var leftRef : ActorRef = ActorRef.noSender
   var rightRef : ActorRef = ActorRef.noSender
 
   def receive = Initializing
 
   def Initializing : Receive = {
-    case HelloFriend(right) =>
+    case HelloFriend(sessionId, right) =>
+      this.sessionId = sessionId
       leftRef = sender()
       rightRef = right.asInstanceOf[ActorRef]
 
@@ -121,7 +125,8 @@ class WorldSessionActor extends Actor with MDCContextAware {
           sendResponse(PacketCoding.CreateGamePacket(0, ActionResultMessage(false, Some(1))))
         case CharacterRequestAction.Select =>
           PacketCoding.DecodeGamePacket(objectHex).require match {
-            case ObjectCreateMessage(len, cls, guid, _) =>
+            case obj @ ObjectCreateMessage(len, cls, guid, _, _) =>
+              log.debug("Object: " + obj)
               // LoadMapMessage 13714 in mossy .gcap
               // XXX: hardcoded shit
               sendRawResponse(hex"31 85 6D 61 70 31 33 85  68 6F 6D 65 33 A4 9C 19 00 00 00 AE 30 5E 70 00  ")
@@ -232,11 +237,15 @@ class WorldSessionActor extends Actor with MDCContextAware {
 
   def sendResponse(cont : PlanetSidePacketContainer) = {
     log.trace("WORLD SEND: " + cont)
-    rightRef ! cont
+
+    MDC("sessionId") = sessionId.toString
+    rightRef !> cont
   }
 
   def sendRawResponse(pkt : ByteVector) = {
     log.trace("WORLD SEND RAW: " + pkt)
-    rightRef ! RawPacket(pkt)
+
+    MDC("sessionId") = sessionId.toString
+    rightRef !> RawPacket(pkt)
   }
 }