From 21089d8cb12701ff0c7f405e1dc00febb53ff9a2 Mon Sep 17 00:00:00 2001
From: Rob Swindell <rob@synchro.net>
Date: Fri, 27 Nov 2020 22:01:52 -0800
Subject: [PATCH] More log output messages/detail. No functional change.
---
src/sbbs3/zmodem.c | 182 ++++++++++++++++++++++++---------------------
1 file changed, 96 insertions(+), 86 deletions(-)
mode change 100644 => 100755 src/sbbs3/zmodem.c
diff --git a/src/sbbs3/zmodem.c b/src/sbbs3/zmodem.c
old mode 100644
new mode 100755
index 2a20b30de2..4ebbb9a802
--- a/src/sbbs3/zmodem.c
+++ b/src/sbbs3/zmodem.c
@@ -571,8 +571,8 @@ int zmodem_send_data_subpkt(zmodem_t* zm, uchar subpkt_type, unsigned char * p,
int zmodem_send_data(zmodem_t* zm, uchar subpkt_type, unsigned char * p, size_t len)
{
if(!zm->frame_in_transit) { /* Start of frame, include ZDATA header */
- lprintf(zm, LOG_DEBUG, "%ld %s start of frame: %s"
- ,(long)zm->current_file_pos, __FUNCTION__, chr(subpkt_type));
+ lprintf(zm, LOG_DEBUG, "%lu %s Start of frame: %s"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, chr(subpkt_type));
zmodem_send_pos_header(zm, ZDATA, (uint32_t)zm->current_file_pos, /* Hex? */ FALSE);
}
@@ -583,7 +583,7 @@ int zmodem_send_pos_header(zmodem_t* zm, int type, int32_t pos, BOOL hex)
{
uchar header[5];
- lprintf(zm, LOG_DEBUG, "%ld %s %s", pos, __FUNCTION__, chr(type));
+ lprintf(zm, LOG_DEBUG, "%lu %s %s", (ulong)pos, __FUNCTION__, chr(type));
header[0] = type;
header[ZP0] = (uchar) (pos & 0xff);
header[ZP1] = (uchar)((pos >> 8) & 0xff);
@@ -605,31 +605,31 @@ int zmodem_send_zfin(zmodem_t* zm)
{
unsigned char zfin_header[] = { ZFIN, 0, 0, 0, 0 };
- lprintf(zm, LOG_NOTICE, "%ld Finishing Session (Sending ZFIN)", (long)zm->current_file_pos);
+ lprintf(zm, LOG_NOTICE, "%lu Finishing Session (Sending ZFIN)", (ulong)zm->current_file_pos);
return zmodem_send_hex_header(zm,zfin_header);
}
int zmodem_send_zabort(zmodem_t* zm)
{
- lprintf(zm, LOG_WARNING, "%ld Aborting Transfer (Sending ZABORT)", (long)zm->current_file_pos);
+ lprintf(zm, LOG_WARNING, "%lu Aborting Transfer (Sending ZABORT)", (ulong)zm->current_file_pos);
return zmodem_send_pos_header(zm, ZABORT, 0, /* Hex? */ TRUE);
}
int zmodem_send_znak(zmodem_t* zm)
{
- lprintf(zm, LOG_INFO, "%ld Sending ZNAK", (long)zm->current_file_pos);
+ lprintf(zm, LOG_INFO, "%lu Sending ZNAK", (ulong)zm->current_file_pos);
return zmodem_send_pos_header(zm, ZNAK, 0, /* Hex? */ TRUE);
}
int zmodem_send_zskip(zmodem_t* zm)
{
- lprintf(zm, LOG_INFO, "%ld Sending ZSKIP", (long)zm->current_file_pos);
+ lprintf(zm, LOG_INFO, "%lu Sending ZSKIP", (ulong)zm->current_file_pos);
return zmodem_send_pos_header(zm, ZSKIP, 0L, /* Hex? */ TRUE);
}
int zmodem_send_zeof(zmodem_t* zm)
{
- lprintf(zm, LOG_INFO, "%ld Sending End-of-File (ZEOF) frame (pos=%lu)", (long)zm->current_file_pos);
+ lprintf(zm, LOG_INFO, "%lu Sending End-of-File (ZEOF) frame", (ulong)zm->current_file_pos);
return zmodem_send_pos_header(zm, ZEOF, (int32_t)zm->current_file_pos, /* Hex? */ TRUE);
}
@@ -655,6 +655,7 @@ int zmodem_recv_raw(zmodem_t* zm)
return(ZCAN);
if(!is_connected(zm))
return(ABORTED);
+ lprintf(zm, LOG_ERR, "%s Received NO INPUT", __FUNCTION__);
}
if(attempt>zm->recv_timeout)
return(TIMEOUT);
@@ -663,7 +664,7 @@ int zmodem_recv_raw(zmodem_t* zm)
zm->n_cans++;
if(zm->n_cans == 5) {
zm->cancelled=TRUE;
- lprintf(zm, LOG_WARNING, "%ld Canceled remotely", (long)zm->current_file_pos);
+ lprintf(zm, LOG_WARNING, "%lu Canceled remotely", (ulong)zm->current_file_pos);
/* return(TIMEOUT); removed June-12-2005 */
}
}
@@ -702,8 +703,8 @@ int zmodem_rx(zmodem_t* zm)
case XON|0x80:
case XOFF:
case XOFF|0x80:
- lprintf(zm,LOG_WARNING, "%ld Dropping flow ctrl char: %s"
- ,(long)zm->current_file_pos, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu Dropping flow ctrl char: %s"
+ ,(ulong)zm->current_file_pos, chr(c));
continue;
default:
/*
@@ -711,8 +712,8 @@ int zmodem_rx(zmodem_t* zm)
* this one wasnt then its spurious and should be dropped.
*/
if(zm->escape_ctrl_chars && (c >= 0) && (c & 0x60) == 0) {
- lprintf(zm,LOG_WARNING, "%ld Dropping unescaped ctrl char: %s"
- ,(long)zm->current_file_pos, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu Dropping unescaped ctrl char: %s"
+ ,(ulong)zm->current_file_pos, chr(c));
continue;
}
/*
@@ -736,8 +737,8 @@ int zmodem_rx(zmodem_t* zm)
case XOFF:
case XOFF|0x80:
case ZDLE:
- lprintf(zm,LOG_WARNING, "%ld Dropping escaped flow ctrl char: %s"
- ,(long)zm->current_file_pos, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu Dropping escaped flow ctrl char: %s"
+ ,(ulong)zm->current_file_pos, chr(c));
continue;
/*
* these four are really nasty.
@@ -750,7 +751,7 @@ int zmodem_rx(zmodem_t* zm)
case ZCRCG:
case ZCRCQ:
case ZCRCW:
-// lprintf(zm,LOG_DEBUG, "%ld Encoding data subpacket type: %s", (long)zm->current_file_pos, chr(c));
+// lprintf(zm,LOG_DEBUG, "%lu Encoding data subpacket type: %s", (ulong)zm->current_file_pos, chr(c));
return (c | ZDLEESC);
case ZRUB0:
return 0x7f;
@@ -765,8 +766,8 @@ int zmodem_rx(zmodem_t* zm)
* a not escaped control character; probably
* something from a network. just drop it.
*/
- lprintf(zm,LOG_WARNING, "%ld Dropping unescaped ctrl char: %s"
- ,(long)zm->current_file_pos, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu Dropping unescaped ctrl char: %s"
+ ,(ulong)zm->current_file_pos, chr(c));
continue;
}
/*
@@ -776,8 +777,8 @@ int zmodem_rx(zmodem_t* zm)
if((c & 0x60) == 0x40) {
return c ^ 0x40;
}
- lprintf(zm,LOG_WARNING, "%ld Illegal sequence: ZDLE %s"
- ,(long)zm->current_file_pos, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu Illegal sequence: ZDLE %s"
+ ,(ulong)zm->current_file_pos, chr(c));
break;
}
break;
@@ -826,7 +827,7 @@ int zmodem_recv_data32(zmodem_t* zm, unsigned char * p, unsigned maxlen, unsigne
break;
if(*l >= maxlen) {
- lprintf(zm, LOG_ERR, "%ld subpacket OVERFLOW (%u > %u)",(long)zm->ack_file_pos, *l, maxlen);
+ lprintf(zm, LOG_ERR, "%lu Subpacket OVERFLOW (%u > %u)",(ulong)zm->ack_file_pos, *l, maxlen);
return SUBPKTOVERFLOW;
}
crc = ucrc32(c,crc);
@@ -846,12 +847,12 @@ int zmodem_recv_data32(zmodem_t* zm, unsigned char * p, unsigned maxlen, unsigne
rxd_crc |= zmodem_rx(zm) << 24;
if(rxd_crc != crc) {
- lprintf(zm,LOG_WARNING, "%ld %s CRC ERROR (%08lX, expected: %08lX) Bytes=%u, subpacket type=%s"
- ,(long)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc, *l, chr(subpkt_type));
+ lprintf(zm,LOG_WARNING, "%lu %s CRC ERROR (%08lX, expected: %08lX) Bytes=%u, subpacket type=%s"
+ ,(ulong)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc, *l, chr(subpkt_type));
return CRCFAILED;
}
- lprintf(zm,LOG_DEBUG, "%ld %s GOOD CRC: %08lX (Bytes=%u, subpacket type=%s)"
- ,(long)zm->ack_file_pos, __FUNCTION__, crc, *l, chr(subpkt_type));
+// lprintf(zm,LOG_DEBUG, "%lu %s GOOD CRC: %08lX (Bytes=%u, subpacket type=%s)"
+// ,(ulong)zm->ack_file_pos, __FUNCTION__, crc, *l, chr(subpkt_type));
zm->ack_file_pos += *l;
@@ -893,12 +894,12 @@ int zmodem_recv_data16(zmodem_t* zm, register unsigned char* p, unsigned maxlen,
rxd_crc |= zmodem_rx(zm);
if(rxd_crc != crc) {
- lprintf(zm,LOG_WARNING, "%ld %s CRC ERROR (%04hX, expected: %04hX) Bytes=%u, subpacket type=%s"
- ,(long)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc, *l, chr(subpkt_type));
+ lprintf(zm,LOG_WARNING, "%lu %s CRC ERROR (%04hX, expected: %04hX) Bytes=%u, subpacket type=%s"
+ ,(ulong)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc, *l, chr(subpkt_type));
return CRCFAILED;
}
- lprintf(zm,LOG_DEBUG, "%ld %s GOOD CRC: %04hX (Bytes=%d, subpacket type=%s)"
- ,(long)zm->ack_file_pos, __FUNCTION__, crc, *l, chr(subpkt_type));
+// lprintf(zm,LOG_DEBUG, "%lu %s GOOD CRC: %04hX (Bytes=%d, subpacket type=%s)"
+// ,(ulong)zm->ack_file_pos, __FUNCTION__, crc, *l, chr(subpkt_type));
zm->ack_file_pos += *l;
@@ -929,11 +930,11 @@ int zmodem_recv_data(zmodem_t* zm, unsigned char* p, size_t maxlen, unsigned* l,
}
if(subpkt_type <= 0) { /* e.g. TIMEOUT, SUBPKTOVERFLOW, CRCFAILED */
- lprintf(zm, LOG_WARNING, "%ld %s ERROR: %s",(long)zm->ack_file_pos, __FUNCTION__, chr(subpkt_type));
+ lprintf(zm, LOG_WARNING, "%lu %s ERROR: %s",(ulong)zm->ack_file_pos, __FUNCTION__, chr(subpkt_type));
return(subpkt_type);
}
- lprintf(zm, LOG_DEBUG, "%ld Successful receipt of subpacket type: %s", (long)zm->ack_file_pos, chr(subpkt_type));
+ lprintf(zm, LOG_DEBUG, "%lu Successful receipt of subpacket type: %s", (ulong)zm->ack_file_pos, chr(subpkt_type));
switch(subpkt_type) {
/*
@@ -962,7 +963,7 @@ int zmodem_recv_data(zmodem_t* zm, unsigned char* p, size_t maxlen, unsigned* l,
return ENDOFFRAME;
}
- lprintf(zm,LOG_WARNING, "%ld INVALID subpacket type: %s", (long)zm->ack_file_pos, chr(subpkt_type));
+ lprintf(zm,LOG_WARNING, "%lu INVALID subpacket type: %s", (ulong)zm->ack_file_pos, chr(subpkt_type));
return INVALIDSUBPKT;
}
@@ -973,7 +974,7 @@ BOOL zmodem_recv_subpacket(zmodem_t* zm, BOOL ack)
type=zmodem_recv_data(zm,zm->rx_data_subpacket,sizeof(zm->rx_data_subpacket),NULL,ack);
if(type!=FRAMEOK && type!=ENDOFFRAME) {
- lprintf(zm, LOG_ERR, "%ld %s ERROR: %s", (long)zm->ack_file_pos, __FUNCTION__, chr(type));
+ lprintf(zm, LOG_ERR, "%lu %s ERROR: %s", (ulong)zm->ack_file_pos, __FUNCTION__, chr(type));
zmodem_send_znak(zm);
return(FALSE);
}
@@ -1058,8 +1059,8 @@ BOOL zmodem_recv_bin16_header(zmodem_t* zm)
for(n=0;n<HDRLEN;n++) {
c = zmodem_rx(zm);
if(c < 0) {
- lprintf(zm, LOG_WARNING, "%ld %s ERROR: %s"
- ,(long)zm->current_file_pos, __FUNCTION__, chr(c));
+ lprintf(zm, LOG_WARNING, "%lu %s ERROR: %s"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, chr(c));
return(FALSE);
}
crc = ucrc16(c,crc);
@@ -1070,12 +1071,12 @@ BOOL zmodem_recv_bin16_header(zmodem_t* zm)
rxd_crc |= zmodem_rx(zm);
if(rxd_crc != crc) {
- lprintf(zm,LOG_WARNING, "%ld %s CRC ERROR: 0x%hX, expected: 0x%hX"
- ,(long)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc);
+ lprintf(zm,LOG_WARNING, "%lu %s CRC ERROR: 0x%hX, expected: 0x%hX"
+ ,(ulong)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc);
return(FALSE);
}
- lprintf(zm,LOG_DEBUG, "%ld %s GOOD CRC: %04hX", __FUNCTION__
- ,(long)zm->ack_file_pos, __FUNCTION__, crc);
+// lprintf(zm,LOG_DEBUG, "%lu %s GOOD CRC: %04hX", __FUNCTION__
+// ,(ulong)zm->ack_file_pos, __FUNCTION__, crc);
zm->rxd_header_len = 5;
@@ -1119,13 +1120,12 @@ BOOL zmodem_recv_hex_header(zmodem_t* zm)
rxd_crc |= c;
if(rxd_crc == crc) {
- lprintf(zm,LOG_DEBUG, "%ld %s GOOD CRC: %04hX"
- ,(long)zm->ack_file_pos, __FUNCTION__, crc);
+// lprintf(zm,LOG_DEBUG, "%s GOOD CRC: %04hX", __FUNCTION__, crc);
zm->rxd_header_len = 5;
}
else {
- lprintf(zm,LOG_WARNING, "%ld %s CRC ERROR: 0x%hX, expected: 0x%hX"
- ,(long)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc);
+ lprintf(zm,LOG_WARNING, "%s CRC ERROR: 0x%hX, expected: 0x%hX"
+ ,__FUNCTION__, rxd_crc, crc);
return FALSE;
}
@@ -1170,11 +1170,11 @@ BOOL zmodem_recv_bin32_header(zmodem_t* zm)
rxd_crc |= zmodem_rx(zm) << 24;
if(rxd_crc != crc) {
- lprintf(zm,LOG_WARNING, "%ld %s CRC ERROR (%08lX, expected: %08lX)"
- ,(long)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc);
+ lprintf(zm,LOG_WARNING, "%lu %s CRC ERROR (%08lX, expected: %08lX)"
+ ,(ulong)zm->ack_file_pos, __FUNCTION__, rxd_crc, crc);
return(FALSE);
}
- lprintf(zm,LOG_DEBUG, "%ld %s GOOD CRC: %08lX", (long)zm->ack_file_pos, __FUNCTION__, crc);
+// lprintf(zm,LOG_DEBUG, "%lu %s GOOD CRC: %08lX", (ulong)zm->ack_file_pos, __FUNCTION__, crc);
zm->rxd_header_len = 5;
return(TRUE);
@@ -1247,15 +1247,15 @@ int zmodem_recv_header_raw(zmodem_t* zm, int errors)
break;
default:
if(c < 0) {
- lprintf(zm,LOG_WARNING, "%ld %s ERROR: %s"
- ,(long)zm->current_file_pos, __FUNCTION__, chr(c));
+ lprintf(zm,LOG_WARNING, "%lu %s ERROR: %s"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, chr(c));
return c;
}
/*
* unrecognized header style
*/
- lprintf(zm,LOG_ERR, "%ld %s UNRECOGNIZED header: %s"
- ,(long)zm->current_file_pos, __FUNCTION__, chr(c));
+ lprintf(zm,LOG_ERR, "%lu %s UNRECOGNIZED header: %s"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, chr(c));
if(errors) {
return INVHDR;
}
@@ -1320,11 +1320,11 @@ int zmodem_recv_header(zmodem_t* zm)
lprintf(zm,LOG_WARNING, "%s TIMEOUT", __FUNCTION__);
break;
case INVHDR:
- lprintf(zm,LOG_WARNING, "%s detected an invalid header", __FUNCTION__);
+ lprintf(zm,LOG_WARNING, "%s detected an INVALID HEADER", __FUNCTION__);
break;
default:
- lprintf(zm,LOG_DEBUG, "%ld %s frame: %s"
- ,(long)frame_pos(zm, ret), __FUNCTION__, frame_desc(ret));
+ lprintf(zm,LOG_DEBUG, "%lu %s frame: %s"
+ ,(ulong)frame_pos(zm, ret), __FUNCTION__, frame_desc(ret));
if(ret==ZCAN)
zm->cancelled=TRUE;
else if(ret==ZRINIT)
@@ -1351,8 +1351,8 @@ int zmodem_recv_header_and_check(zmodem_t* zm)
zmodem_send_znak(zm);
}
- lprintf(zm,LOG_DEBUG, "%ld %s returning: %s (pos=%lu)"
- ,(long)zm->current_file_pos, __FUNCTION__, frame_desc(type), frame_pos(zm, type));
+ lprintf(zm,LOG_DEBUG, "%lu %s returning: %s"
+ ,frame_pos(zm, type), __FUNCTION__, frame_desc(type));
if(type==ZCAN)
zm->cancelled=TRUE;
@@ -1372,13 +1372,13 @@ BOOL zmodem_recv_crc(zmodem_t* zm, uint32_t* crc)
int type;
if(!zmodem_data_waiting(zm,zm->crc_timeout)) {
- lprintf(zm,LOG_ERR, "%ld %s Timeout waiting for response (%u seconds)"
- ,(long)zm->current_file_pos, __FUNCTION__, zm->crc_timeout);
+ lprintf(zm,LOG_ERR, "%lu %s Timeout waiting for response (%u seconds)"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, zm->crc_timeout);
return(FALSE);
}
if((type=zmodem_recv_header(zm))!=ZCRC) {
- lprintf(zm,LOG_ERR, "%ld %s Received %s instead of ZCRC"
- ,(long)zm->current_file_pos, __FUNCTION__, frame_desc(type));
+ lprintf(zm,LOG_ERR, "%lu %s Received %s instead of ZCRC"
+ ,(ulong)zm->current_file_pos, __FUNCTION__, frame_desc(type));
return(FALSE);
}
if(crc!=NULL)
@@ -1501,11 +1501,13 @@ BOOL zmodem_handle_zrpos(zmodem_t* zm, uint64_t* pos)
if(zm->rxd_header_pos <= zm->current_file_size) {
if(*pos != zm->rxd_header_pos) {
*pos = zm->rxd_header_pos;
- lprintf(zm, LOG_INFO, "Resuming transfer from offset: %"PRIu64, *pos);
+ lprintf(zm, LOG_INFO, "%lu Resuming transfer from offset: %"PRIu64
+ ,(ulong)zm->current_file_pos, *pos);
}
return TRUE;
}
- lprintf(zm, LOG_WARNING, "Invalid ZRPOS offset: %lu", zm->rxd_header_pos);
+ lprintf(zm, LOG_WARNING, "%lu Received INVALID ZRPOS offset: %lu"
+ ,(ulong)zm->current_file_pos, zm->rxd_header_pos);
return FALSE;
}
@@ -1513,8 +1515,8 @@ BOOL zmodem_handle_zack(zmodem_t* zm)
{
if(zm->rxd_header_pos == zm->current_file_pos)
return TRUE;
- lprintf(zm, LOG_WARNING, "ZACK for incorrect offset (%lu vs %lu)"
- ,zm->rxd_header_pos, (ulong)zm->current_file_pos);
+ lprintf(zm, LOG_WARNING, "%lu ZACK for INVALID OFFSET: %lu"
+ , (ulong)zm->current_file_pos, zm->rxd_header_pos);
return FALSE;
}
@@ -1596,9 +1598,10 @@ int zmodem_send_from(zmodem_t* zm, FILE* fp, uint64_t pos, uint64_t* sent)
subpkts_sent++;
if(type == ZCRCW || type == ZCRCE) {
- lprintf(zm, LOG_DEBUG, "%ld Sent end-of-frame (%s subpacket)", (long)zm->current_file_pos, chr(type));
- if(type==ZCRCW) { /* ZACK expected */
- lprintf(zm, LOG_DEBUG, "%ld Waiting for ZACK", (long)zm->current_file_pos);
+ lprintf(zm, LOG_DEBUG, "%lu Sent end-of-frame (%s subpacket)"
+ ,(ulong)zm->current_file_pos, chr(type));
+ if(type == ZCRCW) { /* ZACK expected */
+ lprintf(zm, LOG_DEBUG, "%lu Waiting for ZACK", (ulong)zm->current_file_pos);
while(is_connected(zm)) {
int ack;
if((ack = zmodem_recv_header(zm)) != ZACK)
@@ -1619,7 +1622,7 @@ int zmodem_send_from(zmodem_t* zm, FILE* fp, uint64_t pos, uint64_t* sent)
buf_sent+=n;
if(n < zm->block_size) {
- lprintf(zm,LOG_DEBUG, "%ld End of file (or read error) reached", (long)zm->current_file_pos);
+ lprintf(zm,LOG_DEBUG, "%lu End of file (or read error) reached", (ulong)zm->current_file_pos);
zmodem_send_zeof(zm);
return zmodem_recv_header(zm); /* If this is ZRINIT, Success */
}
@@ -1633,9 +1636,11 @@ int zmodem_send_from(zmodem_t* zm, FILE* fp, uint64_t pos, uint64_t* sent)
&& !is_cancelled(zm) && is_connected(zm)) {
int rx_type;
int c;
- lprintf(zm, LOG_DEBUG, "Back-channel traffic detected:");
- if((c = zmodem_recv_raw(zm)) < 0)
+ lprintf(zm, LOG_DEBUG, "Back-channel traffic detected");
+ if((c = zmodem_recv_raw(zm)) < 0) {
+ lprintf(zm, LOG_ERR, "Back-channel receive ERROR: %s", chr(c));
return(c);
+ }
if(c == ZPAD) {
/* ZMODEM.DOC:
FULL STREAMING WITH SAMPLING
@@ -1649,7 +1654,7 @@ int zmodem_send_from(zmodem_t* zm, FILE* fp, uint64_t pos, uint64_t* sent)
return rx_type;
}
} else
- lprintf(zm,LOG_DEBUG, "%s received: %s", __FUNCTION__, chr(c));
+ lprintf(zm,LOG_DEBUG, "Unexpected back-channel data received: %s", chr(c));
}
if(is_cancelled(zm))
return(ZCAN);
@@ -1663,7 +1668,7 @@ int zmodem_send_from(zmodem_t* zm, FILE* fp, uint64_t pos, uint64_t* sent)
}
}
- lprintf(zm, LOG_WARNING, "%s returning unexpectedly!", __FUNCTION__);
+ lprintf(zm, LOG_WARNING, "%s Returning unexpectedly!", __FUNCTION__);
/*
* end of file reached.
@@ -1724,7 +1729,7 @@ BOOL zmodem_send_file(zmodem_t* zm, char* fname, FILE* fp, BOOL request_init, ti
i = zmodem_get_zrinit(zm);
if(i == ZRINIT)
break;
- lprintf(zm,LOG_WARNING, "%s received %s instead of ZRINIT"
+ lprintf(zm,LOG_WARNING, "%s UNEXPECTED %s received instead of ZRINIT"
,__FUNCTION__, frame_desc(i));
}
if(zm->errors>=zm->max_errors || is_cancelled(zm) || !is_connected(zm))
@@ -1844,7 +1849,7 @@ BOOL zmodem_send_file(zmodem_t* zm, char* fname, FILE* fp, BOOL request_init, ti
if(zm->crc_request==0)
lprintf(zm,LOG_NOTICE,"Receiver requested CRC of entire file");
else
- lprintf(zm,LOG_NOTICE,"Receiver requested CRC of first %lu bytes"
+ lprintf(zm,LOG_NOTICE,"Receiver requested CRC of first %lu bytes of file"
,zm->crc_request);
zmodem_send_pos_header(zm,ZCRC,fcrc32(fp,zm->crc_request),TRUE);
type = zmodem_recv_header(zm);
@@ -1910,7 +1915,8 @@ BOOL zmodem_send_file(zmodem_t* zm, char* fname, FILE* fp, BOOL request_init, ti
/* Error of some kind */
- lprintf(zm,LOG_ERR,"Received %s at offset: %"PRId64, chr(type), zm->current_file_pos);
+ zm->errors++;
+ lprintf(zm, LOG_ERR, "%lu ERROR #%d: Received %s", (ulong)zm->current_file_pos, zm->errors, chr(type));
if(zm->block_size == zm->max_block_size && zm->max_block_size > ZBLOCKLEN)
zm->max_block_size /= 2;
@@ -1918,7 +1924,6 @@ BOOL zmodem_send_file(zmodem_t* zm, char* fname, FILE* fp, BOOL request_init, ti
if(zm->block_size > 128)
zm->block_size /= 2;
- zm->errors++;
if(++zm->consecutive_errors > zm->max_errors) {
lprintf(zm, LOG_WARNING, "Too many consecutive errors: %u (%u total)"
,zm->consecutive_errors, zm->errors);
@@ -1963,7 +1968,7 @@ int zmodem_recv_files(zmodem_t* zm, const char* download_dir, uint64_t* bytes_re
bytes=zm->current_file_size;
kbytes=bytes/1024;
if(kbytes<1) kbytes=0;
- lprintf(zm,LOG_INFO,"Downloading %s (%"PRId64" KBytes) via Zmodem", zm->current_file_name, kbytes);
+ lprintf(zm,LOG_INFO,"Downloading %s (%"PRId64" KBytes) via ZMODEM", zm->current_file_name, kbytes);
do { /* try */
skip=TRUE;
@@ -2167,7 +2172,7 @@ void zmodem_parse_zfile_subpacket(zmodem_t* zm)
);
zm->current_file_time=tmptime;
- lprintf(zm,LOG_DEBUG,"Zmodem file (ZFILE) data (%u fields): %s"
+ lprintf(zm,LOG_DEBUG,"ZMODEM file (ZFILE) data (%u fields): %s"
,i, zm->rx_data_subpacket+strlen((char*)zm->rx_data_subpacket)+1);
if(!zm->files_remaining)
@@ -2222,21 +2227,23 @@ unsigned zmodem_recv_file_data(zmodem_t* zm, FILE* fp, int64_t offset)
break;
}
- if(type!=ENDOFFRAME)
+ if(type!=ENDOFFRAME) {
+ lprintf(zm, LOG_WARNING, "%lu Repositioning sender (sending ZRPOS)", (ulong)pos);
zmodem_send_pos_header(zm, ZRPOS, (uint32_t)pos, /* Hex? */ TRUE);
+ }
type = zmodem_recv_file_frame(zm,fp);
if(type == ZEOF || type == ZFIN)
break;
if(type==ENDOFFRAME)
- lprintf(zm,LOG_DEBUG, "%s complete frame at offset: %lu",__FUNCTION__, (ulong)ftello(fp));
+ lprintf(zm,LOG_DEBUG, "%lu Complete frame received", (ulong)ftello(fp));
else {
errors++;
if(type>0 && !zm->local_abort)
- lprintf(zm,LOG_ERR, "%s ERROR #%d %s at offset: %lu",__FUNCTION__, errors, chr(type), (ulong)ftello(fp));
+ lprintf(zm, LOG_ERR, "%lu ERROR #%d: %s", (ulong)ftello(fp), errors, chr(type));
}
if(errors > zm->max_errors) {
- lprintf(zm, LOG_ERR, "%s Maximum errors (%lu) exceeded",__FUNCTION__, zm->max_errors);
+ lprintf(zm, LOG_ERR, "%lu Maximum errors (%lu) exceeded", (ulong)ftello(fp), zm->max_errors);
break;
}
}
@@ -2244,8 +2251,11 @@ unsigned zmodem_recv_file_data(zmodem_t* zm, FILE* fp, int64_t offset)
/*
* wait for the eof header
*/
- for(;errors<=zm->max_errors && !is_cancelled(zm) && type!=ZEOF && type!=ZFIN; errors++)
+ for(;errors<=zm->max_errors && !is_cancelled(zm) && type!=ZEOF && type!=ZFIN; errors++) {
+ lprintf(zm, LOG_INFO, "%lu Waiting for EOF or FIN", (ulong)ftello(fp));
type = zmodem_recv_header_and_check(zm);
+ lprintf(zm, LOG_DEBUG, "%lu Received %s", (ulong)ftello(fp), chr(type));
+ }
return(errors);
}
@@ -2287,12 +2297,12 @@ int zmodem_recv_file_frame(zmodem_t* zm, FILE* fp)
if(type==ZDATA)
break;
- lprintf(zm,LOG_WARNING,"Received %s instead of ZDATA frame", frame_desc(type));
+ lprintf(zm, LOG_WARNING, "%lu Received %s instead of ZDATA frame", (ulong)ftello(fp), frame_desc(type));
}
- if(zm->rxd_header_pos!=(uint32_t)ftello(fp)) {
- lprintf(zm,LOG_WARNING,"Received wrong ZDATA frame (%lu vs %lu)"
- ,zm->rxd_header_pos, (ulong)ftello(fp));
+ if(zm->rxd_header_pos != (uint32_t)ftello(fp)) {
+ lprintf(zm,LOG_WARNING, "%lu Received ZDATA frame with invalid position: %lu"
+ ,(ulong)ftello(fp), (ulong)zm->rxd_header_pos);
return FALSE;
}
--
GitLab