NetworkSession: add a dedicated PrefixedLogger, clean up some boilerplate code

This commit is contained in:
Dylan K. Taylor 2019-05-06 16:32:34 +01:00
parent 7ae84944ca
commit 5250a432d1
4 changed files with 33 additions and 26 deletions

View File

@ -83,6 +83,8 @@ use function time;
use function ucfirst;
class NetworkSession{
/** @var \PrefixedLogger */
private $logger;
/** @var Server */
private $server;
/** @var Player|null */
@ -130,6 +132,8 @@ class NetworkSession{
$this->ip = $ip;
$this->port = $port;
$this->logger = new \PrefixedLogger($this->server->getLogger(), $this->getLogPrefix());
$this->compressedQueue = new \SplQueue();
$this->connectTime = time();
@ -139,6 +143,14 @@ class NetworkSession{
$this->manager->add($this);
}
private function getLogPrefix() : string{
return "NetworkSession: " . $this->getDisplayName();
}
public function getLogger() : \Logger{
return $this->logger;
}
protected function createPlayer() : void{
$ev = new PlayerCreationEvent($this);
$ev->call();
@ -170,6 +182,7 @@ class NetworkSession{
throw new \InvalidStateException("Player info has already been set");
}
$this->info = $info;
$this->logger->setPrefix($this->getLogPrefix());
}
public function isConnected() : bool{
@ -242,7 +255,7 @@ class NetworkSession{
try{
$payload = $this->cipher->decrypt($payload);
}catch(\UnexpectedValueException $e){
$this->server->getLogger()->debug("Encrypted packet from " . $this->getDisplayName() . ": " . bin2hex($payload));
$this->logger->debug("Encrypted packet: " . bin2hex($payload));
throw new BadPacketException("Packet decryption error: " . $e->getMessage(), 0, $e);
}finally{
Timings::$playerNetworkReceiveDecryptTimer->stopTiming();
@ -253,7 +266,7 @@ class NetworkSession{
try{
$stream = new PacketStream(NetworkCompression::decompress($payload));
}catch(\ErrorException $e){
$this->server->getLogger()->debug("Failed to decompress packet from " . $this->getDisplayName() . ": " . bin2hex($payload));
$this->logger->debug("Failed to decompress packet: " . bin2hex($payload));
//TODO: this isn't incompatible game version if we already established protocol version
throw new BadPacketException("Compressed packet batch decode error (incompatible game version?)", 0, $e);
}finally{
@ -268,14 +281,14 @@ class NetworkSession{
try{
$pk = PacketPool::getPacket($stream->getString());
}catch(BinaryDataException $e){
$this->server->getLogger()->debug("Packet batch from " . $this->getDisplayName() . ": " . bin2hex($stream->getBuffer()));
$this->logger->debug("Packet batch: " . bin2hex($stream->getBuffer()));
throw new BadPacketException("Packet batch decode error: " . $e->getMessage(), 0, $e);
}
try{
$this->handleDataPacket($pk);
}catch(BadPacketException $e){
$this->server->getLogger()->debug($pk->getName() . " from " . $this->getDisplayName() . ": " . bin2hex($pk->getBuffer()));
$this->logger->debug($pk->getName() . ": " . bin2hex($pk->getBuffer()));
throw new BadPacketException("Error processing " . $pk->getName() . ": " . $e->getMessage(), 0, $e);
}
}
@ -298,13 +311,13 @@ class NetworkSession{
$packet->decode();
if(!$packet->feof() and !$packet->mayHaveUnreadBytes()){
$remains = substr($packet->getBuffer(), $packet->getOffset());
$this->server->getLogger()->debug("Still " . strlen($remains) . " bytes unread in " . $packet->getName() . ": " . bin2hex($remains));
$this->logger->debug("Still " . strlen($remains) . " bytes unread in " . $packet->getName() . ": " . bin2hex($remains));
}
$ev = new DataPacketReceiveEvent($this, $packet);
$ev->call();
if(!$ev->isCancelled() and !$packet->handle($this->handler)){
$this->server->getLogger()->debug("Unhandled " . $packet->getName() . " received from " . $this->getDisplayName() . ": " . bin2hex($packet->getBuffer()));
$this->logger->debug("Unhandled " . $packet->getName() . ": " . bin2hex($packet->getBuffer()));
}
}finally{
$timings->stopTiming();
@ -511,13 +524,11 @@ class NetworkSession{
return false;
}
$this->server->getLogger()->debug($this->getDisplayName() . " is NOT logged into Xbox Live");
if($this->info->getXuid() !== ""){
$this->server->getLogger()->warning($this->getDisplayName() . " has an XUID, but their login keychain is not signed by Mojang");
$this->logger->warning("Found XUID, but login keychain is not signed by Mojang");
}
}else{
$this->server->getLogger()->debug($this->getDisplayName() . " is logged into Xbox Live");
}
$this->logger->debug("Xbox Live authenticated: " . ($this->authenticated ? "YES" : "NO"));
return $this->manager->kickDuplicates($this);
}
@ -530,7 +541,7 @@ class NetworkSession{
$this->cipher = new NetworkCipher($encryptionKey);
$this->setHandler(new HandshakeSessionHandler($this));
$this->server->getLogger()->debug("Enabled encryption for " . $this->getDisplayName());
$this->logger->debug("Enabled encryption");
}
public function onLoginSuccess() : void{
@ -540,7 +551,7 @@ class NetworkSession{
$pk->status = PlayStatusPacket::LOGIN_SUCCESS;
$this->sendDataPacket($pk);
$this->setHandler(new ResourcePacksSessionHandler($this->server, $this, $this->server->getResourcePackManager()));
$this->setHandler(new ResourcePacksSessionHandler($this, $this->server->getResourcePackManager()));
}
public function onResourcePacksDone() : void{

View File

@ -246,7 +246,7 @@ class ProcessLoginTask extends AsyncTask{
/** @var NetworkSession $session */
$session = $this->fetchLocal(self::TLS_KEY_SESSION);
if(!$session->isConnected()){
$this->worker->getLogger()->error("Player " . $session->getDisplayName() . " was disconnected before their login could be verified");
$session->getLogger()->debug("Disconnected before login could be verified");
}elseif($session->setAuthenticationStatus($this->authenticated, $this->authRequired, $this->error)){
if(!$this->useEncryption){
$session->onLoginSuccess();

View File

@ -32,7 +32,6 @@ use pocketmine\network\mcpe\protocol\ResourcePacksInfoPacket;
use pocketmine\network\mcpe\protocol\ResourcePackStackPacket;
use pocketmine\resourcepacks\ResourcePack;
use pocketmine\resourcepacks\ResourcePackManager;
use pocketmine\Server;
use function ceil;
use function implode;
use function strpos;
@ -45,8 +44,6 @@ use function substr;
class ResourcePacksSessionHandler extends SessionHandler{
private const PACK_CHUNK_SIZE = 1048576; //1MB
/** @var Server */
private $server;
/** @var NetworkSession */
private $session;
/** @var ResourcePackManager */
@ -56,8 +53,7 @@ class ResourcePacksSessionHandler extends SessionHandler{
private $downloadedChunks = [];
public function __construct(Server $server, NetworkSession $session, ResourcePackManager $resourcePackManager){
$this->server = $server;
public function __construct(NetworkSession $session, ResourcePackManager $resourcePackManager){
$this->session = $session;
$this->resourcePackManager = $resourcePackManager;
}
@ -70,7 +66,7 @@ class ResourcePacksSessionHandler extends SessionHandler{
}
private function disconnectWithError(string $error) : void{
$this->server->getLogger()->error("Error while downloading resource packs for " . $this->session->getDisplayName() . ": " . $error);
$this->session->getLogger()->error("Error downloading resource packs: " . $error);
$this->session->disconnect("disconnectionScreen.resourcePack");
}

View File

@ -199,7 +199,7 @@ class SimpleSessionHandler extends SessionHandler{
$actions[] = $action;
}
}catch(\UnexpectedValueException $e){
$this->player->getServer()->getLogger()->debug("Unhandled inventory action from " . $this->player->getName() . ": " . $e->getMessage());
$this->session->getLogger()->debug("Unhandled inventory action: " . $e->getMessage());
return false;
}
}
@ -220,7 +220,7 @@ class SimpleSessionHandler extends SessionHandler{
try{
$this->craftingTransaction->execute();
}catch(TransactionValidationException $e){
$this->player->getServer()->getLogger()->debug("Failed to execute crafting transaction for " . $this->player->getName() . ": " . $e->getMessage());
$this->session->getLogger()->debug("Failed to execute crafting transaction: " . $e->getMessage());
return false;
}finally{
$this->craftingTransaction = null;
@ -229,7 +229,7 @@ class SimpleSessionHandler extends SessionHandler{
}else{
//normal transaction fallthru
if($this->craftingTransaction !== null){
$this->player->getServer()->getLogger()->debug("Got unexpected normal inventory action with incomplete crafting transaction from " . $this->player->getName() . ", refusing to execute crafting");
$this->session->getLogger()->debug("Got unexpected normal inventory action with incomplete crafting transaction, refusing to execute crafting");
$this->craftingTransaction = null;
return false;
}
@ -238,8 +238,8 @@ class SimpleSessionHandler extends SessionHandler{
try{
$transaction->execute();
}catch(TransactionValidationException $e){
$logger = $this->player->getServer()->getLogger();
$logger->debug("Failed to execute inventory transaction from " . $this->player->getName() . ": " . $e->getMessage());
$logger = $this->session->getLogger();
$logger->debug("Failed to execute inventory transaction: " . $e->getMessage());
$logger->debug("Actions: " . json_encode($data->getActions()));
return false;
@ -393,7 +393,7 @@ class SimpleSessionHandler extends SessionHandler{
//TODO: handle this when it doesn't spam every damn tick (yet another spam bug!!)
break;
default:
$this->player->getServer()->getLogger()->debug("Unhandled/unknown player action type " . $packet->action . " from " . $this->player->getName());
$this->session->getLogger()->debug("Unhandled/unknown player action type " . $packet->action);
return false;
}
@ -475,7 +475,7 @@ class SimpleSessionHandler extends SessionHandler{
return true;
}
$this->player->getServer()->getLogger()->debug("Invalid sign update data from " . $this->player->getName() . ": " . base64_encode($packet->namedtag));
$this->session->getLogger()->debug("Invalid sign update data: " . base64_encode($packet->namedtag));
}
return false;