From 978843b5e39be5f9e7f7bf3685fa1c7ea56934e0 Mon Sep 17 00:00:00 2001 From: Deon George Date: Tue, 17 Aug 2021 23:49:39 +1000 Subject: [PATCH] Simplified logging and fix BINKP issue when receiving less than the blksize --- app/Classes/File/Item.php | 2 + app/Classes/File/Receive.php | 30 ++-- app/Classes/Node.php | 6 +- app/Classes/Protocol/Binkp.php | 51 ++++--- app/Classes/Protocol/EMSI.php | 170 ++++++++++----------- app/Classes/Protocol/Zmodem.php | 239 +++++++++++++++--------------- app/Classes/Sock/SocketClient.php | 40 ++--- 7 files changed, 285 insertions(+), 253 deletions(-) diff --git a/app/Classes/File/Item.php b/app/Classes/File/Item.php index 5cb7836..591e723 100644 --- a/app/Classes/File/Item.php +++ b/app/Classes/File/Item.php @@ -15,6 +15,8 @@ use League\Flysystem\UnreadableFileException; */ class Item { + private const LOGKEY = 'I--'; + protected const IS_PKT = (1<<1); protected const IS_ARC = (1<<2); protected const IS_FILE = (1<<3); diff --git a/app/Classes/File/Receive.php b/app/Classes/File/Receive.php index 5c12861..f976215 100644 --- a/app/Classes/File/Receive.php +++ b/app/Classes/File/Receive.php @@ -22,6 +22,8 @@ use App\Models\Address; */ final class Receive extends Item { + private const LOGKEY = 'IR-'; + private Address $ao; private Collection $list; private ?Item $receiving; @@ -88,14 +90,14 @@ final class Receive extends Item throw new Exception('No file to close'); if ($this->file_pos != $this->receiving->file_size) { - Log::warning(sprintf('%s: - Closing [%s], but missing [%d] bytes',__METHOD__,$this->receiving->file_name,$this->receiving->file_size-$this->file_pos)); + Log::warning(sprintf('%s: - Closing [%s], but missing [%d] bytes',self::LOGKEY,$this->receiving->file_name,$this->receiving->file_size-$this->file_pos)); $this->receiving->incomplete = TRUE; } $this->receiving->received = TRUE; $end = time()-$this->start; - Log::debug(sprintf('%s: - Closing [%s], received in [%d]',__METHOD__,$this->receiving->file_name,$end)); + Log::debug(sprintf('%s: - Closing [%s], received in [%d]',self::LOGKEY,$this->receiving->file_name,$end)); fclose($this->f); $this->file_pos = 0; @@ -107,19 +109,19 @@ final class Receive extends Item if (! $this->receiving->incomplete) switch ($this->receiving->file_type) { case self::IS_PKT: - Log::info(sprintf('%s: - Processing mail packet [%s]',__METHOD__,$this->file)); + Log::info(sprintf('%s: - Processing mail packet [%s]',self::LOGKEY,$this->file)); try { $po = Packet::open(new File($this->file),$this->ao->zone->domain); } catch (InvalidPacketException $e) { - Log::error(sprintf('%s: - Not deleting packet [%s], as it generated an exception',__METHOD__,$this->file)); + Log::error(sprintf('%s: - Not deleting packet [%s], as it generated an exception',self::LOGKEY,$this->file)); break; } foreach ($po->messages as $msg) { - Log::info(sprintf('%s: - Mail from [%s] to [%s]',__METHOD__,$msg->fftn,$msg->tftn)); + Log::info(sprintf('%s: - Mail from [%s] to [%s]',self::LOGKEY,$msg->fftn,$msg->tftn)); // @todo Quick check that the packet should be processed by us. // @todo validate that the packet's zone is in the domain. @@ -129,18 +131,18 @@ final class Receive extends Item } if ($po->errors->count()) { - Log::info(sprintf('%s: - Not deleting packet [%s], as it has validation errors',__METHOD__,$this->file)); + Log::info(sprintf('%s: - Not deleting packet [%s], as it has validation errors',self::LOGKEY,$this->file)); // If we want to keep the packet, we could do that logic here } elseif (! config('app.packet_keep')) { - Log::debug(sprintf('%s: - Deleting processed packet [%s]',__METHOD__,$this->file)); + Log::debug(sprintf('%s: - Deleting processed packet [%s]',self::LOGKEY,$this->file)); unlink($this->file); } break; default: - Log::debug(sprintf('%s: - Leaving file [%s] in the inbound dir',__METHOD__,$this->file)); + Log::debug(sprintf('%s: - Leaving file [%s] in the inbound dir',self::LOGKEY,$this->file)); } $this->receiving = NULL; @@ -155,7 +157,7 @@ final class Receive extends Item */ public function open(Address $ao,bool $check=FALSE): bool { - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$check)); + Log::debug(sprintf('%s:+ open [%d]',self::LOGKEY,$check)); // Check we can open this file // @todo @@ -173,14 +175,14 @@ final class Receive extends Item $this->start = time(); $this->file = sprintf('storage/app/%s/%04X-%s',config('app.fido'),$this->ao->id,$this->receiving->recvas); - Log::debug(sprintf('%s: - Opening [%s]',__METHOD__,$this->file)); + Log::debug(sprintf('%s: - Opening [%s]',self::LOGKEY,$this->file)); $this->f = fopen($this->file,'wb'); if (! $this->f) { - Log::error(sprintf('%s: ! Unable to open file [%s] for writing',__METHOD__,$this->receiving->file_name)); + Log::error(sprintf('%s:! Unable to open file [%s] for writing',self::LOGKEY,$this->receiving->file_name)); return 3; // @todo change to const } - Log::info(sprintf('%s: = End - File [%s] opened for writing',__METHOD__,$this->receiving->file_name)); + Log::info(sprintf('%s:= open - File [%s] opened for writing',self::LOGKEY,$this->receiving->file_name)); return 0; // @todo change to const } @@ -192,7 +194,7 @@ final class Receive extends Item */ public function new(array $file): void { - Log::debug(sprintf('%s: + Start',__METHOD__),['file'=>$file]); + Log::debug(sprintf('%s:+ new [%s]',self::LOGKEY,join('|',$file))); if ($this->receiving) throw new Exception('Can only have 1 file receiving at a time'); @@ -224,7 +226,7 @@ final class Receive extends Item throw new FileException('Error while writing to file'); $this->file_pos += $rc; - Log::debug(sprintf('%s: - Write [%d] bytes, file pos now [%d] of [%d]',__METHOD__,$rc,$this->file_pos,$this->receiving->file_size)); + Log::debug(sprintf('%s:- Write [%d] bytes, file pos now [%d] of [%d] (%d)',self::LOGKEY,$rc,$this->file_pos,$this->receiving->file_size,strlen($buf))); return $rc; } diff --git a/app/Classes/Node.php b/app/Classes/Node.php index 3adf7eb..cacd546 100644 --- a/app/Classes/Node.php +++ b/app/Classes/Node.php @@ -23,6 +23,8 @@ use App\Models\Address; */ class Node { + private const LOGKEY = 'N--'; + // Remote Version private int $version_major = 0; private int $version_minor = 0; @@ -156,7 +158,7 @@ class Node */ public function auth(string $password,string $challenge=''): int { - Log::debug(sprintf('%s: + Start [%s]',__METHOD__,$password)); + Log::debug(sprintf('%s:+ auth [%s]',self::LOGKEY,$password)); // Make sure we havent been here already if ($this->ftns_authed->count()) @@ -177,7 +179,7 @@ class Node } } - Log::debug(sprintf('%s: = End [%d]',__METHOD__,$this->ftns_authed->count())); + Log::debug(sprintf('%s:= auth [%d]',self::LOGKEY,$this->ftns_authed->count())); return $this->ftns_authed->count(); } diff --git a/app/Classes/Protocol/Binkp.php b/app/Classes/Protocol/Binkp.php index a297aa7..624eb69 100644 --- a/app/Classes/Protocol/Binkp.php +++ b/app/Classes/Protocol/Binkp.php @@ -69,8 +69,9 @@ final class Binkp extends BaseProtocol private int $rc; private int $error; - private int $rx_ptr; + private int $rx_ptr; // @todo Whats the point of this? It seems its only the size of $rx_buf? private int $rx_size; + private string $rx_buf = ''; private ?Collection $mqueue; private string $tx_buf; @@ -107,7 +108,7 @@ final class Binkp extends BaseProtocol $this->session(self::SESSION_BINKP,$client,(new Address)); $this->client->close(); - Log::info(sprintf('%s:= End - Connection closed [%s]',self::LOGKEY,$client->address_remote)); + Log::info(sprintf('%s:= onConnect - Connection closed [%s]',self::LOGKEY,$client->address_remote)); exit(0); } @@ -301,14 +302,15 @@ final class Binkp extends BaseProtocol */ private function binkp_recv(): int { - Log::debug(sprintf('%s:+ binkp_recv',self::LOGKEY)); + if ($this->DEBUG) + Log::debug(sprintf('%s:+ binkp_recv',self::LOGKEY)); - $buf = ''; $blksz = $this->rx_size == -1 ? BinkpMessage::BLK_HDR_SIZE : $this->rx_size; + Log::debug(sprintf('%s: - binkp_recv blksize [%d] rx_size [%d].',self::LOGKEY,$blksz,$this->rx_size)); if ($blksz !== 0) { try { - $buf = $this->client->read(0,$blksz-$this->rx_ptr); + $this->rx_buf .= $this->client->read(0,$blksz-$this->rx_ptr); } catch (SocketException $e) { if ($e->getCode() == 11) { @@ -318,6 +320,7 @@ final class Binkp extends BaseProtocol return 1; } + Log::error(sprintf('%s: - binkp_recv Exception [%s].',self::LOGKEY,$e->getCode())); $this->socket_error = $e->getMessage(); $this->error = 1; @@ -325,7 +328,7 @@ final class Binkp extends BaseProtocol return 0; } - if (strlen($buf) == 0) { + if (strlen($this->rx_buf) == 0) { // @todo Check that this is correct. Log::debug(sprintf('%s: - binkp_recv Was the socket closed by the remote?',self::LOGKEY)); $this->error = -2; @@ -340,17 +343,21 @@ final class Binkp extends BaseProtocol */ } - $this->rx_ptr += strlen($buf); + $this->rx_ptr = strlen($this->rx_buf); + + if ($this->DEBUG) + Log::debug(sprintf('%s: - binkp_recv rx_ptr [%d] blksz [%d].',self::LOGKEY,$this->rx_ptr,$blksz)); /* Received complete block */ if ($this->rx_ptr == $blksz) { /* Header */ if ($this->rx_size == -1 ) { - $this->is_msg = ord(substr($buf,0,1)) >> 7; - $this->rx_size = ((ord(substr($buf,0,1))&0x7f) << 8 )+ord(substr($buf,1,1)); + $this->is_msg = ord(substr($this->rx_buf,0,1)) >> 7; + $this->rx_size = ((ord(substr($this->rx_buf,0,1))&0x7f) << 8 )+ord(substr($this->rx_buf,1,1)); $this->rx_ptr = 0; - Log::debug(sprintf('%s: - binkp_recv HEADER, is_msg [%d]',self::LOGKEY,$this->is_msg)); + if ($this->DEBUG) + Log::debug(sprintf('%s: - binkp_recv HEADER, is_msg [%d], rx_size [%d]',self::LOGKEY,$this->is_msg,$this->rx_size)); if ($this->rx_size == 0) goto ZeroLen; @@ -367,24 +374,25 @@ final class Binkp extends BaseProtocol /* Handle zero length block */ if ($this->rx_size == 0 ) { - Log::debug(sprintf('%s: - binkp_recv Zero length msg - dropped',self::LOGKEY)); + Log::debug(sprintf('%s:- binkp_recv Zero length msg - dropped',self::LOGKEY)); $this->rx_size = -1; $this->rx_ptr = 0; + $this->rx_buf = ''; return 1; } - Log::debug(sprintf('%s: - binkp_recv BUFFER [%d]',self::LOGKEY,strlen($buf))); + Log::debug(sprintf('%s: - binkp_recv BUFFER [%d]',self::LOGKEY,strlen($this->rx_buf))); - $rc = ord(substr($buf,0,1)); + $rc = ord(substr($this->rx_buf,0,1)); if ($rc > self::BPM_MAX) { - Log::error(sprintf('%s: ! binkp_recv Unknown Message [%s] (%d)',self::LOGKEY,$buf,strlen($buf))); + Log::error(sprintf('%s: ! binkp_recv Unknown Message [%s] (%d)',self::LOGKEY,$this->rx_buf,strlen($this->rx_buf))); $rc = 1; } else { //DEBUG(('B',2,"rcvd %s '%s'%s",mess[rc],bp->rx_buf + 1,CRYPT(bps))); //@todo CRYPT - $data = substr($buf,1); + $data = substr($this->rx_buf,1); switch ($rc) { case self::M_ADR: $rc = $this->M_adr($data); @@ -435,7 +443,7 @@ final class Binkp extends BaseProtocol } else { if ($this->recv->fd) { try { - $rc = $this->recv->write($buf); + $rc = $this->recv->write($this->rx_buf); } catch (Exception $e) { Log::error(sprintf('%s: ! %s',self::LOGKEY,$e->getMessage())); @@ -448,8 +456,8 @@ final class Binkp extends BaseProtocol if ($this->recv->filepos == $this->recv->size) { Log::info(sprintf('%s: - Finished receiving file [%s] with size [%d]',self::LOGKEY,$this->recv->name,$this->recv->size)); - $this->recv->close(); $this->msgs(self::BPM_GOT,$this->recv->name_size_time); + $this->recv->close(); $rc = 1; } @@ -463,6 +471,8 @@ final class Binkp extends BaseProtocol $this->rx_size = -1; } + $this->rx_buf = ''; + } else { $rc = 1; } @@ -585,7 +595,7 @@ final class Binkp extends BaseProtocol */ private function msgs(string $id,string $msg_body): void { - Log::debug(sprintf('%s: msgs [%s]',self::LOGKEY,$msg_body)); + Log::debug(sprintf('%s:+ msgs [%d:%s]',self::LOGKEY,$id,$msg_body)); $this->mqueue->push(new BinkpMessage($id,$msg_body)); @@ -1076,7 +1086,7 @@ final class Binkp extends BaseProtocol $this->msgs(self::BPM_NUL,sprintf('TRF %lu %lu',$this->send->mail_size,$this->send->file_size)); - Log::debug(sprintf('%s:= End',self::LOGKEY)); + Log::debug(sprintf('%s:= M_ok',self::LOGKEY)); return $this->binkp_hsdone(); } @@ -1252,6 +1262,9 @@ final class Binkp extends BaseProtocol if ($rd && ! $this->binkp_recv()) break; + if ($this->DEBUG) + Log::debug(sprintf('%s: - mqueue [%d]',self::LOGKEY,$this->mqueue->count())); + if (($this->mqueue->count() || $wd) && ! $this->binkp_send() && (! $this->send->total_count)) break; } diff --git a/app/Classes/Protocol/EMSI.php b/app/Classes/Protocol/EMSI.php index a2da778..cf144b3 100644 --- a/app/Classes/Protocol/EMSI.php +++ b/app/Classes/Protocol/EMSI.php @@ -19,10 +19,10 @@ use App\Traits\CRC as CRCTrait; final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface { - use CRCTrait; - private const LOGKEY = 'PE-'; + use CRCTrait; + private const EMSI_BEG = '**EMSI_'; private const EMSI_ARGUS1 = '-PZT8AF6-'; private const EMSI_DAT = self::EMSI_BEG.'DAT'; @@ -82,9 +82,12 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface { // If our parent returns a PID, we've forked if (! parent::onConnect($client)) { + Log::withContext(['pid'=>getmypid()]); + $this->session(self::SESSION_AUTO,$client,(new Address)); $this->client->close(); - Log::info(sprintf('%s: = End - Connection closed [%s]',__METHOD__,$client->address_remote)); + + Log::info(sprintf('%s:= onConnect - Connection closed [%s]',self::LOGKEY,$client->address_remote)); exit(0); } @@ -98,7 +101,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function emsi_banner(): void { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ emsi_banner',self::LOGKEY)); $banner = 'This is a mail only system - unless you are a mailer, you should disconnect :)'; $this->client->buffer_add(self::EMSI_REQ.str_repeat(self::DEL,strlen(self::EMSI_REQ)).$banner.self::CR); @@ -254,12 +257,13 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function emsi_parsedat(string $str): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + if ($this->DEBUG) + Log::debug(sprintf('%s:+ emsi_parsedat',self::LOGKEY)); $l = 0; if (! ($str=strstr($str,self::EMSI_DAT))) { - Log::error(sprintf('%s: ! No EMSI_DAT signature found?',__METHOD__)); + Log::error(sprintf('%s:! No EMSI_DAT signature found?',self::LOGKEY)); return 0; } @@ -269,7 +273,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface /* Bad EMSI length */ if ($l != ($x=strlen($str)-18)) { - Log::error(sprintf('%s: ! Bad EMSI_DAT length: [%u], should be: [%u]!',__METHOD__,$l,$x)); + Log::error(sprintf('%s:! Bad EMSI_DAT length: [%u], should be: [%u]!',self::LOGKEY,$l,$x)); return 0; } @@ -279,14 +283,14 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface /* Bad EMSI CRC */ if ($l != ($x = crc16(substr($str,2,strlen($str)-6)))) { - Log::error(sprintf('%s: ! Bad EMSI_DAT CRC: [%04X], should be: [%04X]!',__METHOD__,$l,$x)); + Log::error(sprintf('%s:! Bad EMSI_DAT CRC: [%04X], should be: [%04X]!',self::LOGKEY,$l,$x)); return 0; } /* No EMSI ident */ if (strncmp(substr($str,14),"{EMSI}",6)) { - Log::error(sprintf('%s: ! No EMSI fingerprint?',__METHOD__)); + Log::error(sprintf('%s:! No EMSI fingerprint?',self::LOGKEY)); return 0; } @@ -294,34 +298,34 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface /* {AKAs} */ $x = 21; foreach (explode(' ',$this->emsi_dat_parse($str,$x)) as $rem_aka) { - Log::debug(sprintf('%s: - Parsing AKA [%s]',__METHOD__,$rem_aka)); + Log::debug(sprintf('%s: - Parsing AKA [%s]',self::LOGKEY,$rem_aka)); try { if (! ($o = Address::findFTN($rem_aka))) { - Log::debug(sprintf('%s: ? AKA is UNKNOWN [%s]',__METHOD__,$rem_aka)); + Log::debug(sprintf('%s: ? AKA is UNKNOWN [%s]',self::LOGKEY,$rem_aka)); continue; } } catch (Exception) { - Log::error(sprintf('%s: ! AKA is INVALID [%s]',__METHOD__,$rem_aka)); + Log::error(sprintf('%s: ! AKA is INVALID [%s]',self::LOGKEY,$rem_aka)); continue; } // Check if the remote has our AKA if ($this->setup->system->addresses->pluck('ftn')->search($o->ftn) !== FALSE) { - Log::error(sprintf('%s: ! AKA is OURS [%s]',__METHOD__,$o->ftn)); + Log::error(sprintf('%s: ! AKA is OURS [%s]',self::LOGKEY,$o->ftn)); continue; } // @todo lock nodes - Log::info(sprintf('%s: - Remote AKA [%s]',__METHOD__,$o->ftn)); + Log::info(sprintf('%s: - Remote AKA [%s]',self::LOGKEY,$o->ftn)); $this->node->ftn = $o; } if ($this->originate AND ! $this->node->originate_check()) { - Log::error(sprintf('%s: ! We didnt get who we called?',__METHOD__)); + Log::error(sprintf('%s: ! We didnt get who we called?',self::LOGKEY)); return self::S_FAILURE|self::S_ADDTRY; } @@ -340,18 +344,18 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface } if (! $c) { - Log::info(sprintf('%s: - Remote has password [%s] on us, and we expect [%s]',__METHOD__,$p,$this->node->password)); + Log::info(sprintf('%s: - Remote has password [%s] on us, and we expect [%s]',self::LOGKEY,$p,$this->node->password)); if ($p || $this->node->password) $this->node->optionSet(self::O_BAD); } else { $this->node->optionSet(self::O_PWD); - Log::info(sprintf('%s: - Remote Authed [%d] AKAs',__METHOD__,$c)); + Log::info(sprintf('%s: - Remote Authed [%d] AKAs',self::LOGKEY,$c)); } /* Link codes */ - Log::notice(sprintf('%s: - Remote Link Codes [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote Link Codes [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); /* Compatibility codes */ $codes = $this->emsi_dat_parse($str,$x); @@ -359,44 +363,44 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface foreach (explode(',',$codes) as $code) { switch ($code) { case 'ARC': - Log::debug(sprintf('%s: = Node accepts ARC mail bundle (ARC)',__METHOD__)); + Log::debug(sprintf('%s: = Node accepts ARC mail bundle (ARC)',self::LOGKEY)); break; case 'NRQ': - Log::debug(sprintf('%s: = No file requests accepted by this system (NRQ)',__METHOD__)); + Log::debug(sprintf('%s: = No file requests accepted by this system (NRQ)',self::LOGKEY)); $this->node->optionSet(self::O_NRQ); break; case 'XMA': - Log::debug(sprintf('%s: = Node supports other forms of compressed mail (XMA)',__METHOD__)); + Log::debug(sprintf('%s: = Node supports other forms of compressed mail (XMA)',self::LOGKEY)); break; case 'ZAP': - Log::debug(sprintf('%s: = Remote wants ZEDZAP',__METHOD__)); + Log::debug(sprintf('%s: = Remote wants ZEDZAP',self::LOGKEY)); $this->node->optionSet(self::P_ZEDZAP); break; case 'ZMO': - Log::debug(sprintf('%s: = Remote wants ZMODEM',__METHOD__)); + Log::debug(sprintf('%s: = Remote wants ZMODEM',self::LOGKEY)); $this->node->optionSet(self::P_ZMODEM); break; default: - Log::info(sprintf('%s: = Ignoring unknown option: [%s] ',__METHOD__,$code)); + Log::info(sprintf('%s: = Ignoring unknown option: [%s] ',self::LOGKEY,$code)); } } /* Mailer code */ - Log::notice(sprintf('%s: - Remote Mailer Code [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); // hex + Log::notice(sprintf('%s: - Remote Mailer Code [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); // hex /* Mailer name */ - Log::notice(sprintf('%s: - Remote Mailer [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote Mailer [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); /* Mailer version */ - Log::notice(sprintf('%s: - Remote Mailer Version [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote Mailer Version [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); /* Mailer serial number */ - Log::notice(sprintf('%s: - Remote Mailer Serial Number [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote Mailer Serial Number [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); while ($t=strpos($str,'}',$x)) { $p = substr($str,$x,$t-$x); @@ -407,22 +411,22 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface case 'IDENT': /* System name */ $x = $t+2; - Log::notice(sprintf('%s: - Remote System [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote System [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); /* System location */ - Log::notice(sprintf('%s: - Remote Location [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote Location [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); /* Operator name */ - Log::notice(sprintf('%s: - Remote Operator [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote Operator [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); /* Phone */ - Log::notice(sprintf('%s: - Remote Phone Number [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote Phone Number [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); /* Baud rate */ $this->client->speed = $this->emsi_dat_parse($str,$x,']'); /* Flags */ - Log::notice(sprintf('%s: - Remote Flags [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote Flags [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); $x++; break; @@ -430,21 +434,21 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface // {TRAF}{} case 'TRAF': $x = $t+1; - Log::notice(sprintf('%s: - Remote TRAF [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote TRAF [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); break; // {OHFR}{} case 'OHFR': $x = $t+1; - Log::notice(sprintf('%s: - Remote OHFR [%s]',__METHOD__,$this->emsi_dat_parse($str,$x))); + Log::notice(sprintf('%s: - Remote OHFR [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x))); break; // {MOH#}{[]} case 'MOH#': $x = $t+2; - Log::notice(sprintf('%s: - Remote MOH# [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote MOH# [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); $x++; break; @@ -452,7 +456,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface // {TRX#}{[]} case 'TRX#': $x = $t+2; - Log::notice(sprintf('%s: - Remote TRX [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote TRX [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); $x++; break; @@ -460,14 +464,14 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface // {TZUTC}{[]} case 'TZUTC': $x = $t+2; - Log::notice(sprintf('%s: - Remote TZUTC [%s]',__METHOD__,$this->emsi_dat_parse($str,$x,']'))); + Log::notice(sprintf('%s: - Remote TZUTC [%s]',self::LOGKEY,$this->emsi_dat_parse($str,$x,']'))); $x++; break; default: $x = $t+1; - Log::notice(sprintf('%s: - Remote UNKNOWN [%s] (%s)',__METHOD__,$this->emsi_dat_parse($str,$x),$p)); + Log::notice(sprintf('%s: - Remote UNKNOWN [%s] (%s)',self::LOGKEY,$this->emsi_dat_parse($str,$x),$p)); } } @@ -482,9 +486,9 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function emsi_recv(int $mode): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ emsi_recv',self::LOGKEY)); - Log::debug(sprintf('%s: - STEP 1',__METHOD__)); + Log::debug(sprintf('%s: - STEP 1',self::LOGKEY)); /* * Step 1 * +-+------------------------------------------------------------------+ @@ -499,7 +503,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface do { step2: - Log::debug(sprintf('%s: - STEP 2',__METHOD__)); + Log::debug(sprintf('%s: - STEP 2',self::LOGKEY)); /* Step 2 +-+------------------------------------------------------------------+ :2: Increment Tries : @@ -530,7 +534,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $this->client->buffer_flush(5); step3: - Log::debug(sprintf('%s: - STEP 3',__METHOD__)); + Log::debug(sprintf('%s: - STEP 3',self::LOGKEY)); /* Step 3 * +-+------------------------------------------------------------------+ * :3: T1=20 seconds : @@ -540,7 +544,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $t1 = $this->client->timer_set(20); step4: - Log::debug(sprintf('%s: - STEP 4',__METHOD__)); + Log::debug(sprintf('%s: - STEP 4',self::LOGKEY)); /* Step 4 +-+------------------------------------------------------------------+ :4: Wait for EMSI sequence until EMSI_HBT or EMSI_DAT or any of the : @@ -586,15 +590,15 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface if (($ch == ord(self::CR)) || ($ch == ord(self::NL))) { if (! strncmp($p,self::EMSI_HBT,self::EMSI_SEQ_LEN)) { - Log::debug(sprintf('%s: - Received EMSI_HBT',__METHOD__)); + Log::debug(sprintf('%s: - Received EMSI_HBT',self::LOGKEY)); goto step3; } if (! strncmp($p,self::EMSI_DAT,10)) { - Log::debug(sprintf('%s: - Received EMSI_DAT',__METHOD__)); + Log::debug(sprintf('%s:- Received EMSI_DAT',self::LOGKEY)); - Log::debug(sprintf('%s: - STEP 5',__METHOD__)); + Log::debug(sprintf('%s: - STEP 5',self::LOGKEY)); /* Step 5 +-+------------------------------------------------------------------+ :5: Receive EMSI_DAT packet : @@ -612,7 +616,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $this->client->buffer_add(self::EMSI_ACK.self::CR); $this->client->buffer_flush(5); - Log::debug(sprintf('%s: - STEP 6',__METHOD__)); + Log::debug(sprintf('%s: - STEP 6',self::LOGKEY)); /* Step 6 +-+------------------------------------------------------------------+ :6: Received EMSI_DAT packet OK, exit. : @@ -622,7 +626,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface return self::OK; } else { - Log::debug(sprintf('%s: - EMSI_DAT didnt parse',__METHOD__)); + Log::debug(sprintf('%s: - EMSI_DAT didnt parse',self::LOGKEY)); goto step2; } @@ -633,11 +637,11 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface } else { if (strlen($p) >= self::EMSI_BUF) { - Log::warning(sprintf('%s: ! EMSI_DAT packet too long.',__METHOD__)); + Log::warning(sprintf('%s: ! EMSI_DAT packet too long.',self::LOGKEY)); $rew = strstr($p,self::EMSI_BEG,TRUE); if ($rew && $rew != $p) { - Log::notice(sprintf('%s: - Got EMSI_DAT at offset [%d].',__METHOD__,strlen($rew))); + Log::notice(sprintf('%s: - Got EMSI_DAT at offset [%d].',self::LOGKEY,strlen($rew))); $p = substr($p,strlen($rew)); } @@ -661,9 +665,9 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function emsi_send(): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ emsi_send',self::LOGKEY)); - Log::debug(sprintf('%s: - STEP 1',__METHOD__)); + Log::debug(sprintf('%s: - STEP 1',self::LOGKEY)); /* Step 1 +-+------------------------------------------------------------------+ :1: Tries=0, T1=60 seconds : @@ -675,7 +679,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $t1 = $this->client->timer_set(self::EMSI_HSTIMEOUT); step2: - Log::debug(sprintf('%s: - STEP 2',__METHOD__)); + Log::debug(sprintf('%s: - STEP 2',self::LOGKEY)); /* Step 2 +-+------------------------------------------------------------------+ :2: Transmit EMSI_DAT packet and increment Tries : @@ -697,7 +701,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface :3: T2=20 seconds : +-+------------------------------------------------------------------+ */ - Log::debug(sprintf('%s: - STEP 3',__METHOD__)); + Log::debug(sprintf('%s: - STEP 3',self::LOGKEY)); $t2 = $this->client->timer_set(20); /* Step 4 @@ -715,7 +719,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface : : If any other sequence received, go to step 2. : +-+------------------------------------------------------------------+ */ - Log::debug(sprintf('%s: - STEP 4',__METHOD__)); + Log::debug(sprintf('%s: - STEP 4',self::LOGKEY)); while(! $this->client->timer_expired($t1)) { $ch = $this->client->read_ch(max( 1,min($this->client->timer_rest($t1),$this->client->timer_rest($t2)))); // Log::debug(sprintf('%s: - Got (%x) {%03d} (%c)',__METHOD__,$ch,$ch,$ch)); @@ -739,7 +743,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface continue; if (! strncmp($p,self::EMSI_DAT,10)) { - Log::warning(sprintf('%s: - Got unexpected EMSI_DAT - Argus?',__METHOD__)); + Log::warning(sprintf('%s: - Got unexpected EMSI_DAT - Argus?',self::LOGKEY)); $this->client->buffer_add(self::EMSI_ACK); $this->client->buffer_add(self::EMSI_ACK); $this->client->buffer_flush(1); @@ -747,12 +751,12 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $t2 = $this->client->timer_set($this->client->timer_rest($t2) >> 2); } else if (! strncmp($p,self::EMSI_REQ,self::EMSI_SEQ_LEN)) { - Log::notice(sprintf('%s: - Got EMSI_REQ - skipping...',__METHOD__)); + Log::notice(sprintf('%s: - Got EMSI_REQ - skipping...',self::LOGKEY)); } else if (! strncmp($p,self::EMSI_ACK,self::EMSI_SEQ_LEN)) { - Log::debug(sprintf('%s: - Got EMSI_ACK',__METHOD__)); + Log::debug(sprintf('%s: - Got EMSI_ACK',self::LOGKEY)); - Log::debug(sprintf('%s: - STEP 5',__METHOD__)); + Log::debug(sprintf('%s: - STEP 5',self::LOGKEY)); /* Step 5 +-+------------------------------------------------------------------+ :5: Received EMSI_ACK, exit. : @@ -772,7 +776,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $p .= chr($ch); } else { - Log::warning(sprintf('%s: ! EMSI packet too long',__METHOD__)); + Log::warning(sprintf('%s: ! EMSI packet too long',self::LOGKEY)); } } } /* goto step4; */ @@ -801,7 +805,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface protected function protocol_init(): int { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ protocol_init',self::LOGKEY)); $got = 0; $tries = 0; @@ -824,7 +828,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface while (TRUE) { $ch = $this->client->read_ch(max( 1,min($this->client->timer_rest($t1),$this->client->timer_rest($t2)))); if ($this->DEBUG) - Log::debug(sprintf('%s: - Got [%x] (%c)',__METHOD__,$ch,$ch)); + Log::debug(sprintf('%s: - Got [%x] (%c)',self::LOGKEY,$ch,$ch)); if (($ch != self::TIMEOUT) && ($ch < 0)) return $ch; @@ -843,7 +847,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface if (++$tries > 10) return self::TIMEOUT; - Log::debug(sprintf('%s: - Sending EMSI_INQ (Try %d of 10)...',__METHOD__,$tries)); + Log::debug(sprintf('%s: - Sending EMSI_INQ (Try %d of 10)...',self::LOGKEY,$tries)); $this->client->buffer_add(self::EMSI_INQ.self::CR); } @@ -858,7 +862,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface if (($ch == ord(self::CR)) || ($ch == ord(self::NL))) { if (strstr($p,self::EMSI_REQ)) { - Log::info(sprintf('%s: - Got EMSI_REQ',__METHOD__)); + Log::info(sprintf('%s: - Got EMSI_REQ',self::LOGKEY)); if ($gotreq++) return self::OK; @@ -866,7 +870,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $this->client->buffer_flush(5); } elseif ($p && strstr($p,self::EMSI_BEG) && strstr($p,self::EMSI_ARGUS1)) { - Log::info(sprintf('%s: - Got Intro [%s]',__METHOD__,$p)); + Log::info(sprintf('%s: - Got Intro [%s]',self::LOGKEY,$p)); } continue; @@ -890,7 +894,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface while (! $this->client->timer_expired($t1)) { $ch = $this->client->read_ch(max( 1,min($this->client->timer_rest($t1),$this->client->timer_rest($t2)))); if ($this->DEBUG) - Log::debug(sprintf('%s: - Got [%x] (%c)',__METHOD__,$ch,$ch)); + Log::debug(sprintf('%s: - Got [%x] (%c)',self::LOGKEY,$ch,$ch)); if (($ch != self::TIMEOUT) && ($ch < 0)) return $ch; @@ -919,7 +923,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface $got = 0; if (strstr($p, self::EMSI_INQ)) { - Log::info(sprintf('%s: - Got EMSI_REQ',__METHOD__)); + Log::info(sprintf('%s: - Got EMSI_REQ',self::LOGKEY)); return self::OK; } @@ -944,7 +948,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ protected function protocol_session(): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ protocol_session',self::LOGKEY)); $was_req = 0; $got_req = 0; @@ -962,19 +966,19 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface if ($rc < 0) return (self::S_REDIAL|self::S_ADDTRY); - Log::info(sprintf('%s: - Starting outbound EMSI session to [%s]',__METHOD__,$this->client->address_remote)); + Log::info(sprintf('%s: - Starting outbound EMSI session to [%s]',self::LOGKEY,$this->client->address_remote)); // Inbound session } else { $rc = $this->emsi_recv(self::SM_INBOUND); if ($rc < 0) { - Log::error(sprintf('%s: ! Unable to establish EMSI session',__METHOD__)); + Log::error(sprintf('%s:! Unable to establish EMSI session',self::LOGKEY)); return (self::S_REDIAL|self::S_ADDTRY); } - Log::info(sprintf('%s: - Starting inbound EMSI session from [%s]',__METHOD__,$this->client->address_remote)); + Log::info(sprintf('%s: - Starting inbound EMSI session from [%s]',self::LOGKEY,$this->client->address_remote)); if ($this->node->aka_authed) { $xproto = $this->is_freq_available(); @@ -985,7 +989,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface foreach ($this->protocols as $p => $key) { if ($this->node->optionGet($key)) { - Log::debug(sprintf('%s: - Remote supports [%s] (%x)',__METHOD__,$p,$key)); + Log::debug(sprintf('%s: - Remote supports [%s] (%x)',self::LOGKEY,$p,$key)); $this->optionSet($key); } } @@ -1002,14 +1006,14 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface // @todo Lock Node AKAs - Log::info(sprintf('%s: - We have %lu%s mail, %lu%s files',__METHOD__,$this->send->mail_size,'b',$this->send->file_size,'b')); + Log::info(sprintf('%s: - We have %lu%s mail, %lu%s files',self::LOGKEY,$this->send->mail_size,'b',$this->send->file_size,'b')); $proto = $this->originate ? $this->node->optionGet(self::P_MASK) : $this->optionGet(self::P_MASK); switch ($proto) { case self::P_NONE: case self::P_NCP: - Log::error(sprintf('%s: ! No compatible protocols',__METHOD__)); + Log::error(sprintf('%s:! No compatible protocols',self::LOGKEY)); return self::S_FAILURE; @@ -1046,17 +1050,17 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Unknown Protocol [%s]',__METHOD__,$proto)); + Log::error(sprintf('%s: ? Unknown Protocol [%s]',self::LOGKEY,$proto)); $t = 'Unknown'; } $xproto = ($this->optionGet(self::O_RH1) && ($this->node->optionGet(self::O_RH1))); $x = (substr($t,1,1) == 'H' && $xproto ) ? 'x' : ''; - Log::info(sprintf('%s: = Using [%s]',__METHOD__,$t)); + Log::info(sprintf('%s: = Using [%s]',self::LOGKEY,$t)); - Log::debug(sprintf('%s: = Options: %s%s%s%s%s%s%s%s%s%s%s', - __METHOD__,$x,$t, + Log::debug(sprintf('%s: = Options: %s%s%s%s%s%s%s%s%s%s%s', + self::LOGKEY,$x,$t, ($this->node->optionGet(self::O_LST)) ? '/LST' : '', ($this->node->optionGet(self::O_PWD)) ? '/PWD' : '', ($this->node->optionGet(self::O_HXT)) ? '/MO': '', @@ -1148,7 +1152,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function wazoorecv(int $zap): bool { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ wazoorecv',self::LOGKEY)); // @todo If the node is not defined in the DB node->address is NULL. Need to figure out how to handle those nodes. $rc = (new Zmodem)->zmodem_receive($this->client,$zap,$this->recv,$this->node->address); @@ -1165,7 +1169,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface */ private function wazoosend(int $zap): bool { - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$zap)); + Log::debug(sprintf('%s:+ wazoosend [%d]',self::LOGKEY,$zap)); // See if there is anything to add to the outbound // Add our mail to the queue if we have authenticated @@ -1179,7 +1183,7 @@ final class EMSI extends BaseProtocol implements CRCInterface,ZmodemInterface if (! $z->zmodem_sendinit($this->client,$zap) && $this->send->total_count) $z->zmodem_sendfile($this->send); - Log::debug(sprintf('%s: - Finished sending',__METHOD__)); + Log::debug(sprintf('%s:- Finished sending',self::LOGKEY)); return ($z->zmodem_senddone()<0); } -} +} \ No newline at end of file diff --git a/app/Classes/Protocol/Zmodem.php b/app/Classes/Protocol/Zmodem.php index 7d04da5..e1ebfce 100644 --- a/app/Classes/Protocol/Zmodem.php +++ b/app/Classes/Protocol/Zmodem.php @@ -16,6 +16,8 @@ use App\Traits\CRC as CRCTrait; final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface { + private const LOGKEY = 'Z--'; + use CRCTrait; /* ZModem constants */ @@ -204,9 +206,13 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface { // If our parent returns a PID, we've forked if (! parent::onConnect($client)) { + Log::withContext(['pid'=>getmypid()]); + $this->session(self::SESSION_ZMODEM,$client); $this->client->close(); - Log::info(sprintf('%s: = End - Connection closed [%s]',__METHOD__,$client->address_remote)); + + Log::info(sprintf('%s:= onConnect - Connection closed [%s]',self::LOGKEY,$client->address_remote)); + exit(0); } return NULL; @@ -235,7 +241,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ! Strange cancap [%d]',__METHOD__,$canzap)); + Log::error(sprintf('%s: ! init Strange cancap [%d]',self::LOGKEY,$canzap)); } /* Maximum block size -- by protocol, may be reduced by window size later */ @@ -256,6 +262,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface public function protocol_init(): int { // Not used + return 0; } /** @@ -291,7 +298,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ public function zmodem_receive(SocketClient $client,int $canzap,Receive $recv,Address $ao): int { - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$canzap)); + Log::debug(sprintf('%s:+ zmodem_receive [%d]',self::LOGKEY,$canzap)); $opts = $this->init($client,$canzap); @@ -303,17 +310,17 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface switch ($rc=$this->ls_zrecvfinfo(self::ZRINIT,($this->ls_Protocol&self::LSZ_OPTFIRSTBATCH) ? 1 : 0)) { case self::ZFIN: - Log::debug(sprintf('%s: = ZFIN after INIT, empty batch',__METHOD__)); + Log::debug(sprintf('%s:= zmodem_receive ZFIN after INIT, empty batch',self::LOGKEY)); $this->ls_zdonereceiver(); return self::LSZ_OK; case self::ZFILE: - Log::debug(sprintf('%s: = ZFILE after INIT',__METHOD__)); + Log::debug(sprintf('%s: = zmodem_receive ZFILE after INIT',self::LOGKEY)); break; default: - Log::error(sprintf('%s: ! Something strange after init [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:! zmodem_receive Something strange after init [%d]',self::LOGKEY,$rc)); $this->ls_zabort(); $this->ls_zdonereceiver(); @@ -324,59 +331,59 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface while (TRUE) { switch ($rc) { case self::ZFIN: - Log::debug(sprintf('%s: = ZFIN',__METHOD__)); + Log::debug(sprintf('%s:= zmodem_receive ZFIN',self::LOGKEY)); $this->ls_zdonereceiver(); return self::LSZ_OK; case self::ZFILE: if (! $this->recv->to_get) { - Log::error(sprintf('%s: ! No files to get?',__METHOD__)); + Log::error(sprintf('%s: ! zmodem_receive No files to get?',self::LOGKEY)); $frame = self::ZSKIP; } else { switch ($this->recv->open($ao)) { case self::FOP_SKIP: - Log::info(sprintf('%s: = Skip this file [%s]',__METHOD__,$this->recv->name)); + Log::info(sprintf('%s: = zmodem_receive Skip this file [%s]',self::LOGKEY,$this->recv->name)); $frame = self::ZSKIP; break; case self::FOP_SUSPEND: - Log::info(sprintf('%s: = Suspend this file [%s]',__METHOD__,$this->recv->name)); + Log::info(sprintf('%s: = zmodem_receive Suspend this file [%s]',self::LOGKEY,$this->recv->name)); $frame = self::ZFERR; break; case self::FOP_CONT: case self::FOP_OK: - Log::info(sprintf('%s: = Receving [%s] from [%d]',__METHOD__,$this->recv->name,$this->recv->filepos)); + Log::info(sprintf('%s: = zmodem_receive Receving [%s] from [%d]',self::LOGKEY,$this->recv->name,$this->recv->filepos)); $frame = self::ZRINIT; switch (($rc=$this->ls_zrecvfile($recv->filepos))) { case self::ZFERR: - Log::debug(sprintf('%s: = ZFERR',__METHOD__)); + Log::debug(sprintf('%s: = zmodem_receive ZFERR',self::LOGKEY)); $this->recv->close(); $frame = self::ZFERR; break; case self::ZSKIP: - Log::debug(sprintf('%s: = ZSKIP',__METHOD__)); + Log::debug(sprintf('%s: = zmodem_receive ZSKIP',self::LOGKEY)); $this->recv->close(); $frame = self::ZSKIP; break; case self::LSZ_OK: - Log::debug(sprintf('%s: = OK',__METHOD__)); + Log::debug(sprintf('%s: = zmodem_receive OK',self::LOGKEY)); $this->recv->close(); break; default: - Log::error(sprintf('%s: ! OTHER [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:! zmodem_receive OTHER [%d]',self::LOGKEY,$rc)); $this->recv->close(); return self::LSZ_ERROR; @@ -389,7 +396,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; case self::ZABORT: - Log::debug(sprintf('%s: = ZABORT',__METHOD__)); + Log::debug(sprintf('%s:= zmodem_receive ZABORT',self::LOGKEY)); $this->ls_zabort(); $this->ls_zdonereceiver(); @@ -397,7 +404,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return self::LSZ_ERROR; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? zmodem_receive Something strange [%d]',self::LOGKEY,$rc)); $this->ls_zabort(); $this->ls_zdonereceiver(); @@ -447,7 +454,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? zmodem_senddone Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -457,7 +464,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while ($trys < 10); - Log::error(sprintf('%s: ? Something strange or timeeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? zmodem_senddone Something strange or timeeout [%d]',self::LOGKEY,$rc)); return $rc; } @@ -470,7 +477,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ public function zmodem_sendinit(SocketClient $client,int $canzap): int { - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$canzap)); + Log::debug(sprintf('%s:+ zmodem_sendinit [%d]',self::LOGKEY,$canzap)); $this->init($client,$canzap); @@ -487,7 +494,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface ($this->ls_Protocol&self::LSZ_OPTESCAPEALL) ? ',ESCALL' : '' )); - Log::debug(sprintf('%s: = End [%x]',__METHOD__,$rc)); + Log::debug(sprintf('%s:= zmodem_sendinit [%x]',self::LOGKEY,$rc)); return $rc; } @@ -499,7 +506,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ public function zmodem_sendfile(Send $send): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ zmodem_sendfile',self::LOGKEY)); while ($send->total_count && $send->open()) { try { @@ -524,7 +531,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return $rc; } catch (\Exception $e) { - Log::error(sprintf('%s: ! Error [%s]',__METHOD__,$e->getMessage())); + Log::error(sprintf('%s: ! Error [%s]',self::LOGKEY,$e->getMessage())); } } @@ -840,7 +847,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zdonereceiver(): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ ls_zdonereceiver',self::LOGKEY)); $trys = 0; $retransmit = 1; @@ -866,12 +873,12 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface case self::XON|0x80: case self::XOFF|0x80: if ($this->DEBUG) - Log::debug(sprintf('%s: - XON/XOFF, skip it',__METHOD__)); + Log::debug(sprintf('%s: - ls_zdonereceiver XON/XOFF, skip it',self::LOGKEY)); break; case self::ZPAD: if ($this->DEBUG) - Log::debug(sprintf('%s: - ZPAD',__METHOD__)); + Log::debug(sprintf('%s: - ls_zdonereceiver ZPAD',self::LOGKEY)); if (($rc=$this->ls_zrecvhdr($this->ls_rxHdr,$this->ls_HeaderTimeout)) < 0) return $rc; @@ -884,7 +891,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zdonereceiver Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -894,7 +901,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while ($trys < 10); - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zdonereceiver Something strange [%d]',self::LOGKEY,$rc)); return $rc; } @@ -907,7 +914,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zinitsender(int $window,string $attstr) { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ ls_zinitsender',self::LOGKEY)); $trys = 0; @@ -936,7 +943,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface switch ($rc=$this->ls_zrecvhdr($this->ls_rxHdr,$this->ls_HeaderTimeout)) { /* Ok, We got RINIT! */ case self::ZRINIT: - Log::debug(sprintf('%s: - ZRINIT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zinitsender ZRINIT',self::LOGKEY)); $this->rxOptions= (($this->ls_rxHdr[self::LSZ_F1]&0xff)<<8)|($this->ls_rxHdr[self::LSZ_F0]&0xff); @@ -967,7 +974,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface if ($window && (! $this->ls_txWinSize || ($this->ls_txWinSize > $window))) $this->ls_txWinSize = $window; - Log::debug(sprintf('%s: - ZRINIT OK - effproto [%08x], winsize [%d]',__METHOD__,$this->ls_Protocol,$this->ls_txWinSize)); + Log::debug(sprintf('%s: - ls_zinitsender ZRINIT OK - effproto [%08x], winsize [%d]',self::LOGKEY,$this->ls_Protocol,$this->ls_txWinSize)); /* Ok, now we could calculate real max frame size and initial block size */ if ($this->ls_txWinSize && $this->ls_MaxBlockSize>$this->ls_txWinSize) { @@ -1001,7 +1008,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface if ($this->ls_txCurBlockSize>$this->ls_MaxBlockSize) $this->ls_txCurBlockSize=$this->ls_MaxBlockSize; - Log::debug(sprintf('%s: - ZRINIT OK - block sizes Max [%d] Current [%d]',__METHOD__,$this->ls_MaxBlockSize,$this->ls_txCurBlockSize)); + Log::debug(sprintf('%s: - ls_zinitsender ZRINIT OK - block sizes Max [%d] Current [%d]',self::LOGKEY,$this->ls_MaxBlockSize,$this->ls_txCurBlockSize)); /* Send ZSINIT, if we need it */ if ($attstr || (! ($this->rxOptions&self::LSZ_RXWNTESCCTL) && ($this->ls_Protocol&self::LSZ_OPTESCAPEALL))) @@ -1012,7 +1019,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* Return number to peer, he is paranoid */ case self::ZCHALLENGE: - Log::debug(sprintf('%s: - CHALLENGE',__METHOD__)); + Log::debug(sprintf('%s: - ls_zinitsender CHALLENGE',self::LOGKEY)); if (($rc=$this->ls_zsendhhdr(ZACK,$this->ls_rxHdr)) < 0) return $rc; @@ -1028,7 +1035,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* ZFIN from previous session? Or may be real one? */ case self::ZFIN: - Log::debug(sprintf('%s: - ZFIN [%d]',__METHOD__,$zfins)); + Log::debug(sprintf('%s: - ls_zinitsender ZFIN [%d]',self::LOGKEY,$zfins)); if (++$zfins == self::LSZ_TRUSTZFINS) return self::LSZ_ERROR; @@ -1037,20 +1044,20 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* Please, resend */ case self::LSZ_BADCRC: - Log::debug(sprintf('%s: - LSZ_BADCRC',__METHOD__)); + Log::debug(sprintf('%s: - ls_zinitsender LSZ_BADCRC',self::LOGKEY)); /* We don't support it! */ case self::ZCOMMAND: - Log::debug(sprintf('%s: - ZCOMMAND',__METHOD__)); + Log::debug(sprintf('%s: - ls_zinitsender ZCOMMAND',self::LOGKEY)); $this->ls_zsendhhdr(ZNAK,$this->ls_storelong(0)); /* Abort this session -- we trust in ABORT! */ case self::ZABORT: - Log::debug(sprintf('%s: - ZABORT',__METHOD__)); + Log::debug(sprintf('%s:- ls_zinitsender ZABORT',self::LOGKEY)); return self::LSZ_ERROR; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zinitsender Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -1058,7 +1065,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while ($trys < 10); - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zinitsender Something strange or timeout [%d]',self::LOGKEY,$rc)); return $rc; } @@ -1074,7 +1081,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface private function ls_zrecvdata16(string &$data,int &$len,int $timeout): int { if ($this->DEBUG) - Log::debug('+ Start',['m'=>__METHOD__,'d'=>$data]); + Log::debug(sprintf('%s:+ ls_zrecvdata16',self::LOGKEY),['d'=>$data]); $got = 0; /* Bytes total got */ $crc = 0; /* Received CRC */ @@ -1083,7 +1090,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface while ($rcvdata && (($c = $this->ls_readzdle($timeout)) >= 0)) { if ($this->DEBUG) - Log::debug(sprintf(' - got [%x] (%c)',$c,($c<31 ? 32 : $c)),['m'=>__METHOD__,'c'=>serialize($c)]); + Log::debug(sprintf('%s: - ls_zrecvdata16 got [%x] (%c)',self::LOGKEY,$c,($c<31 ? 32 : $c)),['c'=>serialize($c)]); if ($c < 256) { $data .= chr($c&0xff); @@ -1110,7 +1117,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* We finish loop by error in ls_readzdle() */ if ($rcvdata) { - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zrecvdata16 Something strange or timeout [%d]',self::LOGKEY,$rc)); return $c; } @@ -1129,7 +1136,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $incrc = crc16($data.chr($frametype)); if ($this->DEBUG) - Log::debug(sprintf('CRC%d got %08x - calculated %08x',16,$incrc,$crc),['m'=>__METHOD__]); + Log::debug(sprintf('%s: - ls_zrecvdata16 CRC%d got %08x - calculated %08x',self::LOGKEY,16,$incrc,$crc),['m'=>__METHOD__]); if ($incrc != $crc) return self::LSZ_BADCRC; @@ -1137,7 +1144,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $len = $got; if ($this->DEBUG) - Log::debug('= End',['m'=>__METHOD__,'frametype'=>$frametype]); + Log::debug(sprintf('%s:= ls_zrecvdata16 - frametype [%d]',self::LOGKEY,$frametype)); return $frametype; } @@ -1153,7 +1160,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface private function ls_zrecvdata32(string &$data,int &$len,int $timeout): int { if ($this->DEBUG) - Log::debug('+ Start',['m'=>__METHOD__,'d'=>$data]); + Log::debug(sprintf('%s:+ ls_zrecvdata32',self::LOGKEY),['d'=>$data]); $got = 0; /* Bytes total got */ $crc = 0; /* Received CRC */ @@ -1162,7 +1169,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface while ($rcvdata && (($c=$this->ls_readzdle($timeout)) >= 0)) { if ($this->DEBUG) - Log::debug(sprintf(' - got [%x] (%c)',$c,($c<31 ? 32 : $c)),['m'=>__METHOD__,'c'=>serialize($c)]); + Log::debug(sprintf('%s: - ls_zrecvdata32 got [%x] (%c)',self::LOGKEY,$c,($c<31 ? 32 : $c)),['c'=>serialize($c)]); if ($c < 256) { $data .= chr($c&0xff); @@ -1189,7 +1196,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* We finish loop by error in ls_readzdle() */ if ($rcvdata) { - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zrecvdata32 Something strange or timeout [%d]',self::LOGKEY,$rc)); return $c; } @@ -1214,7 +1221,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $incrc = crc32($data.chr($frametype)); if ($this->DEBUG) - Log::debug(sprintf('CRC%d got %08x - calculated %08x',32,$incrc,$crc),['m'=>__METHOD__]); + Log::debug(sprintf('%s: - ls_zrecvdata32 CRC%d got %08x - calculated %08x',self::LOGKEY,32,$incrc,$crc)); if ($incrc != $crc) return self::LSZ_BADCRC; @@ -1222,7 +1229,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $len = $got; if ($this->DEBUG) - Log::debug('= End',['m'=>__METHOD__,'frametype'=>$frametype]); + Log::debug(sprintf('%s:= ls_zrecvdata32 - frametype [%d]',self::LOGKEY,$frametype)); return $frametype; } @@ -1236,7 +1243,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zrecvfile(int $pos): int { - Log::debug('+ Start',['m'=>__METHOD__,'pos'=>$pos]); + Log::debug(sprintf('%s:+ ls_zrecvfile - pos [%d]',self::LOGKEY,$pos)); $needzdata = 1; $len = 0; @@ -1254,7 +1261,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $needzdata = 1; case self::ZCRCG: - Log::debug(sprintf('%s: - ZCRC%s, [%d] bytes at [%d]',__METHOD__,($rc==self::ZCRCE ? 'E' : 'G'),$len,$rxpos)); + Log::debug(sprintf('%s: - ls_zrecvfile ZCRC%s, [%d] bytes at [%d]',self::LOGKEY,($rc==self::ZCRCE ? 'E' : 'G'),$len,$rxpos)); $rxpos += $len; @@ -1269,7 +1276,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $needzdata = 1; case self::ZCRCQ: - Log::debug(sprintf('%s: - ZCRC%s, [%d] bytes at [%d]',__METHOD__,($rc==self::ZCRCW ? 'W' : 'Q'),$len,$rxpos)); + Log::debug(sprintf('%s: - ls_zrecvfile ZCRC%s, [%d] bytes at [%d]',self::LOGKEY,($rc==self::ZCRCW ? 'W' : 'Q'),$len,$rxpos)); $rxpos += $len; @@ -1296,7 +1303,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zrecvfile Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -1313,13 +1320,13 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* We need new position -- ZDATA (and may be ZEOF) */ } else { - Log::debug(sprintf('%s: - Want ZDATA/ZEOF at [%d]',__METHOD__,$rxpos)); + Log::debug(sprintf('%s: - ls_zrecvfile Want ZDATA/ZEOF at [%d]',self::LOGKEY,$rxpos)); if (($rc=$this->ls_zrecvnewpos($rxpos,$newpos)) < 0) return $rc; if ($newpos != $rxpos) { - Log::error(sprintf('%s: - Bad new position [%d] in [%d]',__METHOD__,$newpos,$rc)); + Log::error(sprintf('%s: - ls_zrecvfile Bad new position [%d] in [%d]',self::LOGKEY,$newpos,$rc)); if ($this->ls_rxAttnStr) { $this->client->buffer_add($this->ls_rxAttnStr); @@ -1333,7 +1340,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } else { if ($rc == self::ZEOF) { - Log::debug(sprintf('%s: - ZEOF',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfile ZEOF',self::LOGKEY)); if (($rc=$this->ls_zsendhhdr(self::ZRINIT,$this->ls_storelong(0))) < 0) return $rc; @@ -1341,7 +1348,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return self::LSZ_OK; } - Log::debug(sprintf('%s: - ZDATA',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfile ZDATA',self::LOGKEY)); $needzdata = 0; } } @@ -1362,7 +1369,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zrecvfinfo(int $frame,int $first): int { - Log::debug(sprintf('%s: + Start - Frame [%d], First [%d]',__METHOD__,$frame,$first)); + Log::debug(sprintf('%s:+ ls_zrecvfinfo - Frame [%d], First [%d]',self::LOGKEY,$frame,$first)); $trys = 0; $retransmit = ($frame != self::ZRINIT); @@ -1391,7 +1398,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return $rc; } - Log::debug(sprintf('%s: - ZRINIT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZRINIT',self::LOGKEY)); $txHdr = []; $txHdr[self::LSZ_P0] = ($win&0xff); @@ -1409,22 +1416,22 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface switch (($rc=$this->ls_zrecvhdr($this->ls_rxHdr,$this->ls_HeaderTimeout))) { /* Send ZRINIT again */ case self::ZRQINIT: - Log::debug(sprintf('%s: - ZRQINIT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZRQINIT',self::LOGKEY)); /* We will trust in first ZFIN after ZRQINIT */ $first = 1; case self::ZNAK: - Log::debug(sprintf('%s: - ZNAK',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZNAK',self::LOGKEY)); case self::LSZ_TIMEOUT: - Log::debug(sprintf('%s: - LSZ_TIMEOUT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo LSZ_TIMEOUT',self::LOGKEY)); $retransmit = 1; break; /* He want to set some options */ case self::ZSINIT: - Log::debug(sprintf('%s: - ZSINIT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZSINIT',self::LOGKEY)); if (($rc=$this->ls_zrecvcrcw($this->rxbuf,$len)) < 0) return $rc; @@ -1452,7 +1459,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* Ok, File started! */ case self::ZFILE: - Log::debug(sprintf('%s: - ZFILE',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZFILE',self::LOGKEY)); if (($rc=$this->ls_zrecvcrcw($this->rxbuf,$len)) < 0) return $rc; @@ -1471,7 +1478,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $filesleft, // @todo Should track this $bytesleft) < 2) { - Log::error(sprintf('%s: ! File info is corrupted [%s]',__METHOD__,$this->rxbuf)); + Log::error(sprintf('%s: ! ls_zrecvfinfo File info is corrupted [%s]',self::LOGKEY,$this->rxbuf)); $filesleft = -1; } else { @@ -1489,7 +1496,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* ZFIN from previous session? Or may be real one? */ case self::ZFIN: - Log::debug(sprintf('%s: - ZFIN [%d], first [%d]',__METHOD__,$zfins,$first)); + Log::debug(sprintf('%s: - ls_zrecvfinfo ZFIN [%d], first [%d]',self::LOGKEY,$zfins,$first)); if ($first || (++$zfins == self::LSZ_TRUSTZFINS)) return self::ZFIN; @@ -1498,11 +1505,11 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* Abort this session -- we trust in ABORT! */ case self::ZABORT: - Log::debug(sprintf('%s: - ZABORT',__METHOD__)); + Log::debug(sprintf('%s:- ls_zrecvfinfo ZABORT',self::LOGKEY)); return self::ZABORT; case self::LSZ_BADCRC: - Log::debug(sprintf('%s: - BADCRC',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvfinfo BADCRC',self::LOGKEY)); $this->ls_zsendhhdr(self::ZNAK,$this->ls_storelong(0)); $retransmit = 1; @@ -1510,7 +1517,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zrecvfinfo Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -1520,14 +1527,14 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while ($trys < 10); - Log::error(sprintf('%s: ? Something strange or timeout',__METHOD__)); + Log::error(sprintf('%s:? ls_zrecvfinfo Something strange or timeout',self::LOGKEY)); return self::LSZ_TIMEOUT; } private function ls_zrecvhdr(array &$hdr,int $timeout): int { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start with [%d] timeout',__METHOD__,$timeout)); + Log::debug(sprintf('%s:+ ls_zrecvhdr with [%d] timeout',self::LOGKEY,$timeout)); $state = self::rhInit; $readmode = self::rm7BIT; @@ -1544,7 +1551,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface if ($state == self::rhInit) { if ($this->DEBUG) - Log::debug(sprintf('%s: - Init State',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvhdr Init State',self::LOGKEY)); $frametype = self::LSZ_ERROR; $crc = 0; @@ -1558,7 +1565,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface while ($rc = $this->client->hasData($timeout)) { if ($this->DEBUG) - Log::debug(sprintf('%s: - hasData - readmode [%d] - Garbage [%d]',__METHOD__,$readmode,$garbage)); + Log::debug(sprintf('%s: - ls_zrecvhdr hasData - readmode [%d] - Garbage [%d]',self::LOGKEY,$readmode,$garbage)); switch ($readmode) { case self::rm8BIT: @@ -1576,7 +1583,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } if ($this->DEBUG) - Log::debug(sprintf('%s: - %s [%x] (%c)',__METHOD__,$readmode,$c,$c)); + Log::debug(sprintf('%s: - ls_zrecvhdr %s [%x] (%c)',self::LOGKEY,$readmode,$c,$c)); /* Here is error */ if ($c < 0) @@ -1586,7 +1593,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $c &= 0xff; if ($this->DEBUG) - Log::debug(sprintf('%s: = %x',__METHOD__,$c),['state'=>$state]); + Log::debug(sprintf('%s: = ls_zrecvhdr %x (%d)',self::LOGKEY,$c,$state)); switch ($state) { case self::rhInit: @@ -1694,7 +1701,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface case self::rhBYTE: if ($this->DEBUG) - Log::debug(sprintf('%s: - [%02x] (%d)',__METHOD__,$c,$got)); + Log::debug(sprintf('%s: - ls_zrecvhdr [%02x] (%d)',self::LOGKEY,$c,$got)); $hdr[$got] = $c; @@ -1707,7 +1714,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface case self::rhCRC: if ($this->DEBUG) - Log::debug(sprintf('%s: - [%02x] (%d|%d)',__METHOD__,$c,$crcgot+1,$got)); + Log::debug(sprintf('%s: - ls_zrecvhdr [%02x] (%d|%d)',self::LOGKEY,$c,$crcgot+1,$got)); if ($crcl == 2) { $crc <<= 8; @@ -1724,7 +1731,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface if ($crcl == 2) { if (($this->ls_Protocol&self::LSZ_OPTCRC32) && ($readmode != self::rmHEX)) - Log::error(sprintf('%s: - was CRC32, got CRC16 binary header',__METHOD__)); + Log::error(sprintf('%s: - ls_zrecvhdr was CRC32, got CRC16 binary header',self::LOGKEY)); $crc &= 0xffff; @@ -1733,14 +1740,14 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } else { if (! ($this->ls_Protocol&self::LSZ_OPTCRC32)) - Log::error(sprintf('s: - was CRC16, got CRC32 binary header',__METHOD__)); + Log::error(sprintf('%s: - ls_zrecvhdr was CRC16, got CRC32 binary header',self::LOGKEY)); $incrc = $this->CRC32_FINISH($incrc); $this->ls_Protocol |= self::LSZ_OPTCRC32; } if ($this->DEBUG) - Log::debug(sprintf('%s: - CRC%d got %08x - calculated %08x',__METHOD__,(($crcl==2) ? 16 : 32),$incrc,$crc)); + Log::debug(sprintf('%s: - ls_zrecvhdr CRC%d got %08x - calculated %08x',self::LOGKEY,(($crcl==2) ? 16 : 32),$incrc,$crc)); if ($incrc != $crc) return self::LSZ_BADCRC; @@ -1765,7 +1772,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface case self::CR: case self::CR|0x80: if ($this->DEBUG) - Log::debug(sprintf('%s: ? rhCR, ignoring any remaining chars [%d]',__METHOD__,$c)); + Log::debug(sprintf('%s:? ls_zrecvhdr rhCR, ignoring any remaining chars [%d]',self::LOGKEY,$c)); /* At this point, most implementations ignore checking for the remaining chars */ return $frametype; @@ -1779,12 +1786,12 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface case self::XON: case self::XON|0x80: if ($this->DEBUG) - Log::debug(sprintf('%s: ? rhCR, got XON without CR/LF [%d]',__METHOD__,$c)); + Log::debug(sprintf('%s:? ls_zrecvhdr rhCR, got XON without CR/LF [%d]',self::LOGKEY,$c)); return $frametype; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$c)); + Log::error(sprintf('%s:? ls_zrecvhdr Something strange [%d]',self::LOGKEY,$c)); return self::LSZ_BADCRC; } @@ -1800,7 +1807,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$c)); + Log::error(sprintf('%s:? ls_zrecvhdr Something strange [%d]',self::LOGKEY,$c)); return self::LSZ_BADCRC; } @@ -1810,7 +1817,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $state = self::rhInit; if ($this->DEBUG) - Log::debug(sprintf('%s: rhXON',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvhdr rhXON',self::LOGKEY)); switch ($c) { case self::ZPAD: @@ -1825,7 +1832,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return $frametype; default: - Log::error(sprintf('%s: ! rhXON unexpcted [%d]',__METHOD__,$c)); + Log::error(sprintf('%s:! ls_zrecvhdr rhXON unexpcted [%d]',self::LOGKEY,$c)); return self::LSZ_BADCRC; } @@ -1833,7 +1840,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } } - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zrecvhdr Something strange or timeout [%d]',self::LOGKEY,$rc)); return $rc; } @@ -1855,17 +1862,17 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface return self::LSZ_OK; case self::LSZ_BADCRC: - Log::debug(sprintf('%s: - got BADCRC',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvcrcw got BADCRC',self::LOGKEY)); $this->ls_zsendhhdr(self::ZNAK,$this->ls_storelong(0)); return 1; case self::LSZ_TIMEOUT: - Log::debug(sprintf('%s: - got TIMEOUT',__METHOD__)); + Log::debug(sprintf('%s: - ls_zrecvcrcw got TIMEOUT',self::LOGKEY)); break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zrecvcrcw Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -1916,7 +1923,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zrecvnewpos Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -1926,7 +1933,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while (++$trys < 10); - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zrecvnewpos Something strange or timeout [%d]',self::LOGKEY,$rc)); return self::LSZ_TIMEOUT; } @@ -1940,11 +1947,11 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zrpos(Send $send,int $newpos): int { - Log::debug(sprintf('%s: + Start, newpos [%d]',__METHOD__,$newpos)); + Log::debug(sprintf('%s:+ ls_zrpos, newpos [%d]',self::LOGKEY,$newpos)); if ($newpos == $this->ls_txLastRepos) { if (++$this->ls_txReposCount > 10) { - Log::error(sprintf('%s: ! ZRPOS to [%ld] limit reached',__METHOD__,$newpos)); + Log::error(sprintf('%s:! ZRPOS to [%ld] limit reached',self::LOGKEY,$newpos)); return self::LSZ_ERROR; } @@ -1958,7 +1965,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $this->ls_txLastACK = $newpos; if (! $send->seek($newpos)) { - Log::error(sprintf('%s: ! ZRPOS to [%ld] seek error',__METHOD__,$send->filepos)); + Log::error(sprintf('%s:! ZRPOS to [%ld] seek error',self::LOGKEY,$send->filepos)); return self::LSZ_ERROR; } @@ -1980,11 +1987,11 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zsenddata(string $data,int $frame): int { - Log::debug(sprintf('%s: + Start [%d] (%d)',__METHOD__,strlen($data),$frame)); + Log::debug(sprintf('%s:+ ls_zsenddata [%d] (%d)',self::LOGKEY,strlen($data),$frame)); if ($this->ls_Protocol&self::LSZ_OPTCRC32) { if ($this->DEBUG) - Log::debug(sprintf('%s: - CRC32',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsenddata CRC32',self::LOGKEY)); for ($n=0;$nls_sendchar(ord($data[$n])); @@ -2013,7 +2020,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } else { if ($this->DEBUG) - Log::debug(sprintf('%s: - CRC16',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsenddata CRC16',self::LOGKEY)); for ($n=0;$nls_sendchar(ord($data[$n])); @@ -2052,7 +2059,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zsendbhdr(int $frametype,array $hdr): int { - Log::debug(sprintf('%s: + Start',__METHOD__)); + Log::debug(sprintf('%s:+ ls_zsendbhdr',self::LOGKEY)); $crc = $this->LSZ_INIT_CRC(); @@ -2113,7 +2120,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface */ private function ls_zsendfile(Send $send,int $sernum,int $fileleft,int $bytesleft): int { - Log::debug(sprintf('%s: + Start [%s]',__METHOD__,$send->name)); + Log::debug(sprintf('%s:+ ls_zsendfile [%s]',self::LOGKEY,$send->name)); $trys = 0; $needack = 0; @@ -2121,7 +2128,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface switch (($rc = $this->ls_zsendfinfo($send,$sernum,$send->filepos,$fileleft,$bytesleft))) { /* Ok, It's OK! */ case self::ZRPOS: - Log::debug(sprintf('%s: - ZRPOS to [%d]',__METHOD__,$send->filepos)); + Log::debug(sprintf('%s: - ls_zsendfile ZRPOS to [%d]',self::LOGKEY,$send->filepos)); break; /* Skip it */ @@ -2129,13 +2136,13 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* Suspend it */ case self::ZFERR: // @todo Mark the file as skipped - Log::debug(sprintf('%s: - ZSKIP/ZFERR',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsendfile ZSKIP/ZFERR',self::LOGKEY)); return $rc; case self::ZABORT: /* Session is aborted */ case self::ZFIN: - Log::debug(sprintf('%s: - ZABORT/ZFIN',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsendfile ZABORT/ZFIN',self::LOGKEY)); $this->ls_zsendhhdr(self::ZFIN,$this->ls_storelong(0)); return self::LSZ_ERROR; @@ -2144,7 +2151,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface if ($rc < 0) return $rc; - Log::debug(sprintf('%s: - Strange answer on ZFILE: %d',__METHOD__,$rc)); + Log::debug(sprintf('%s:- ls_zsendfile Strange answer on ZFILE [%d]',self::LOGKEY,$rc)); return self::LSZ_ERROR; } @@ -2161,7 +2168,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* We need to send ZDATA if previous frame was ZCRCW Also, frame will be ZCRCW, if it is after RPOS */ if ($frame == self::ZCRCW) { - Log::debug(sprintf('%s: - send ZDATA at [%d]',__METHOD__,$send->filepos)); + Log::debug(sprintf('%s: - ls_zsendfile send ZDATA at [%d]',self::LOGKEY,$send->filepos)); if (($rc=$this->ls_zsendbhdr(self::ZDATA,$this->ls_storelong($send->filepos))) < 0) return $rc; @@ -2172,7 +2179,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface $txbuf = $send->read($this->ls_txCurBlockSize); } catch (\Exception $e) { - Log::error(sprintf('%s: Read error')); + Log::error(sprintf('%s:! ls_zsendfile Read error',self::LOGKEY)); return self::LSZ_ERROR; } @@ -2219,28 +2226,28 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface switch (($rc=$this->ls_zrecvhdr($this->ls_rxHdr,$needack ? $this->ls_HeaderTimeout : 0))) { // @todo set timeout to 5 for debugging wtih POP /* They don't need this file */ case self::ZSKIP: - Log::debug(sprintf('%s: - ZSKIP',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsendfile ZSKIP',self::LOGKEY)); /* Problems occured -- suspend file */ case self::ZFERR: - Log::debug(sprintf('%s: - ZFERR',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsendfile ZFERR',self::LOGKEY)); return $rc; /* Ok, position ACK */ case self::ZACK: $this->ls_txLastACK = $this->ls_fetchlong($this->ls_rxHdr); - Log::debug(sprintf('%s: - ZACK',__METHOD__),['ls_rxHdr'=>$this->ls_rxHdr,'ls_txLastACK'=>$this->ls_txLastACK,'ls_rxHdr'=>$this->ls_rxHdr]); + Log::debug(sprintf('%s: - ls_zsendfile ZACK',self::LOGKEY),['ls_rxHdr'=>$this->ls_rxHdr,'ls_txLastACK'=>$this->ls_txLastACK,'ls_rxHdr'=>$this->ls_rxHdr]); break; /* Repos */ case self::ZRPOS: - Log::debug(sprintf('%s: - ZRPOS',__METHOD__)); + Log::debug(sprintf('%s: - ZRPOS',self::LOGKEY)); if (($rc=$this->ls_zrpos($send,$this->ls_fetchlong($this->ls_rxHdr))) < 0) return $rc; - Log::debug(sprintf('%s: - ZRPOS [%d]',__METHOD__,$rc)); + Log::debug(sprintf('%s: - ZRPOS [%d]',self::LOGKEY,$rc)); /* Force to retransmit ZDATA */ $frame = self::ZCRCW; @@ -2265,7 +2272,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zsendfile Something strange [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -2324,7 +2331,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface /* ACK for data -- it lost! */ case self::ZACK: - Log::debug(sprintf('%s: - ZACK after EOF',__METHOD__)); + Log::debug(sprintf('%s: - ls_zsendfile ZACK after EOF',self::LOGKEY)); $this->ls_txLastACK = $this->ls_fetchlong($this->ls_rxHdr); break; @@ -2344,7 +2351,7 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface break; default: - Log::error(sprintf('%s: ? Something strange after ZEOF [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s: ? ls_zsendfile Something strange after ZEOF [%d]',self::LOGKEY,$rc)); if ($rc < 0) return $rc; @@ -2355,14 +2362,14 @@ final class Zmodem extends Protocol implements CRCInterface,ZmodemInterface } while ($send->feof() && $trys < 10); if ($send->feof()) { - Log::error(sprintf('%s: ! To many tries waiting for ZEOF ACK',__METHOD__)); + Log::error(sprintf('%s:! ls_zsendfile To many tries waiting for ZEOF ACK',self::LOGKEY)); return self::LSZ_ERROR; } } } - Log::error(sprintf('%s: ? Something strange or timeout [%d]',__METHOD__,$rc)); + Log::error(sprintf('%s:? ls_zsendfile Something strange or timeout [%d]',self::LOGKEY,$rc)); return $rc; } diff --git a/app/Classes/Sock/SocketClient.php b/app/Classes/Sock/SocketClient.php index 8419ace..e543eda 100644 --- a/app/Classes/Sock/SocketClient.php +++ b/app/Classes/Sock/SocketClient.php @@ -14,6 +14,8 @@ use Illuminate\Support\Str; * @property int speed */ final class SocketClient { + private const LOGKEY = 'SC-'; + // For deep debugging private bool $DEBUG = FALSE; @@ -53,10 +55,10 @@ final class SocketClient { private int $rx_left = 0; private string $rx_buf = ''; - public function __construct (\Socket $connection,int $speed=self::TCP_SPEED) { + public function __construct (\Socket $connection) { socket_getsockname($connection,$this->address_local,$this->port_local); socket_getpeername($connection,$this->address_remote,$this->port_remote); - Log::info(sprintf('%s: + Connection from [%s] on port [%d]',__METHOD__,$this->address_remote,$this->port_remote)); + Log::info(sprintf('%s:+ Connection from [%s] on port [%d]',self::LOGKEY,$this->address_remote,$this->port_remote)); $this->connection = $connection; } @@ -72,7 +74,7 @@ final class SocketClient { return Arr::get($this->session,$key); default: - throw new \Exception(sprintf('%s: Unknown key [%s]:',__METHOD__,$key)); + throw new \Exception(sprintf('%s:! Unknown key [%s]:',self::LOGKEY,$key)); } } @@ -83,7 +85,7 @@ final class SocketClient { return $this->session[$key] = $value; default: - throw new \Exception(sprintf('%s: Unknown key [%s]:',__METHOD__,$key)); + throw new \Exception(sprintf('%s:! Unknown key [%s]:',self::LOGKEY,$key)); } } @@ -97,7 +99,7 @@ final class SocketClient { public function buffer_add(string $data): void { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start [%s] (%d)',__METHOD__,$data,strlen($data))); + Log::debug(sprintf('%s:+ Start [%s] (%d)',self::LOGKEY,$data,strlen($data))); //$rc = self::OK; //$tx_ptr = self::TX_BUF_SIZE-$this->tx_free; @@ -107,7 +109,7 @@ final class SocketClient { while ($num_bytes) { if ($this->DEBUG) - Log::debug(sprintf('%s: - Num Bytes [%d]: TX Free [%d]',__METHOD__,$num_bytes,$this->tx_free)); + Log::debug(sprintf('%s: - Num Bytes [%d]: TX Free [%d]',self::LOGKEY,$num_bytes,$this->tx_free)); if ($num_bytes > $this->tx_free) { do { @@ -125,7 +127,7 @@ final class SocketClient { } else { if ($this->DEBUG) - Log::debug(sprintf('%s: - Remaining data to send [%d]',__METHOD__,$num_bytes)); + Log::debug(sprintf('%s: - Remaining data to send [%d]',self::LOGKEY,$num_bytes)); $this->tx_buf .= substr($data,$ptr,$num_bytes); $this->tx_free -= $num_bytes; @@ -134,7 +136,7 @@ final class SocketClient { } if ($this->DEBUG) - Log::debug(sprintf('%s: = End [%s]',__METHOD__,strlen($this->tx_buf))); + Log::debug(sprintf('%s:= End [%s]',self::LOGKEY,strlen($this->tx_buf))); } /** @@ -156,7 +158,7 @@ final class SocketClient { public function buffer_flush(int $timeout): int { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$timeout)); + Log::debug(sprintf('%s:+ Start [%d]',self::LOGKEY,$timeout)); $rc = self::OK; $tx_ptr = 0; @@ -168,9 +170,9 @@ final class SocketClient { if ($rc = $this->canSend($tv)>0) { if ($this->DEBUG) - Log::debug(sprintf('%s: - Sending [%d]',__METHOD__,$restsize)); + Log::debug(sprintf('%s: - Sending [%d]',self::LOGKEY,$restsize)); $rc = $this->send(substr($this->tx_buf,$tx_ptr,$restsize),0); - Log::debug(sprintf('%s: - Sent [%d] (%s)',__METHOD__,$rc,Str::limit($this->tx_buf,15))); + Log::debug(sprintf('%s: - Sent [%d] (%s)',self::LOGKEY,$rc,Str::limit($this->tx_buf,15))); if ($rc == $restsize) { $this->tx_buf = ''; @@ -194,7 +196,7 @@ final class SocketClient { } if ($this->DEBUG) - Log::debug(sprintf('%s: = End [%d]',__METHOD__,$rc)); + Log::debug(sprintf('%s:= End [%d]',self::LOGKEY,$rc)); return $rc; } @@ -230,7 +232,7 @@ final class SocketClient { */ public static function create(string $address,int $port,int $speed=self::TCP_SPEED): self { - Log::debug(sprintf('%s: + Creating connection to [%s:%d]',__METHOD__,$address,$port)); + Log::debug(sprintf('%s:+ Creating connection to [%s:%d]',self::LOGKEY,$address,$port)); $address = gethostbyname($address); @@ -271,7 +273,7 @@ final class SocketClient { public function read(int $timeout,int $len=1024) { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start [%d] (%d)',__METHOD__,$len,$timeout)); + Log::debug(sprintf('%s:+ Start [%d] (%d)',self::LOGKEY,$len,$timeout)); if ($timeout AND ($this->hasData($timeout) === 0)) return ''; @@ -279,7 +281,7 @@ final class SocketClient { $buf = ''; $rc = socket_recv($this->connection,$buf, $len,MSG_DONTWAIT); if ($this->DEBUG) - Log::debug(sprintf('%s: - Read [%d]',__METHOD__,$rc)); + Log::debug(sprintf('%s: - Read [%d]',self::LOGKEY,$rc)); if ($rc === FALSE) throw new SocketException($x=socket_last_error($this->connection),socket_strerror($x)); @@ -309,7 +311,7 @@ final class SocketClient { public function read_ch(int $timeout): int { if ($this->DEBUG) - Log::debug(sprintf('%s: + Start [%d]',__METHOD__,$timeout),['rx_left'=>$this->rx_left,'rx_ptr'=>$this->rx_ptr]); + Log::debug(sprintf('%s:+ Start [%d] - rx_left[%d], rx_ptr[%d]',self::LOGKEY,$timeout,$this->rx_left,$this->rx_ptr)); // If our buffer is empty, we'll try and read from the remote if ($this->rx_left == 0) { @@ -317,7 +319,7 @@ final class SocketClient { try { if (! strlen($this->rx_buf = $this->read(0,self::RX_BUF_SIZE))) { if ($this->DEBUG) - Log::debug(sprintf('%s: - Nothing read',__METHOD__)); + Log::debug(sprintf('%s: - Nothing read',self::LOGKEY)); return self::TTY_TIMEOUT; } @@ -327,7 +329,7 @@ final class SocketClient { } if ($this->DEBUG) - Log::info(sprintf('%s: - Read [%d] bytes',__METHOD__,strlen($this->rx_buf))); + Log::info(sprintf('%s: - Read [%d] bytes',self::LOGKEY,strlen($this->rx_buf))); $this->rx_ptr = 0; $this->rx_left = strlen($this->rx_buf); @@ -343,7 +345,7 @@ final class SocketClient { $this->rx_ptr++; if ($this->DEBUG) - Log::debug(sprintf('%s: = Return [%x] (%c)',__METHOD__,$rc,$rc)); + Log::debug(sprintf('%s:= Return [%x] (%c)',self::LOGKEY,$rc,$rc)); return $rc; }