From db1b994cc2670f61fa97796d99aacea632f02e24 Mon Sep 17 00:00:00 2001 From: Nickolay Olshevsky Date: Sun, 12 Nov 2023 17:15:11 +0200 Subject: [PATCH] Add some debug logging. --- src/lib/rnp.cpp | 3 ++ src/librepgp/stream-common.cpp | 14 ++++++- src/librepgp/stream-parse.cpp | 69 ++++++++++++++++++++++++++++++++++ 3 files changed, 85 insertions(+), 1 deletion(-) diff --git a/src/lib/rnp.cpp b/src/lib/rnp.cpp index 51945bb10e..4207830d71 100644 --- a/src/lib/rnp.cpp +++ b/src/lib/rnp.cpp @@ -3132,14 +3132,17 @@ rnp_verify_dest_provider(pgp_parse_handler_t *handler, const char * filename, uint32_t mtime) { + RNP_LOG("here"); rnp_op_verify_t op = (rnp_op_verify_t) handler->param; if (!op->output) { + RNP_LOG("here"); return false; } *dst = &(op->output->dst); *closedst = false; op->filename = filename ? std::string(filename) : ""; op->file_mtime = mtime; + RNP_LOG("here"); return true; } diff --git a/src/librepgp/stream-common.cpp b/src/librepgp/stream-common.cpp index f1f2270a45..1c5397f002 100644 --- a/src/librepgp/stream-common.cpp +++ b/src/librepgp/stream-common.cpp @@ -55,16 +55,18 @@ bool src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) { size_t left = len; - size_t read; + size_t read = 0; pgp_source_cache_t *cache = src->cache; bool readahead = cache ? cache->readahead : false; if (src->error) { + RNP_LOG("here"); return false; } if (src->eof || (len == 0)) { *readres = 0; + RNP_LOG("here"); return true; } @@ -96,11 +98,14 @@ src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) // If there is no cache or chunk is larger then read directly if (!src->read(src, buf, left, &read)) { src->error = 1; + RNP_LOG("here"); return false; } + // RNP_LOG("here: %p %zu", src->read, read); if (!read) { src->eof = 1; len = len - left; + RNP_LOG("here: %zu", len); goto finish; } left -= read; @@ -109,11 +114,14 @@ src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) // Try to fill the cache to avoid small reads if (!src->read(src, &cache->buf[0], sizeof(cache->buf), &read)) { src->error = 1; + RNP_LOG("here"); return false; } + // RNP_LOG("here: %p %zu", src->read, read); if (!read) { src->eof = 1; len = len - left; + RNP_LOG("here: %zu", len); goto finish; } else if (read < left) { memcpy(buf, &cache->buf[0], read); @@ -129,11 +137,15 @@ src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) } finish: + RNP_LOG("here: %p", src->read); src->readb += len; + RNP_LOG("here: %zu", src->readb); if (src->knownsize && (src->readb == src->size)) { src->eof = 1; } + RNP_LOG("here: %zu", len); *readres = len; + RNP_LOG("here"); return true; } diff --git a/src/librepgp/stream-parse.cpp b/src/librepgp/stream-parse.cpp index f80fe5d16d..7854b5c1bd 100644 --- a/src/librepgp/stream-parse.cpp +++ b/src/librepgp/stream-parse.cpp @@ -228,6 +228,7 @@ is_pgp_source(pgp_source_t &src) static bool partial_pkt_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) { + RNP_LOG("partial"); if (src->eof) { *readres = 0; return true; @@ -240,15 +241,21 @@ partial_pkt_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) size_t read; size_t write = 0; + RNP_LOG("partial"); while (len > 0) { + RNP_LOG("partial"); if (!param->pleft && param->last) { + RNP_LOG("partial: %p %zu", readres, write); // we have the last chunk *readres = write; return true; } + RNP_LOG("partial"); if (!param->pleft) { // reading next chunk + RNP_LOG("partial"); if (!stream_read_partial_chunk_len(param->readsrc, &read, ¶m->last)) { + RNP_LOG("partial"); return false; } param->psize = read; @@ -256,15 +263,18 @@ partial_pkt_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) } if (!param->pleft) { + RNP_LOG("partial"); *readres = write; return true; } + RNP_LOG("partial"); read = param->pleft > len ? len : param->pleft; if (!src_read(param->readsrc, buf, read, &read)) { RNP_LOG("failed to read data chunk"); return false; } + RNP_LOG("partial"); if (!read) { RNP_LOG("unexpected eof"); *readres = write; @@ -276,6 +286,7 @@ partial_pkt_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) param->pleft -= read; } + RNP_LOG("partial"); *readres = write; return true; } @@ -323,10 +334,13 @@ init_partial_pkt_src(pgp_source_t *src, pgp_source_t *readsrc, pgp_packet_hdr_t static bool literal_src_read(pgp_source_t *src, void *buf, size_t len, size_t *read) { + RNP_LOG("here"); pgp_source_literal_param_t *param = (pgp_source_literal_param_t *) src->param; if (!param) { + RNP_LOG("here"); return false; } + RNP_LOG("here: %d", (int) param->pkt.readsrc->type); return src_read(param->pkt.readsrc, buf, len, read); } @@ -349,6 +363,7 @@ literal_src_close(pgp_source_t *src) static bool compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) { + RNP_LOG("here"); pgp_source_compressed_param_t *param = (pgp_source_compressed_param_t *) src->param; if (!param) { return false; @@ -359,6 +374,7 @@ compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) return true; } + RNP_LOG("here"); if (param->alg == PGP_C_NONE) { if (!src_read(param->pkt.readsrc, buf, len, readres)) { RNP_LOG("failed to read uncompressed data"); @@ -366,6 +382,7 @@ compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) } return true; } + RNP_LOG("here"); if ((param->alg == PGP_C_ZIP) || (param->alg == PGP_C_ZLIB)) { param->z.next_out = (Bytef *) buf; param->z.avail_out = len; @@ -373,25 +390,33 @@ compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) param->z.avail_in = param->inlen - param->inpos; while ((param->z.avail_out > 0) && (!param->zend)) { + RNP_LOG("here"); if (param->z.avail_in == 0) { size_t read = 0; + RNP_LOG("here"); if (!src_read(param->pkt.readsrc, param->in, sizeof(param->in), &read)) { RNP_LOG("failed to read data"); return false; } + RNP_LOG("here"); param->z.next_in = param->in; param->z.avail_in = read; param->inlen = read; param->inpos = 0; + RNP_LOG("here"); } + RNP_LOG("here"); int ret = inflate(¶m->z, Z_SYNC_FLUSH); + RNP_LOG("here: %d", ret); if (ret == Z_STREAM_END) { param->zend = true; if (param->z.avail_in > 0) { RNP_LOG("data beyond the end of z stream"); } + RNP_LOG("here"); break; } + RNP_LOG("here"); if (ret != Z_OK) { RNP_LOG("inflate error %d", ret); return false; @@ -401,12 +426,15 @@ compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) return false; } } + RNP_LOG("here"); param->inpos = param->z.next_in - param->in; *readres = len - param->z.avail_out; + RNP_LOG("here: %zu", *readres); return true; } #ifdef HAVE_BZLIB_H if (param->alg == PGP_C_BZIP2) { + RNP_LOG("here"); param->bz.next_out = (char *) buf; param->bz.avail_out = len; param->bz.next_in = (char *) (param->in + param->inpos); @@ -447,6 +475,7 @@ compressed_src_read(pgp_source_t *src, void *buf, size_t len, size_t *readres) return true; } #endif + RNP_LOG("here"); return false; } @@ -704,28 +733,35 @@ encrypted_src_read_aead(pgp_source_t *src, void *buf, size_t len, size_t *read) static bool encrypted_src_read_cfb(pgp_source_t *src, void *buf, size_t len, size_t *readres) { + RNP_LOG("here"); pgp_source_encrypted_param_t *param = (pgp_source_encrypted_param_t *) src->param; if (param == NULL) { + RNP_LOG("here"); return false; } if (src->eof) { *readres = 0; + RNP_LOG("here"); return true; } + RNP_LOG("here"); size_t read; if (!src_read(param->pkt.readsrc, buf, len, &read)) { + RNP_LOG("here"); return false; } if (!read) { *readres = 0; + RNP_LOG("here"); return true; } bool parsemdc = false; uint8_t mdcbuf[MDC_V1_SIZE]; if (param->auth_type == rnp::AuthType::MDC) { + RNP_LOG("here"); size_t mdcread = 0; /* make sure there are always 22 bytes left on input */ if (!src_peek(param->pkt.readsrc, mdcbuf, MDC_V1_SIZE, &mdcread) || @@ -743,10 +779,13 @@ encrypted_src_read_cfb(pgp_source_t *src, void *buf, size_t len, size_t *readres } } + RNP_LOG("here"); pgp_cipher_cfb_decrypt(¶m->decrypt, (uint8_t *) buf, (uint8_t *) buf, read); + RNP_LOG("here"); if (param->auth_type == rnp::AuthType::MDC) { try { + RNP_LOG("here"); param->mdc->add(buf, read); if (parsemdc) { @@ -774,6 +813,7 @@ encrypted_src_read_cfb(pgp_source_t *src, void *buf, size_t len, size_t *readres } } *readres = read; + RNP_LOG("here"); return true; } @@ -2338,6 +2378,7 @@ encrypted_read_packet_data(pgp_source_encrypted_param_t *param) static rnp_result_t init_encrypted_src(pgp_parse_handler_t *handler, pgp_source_t *src, pgp_source_t *readsrc) { + RNP_LOG("here"); if (!init_src_common(src, 0)) { return RNP_ERROR_OUT_OF_MEMORY; } @@ -2354,11 +2395,13 @@ init_encrypted_src(pgp_parse_handler_t *handler, pgp_source_t *src, pgp_source_t src->type = PGP_STREAM_ENCRYPTED; /* Read the packet-related information */ + RNP_LOG("here"); rnp_result_t errcode = encrypted_read_packet_data(param); if (errcode) { goto finish; } + RNP_LOG("here"); src->read = (!param->use_cfb() #ifdef ENABLE_CRYPTO_REFRESH || param->is_v2_seipd() @@ -2374,11 +2417,13 @@ init_encrypted_src(pgp_parse_handler_t *handler, pgp_source_t *src, pgp_source_t goto finish; } + RNP_LOG("here"); /* informing handler about the available pubencs/symencs */ if (handler->on_recipients) { handler->on_recipients(param->pubencs, param->symencs, handler->param); } + RNP_LOG("here"); bool have_key; have_key = false; /* Trying public-key decryption */ @@ -2456,15 +2501,19 @@ init_encrypted_src(pgp_parse_handler_t *handler, pgp_source_t *src, pgp_source_t /* Trying password-based decryption */ if (!have_key && !param->symencs.empty()) { + RNP_LOG("here"); rnp::secure_array password; pgp_password_ctx_t pass_ctx(PGP_OP_DECRYPT_SYM); if (!pgp_request_password( handler->password_provider, &pass_ctx, password.data(), password.size())) { errcode = RNP_ERROR_BAD_PASSWORD; + RNP_LOG("here"); goto finish; } + RNP_LOG("here"); int intres = encrypted_try_password(param, password.data()); + RNP_LOG("here: %d", intres); if (intres > 0) { have_key = true; } else if (intres < 0) { @@ -2475,13 +2524,16 @@ init_encrypted_src(pgp_parse_handler_t *handler, pgp_source_t *src, pgp_source_t } /* report decryption start to the handler */ + RNP_LOG("here"); if (handler->on_decryption_info) { + RNP_LOG("here"); handler->on_decryption_info(param->auth_type == rnp::AuthType::MDC, param->aead_hdr.aalg, param->salg, handler->param); } + RNP_LOG("here"); if (!have_key) { RNP_LOG("failed to obtain decrypting key or password"); if (!errcode) { @@ -2712,6 +2764,7 @@ init_packet_sequence(pgp_processing_ctx_t &ctx, pgp_source_t &src) pgp_source_t *lsrc = &src; size_t srcnum = ctx.sources.size(); + RNP_LOG("here"); while (1) { uint8_t ptag = 0; if (!src_peek_eq(lsrc, &ptag, 1)) { @@ -2848,6 +2901,10 @@ process_pgp_source(pgp_parse_handler_t *handler, pgp_source_t &src) bool closeout = true; uint8_t * readbuf = NULL; + RNP_LOG("here"); + RNP_LOG("encrypted_src_read_cfb: %p", encrypted_src_read_aead); + RNP_LOG("compressed_src_read: %p", compressed_src_read); + RNP_LOG("partial_pkt_src_read: %p", partial_pkt_src_read); ctx.handler = *handler; /* Building readers sequence. Checking whether it is binary data */ if (is_pgp_source(src)) { @@ -2902,6 +2959,7 @@ process_pgp_source(pgp_parse_handler_t *handler, pgp_source_t &src) } src_close(&datasrc); } else { + RNP_LOG("here"); if (handler->ctx->detached) { RNP_LOG("Detached signature expected."); res = RNP_ERROR_BAD_STATE; @@ -2912,25 +2970,34 @@ process_pgp_source(pgp_parse_handler_t *handler, pgp_source_t &src) char * filename = NULL; uint32_t mtime = 0; + RNP_LOG("here"); if (ctx.literal_src) { auto *param = static_cast(ctx.literal_src->param); filename = param->hdr.fname; mtime = param->hdr.timestamp; } + RNP_LOG("here: %s", filename); if (!handler->dest_provider || !handler->dest_provider(handler, &outdest, &closeout, filename, mtime)) { res = RNP_ERROR_WRITE; + RNP_LOG("here"); goto finish; } /* reading the input */ + RNP_LOG("here: %p", decsrc); + RNP_LOG("here: %d", decsrc->eof); + RNP_LOG("here: %d", (int) decsrc->type); while (!decsrc->eof) { size_t read = 0; + RNP_LOG("here"); if (!src_read(decsrc, readbuf, PGP_INPUT_CACHE_SIZE, &read)) { res = RNP_ERROR_GENERIC; + RNP_LOG("here"); break; } + RNP_LOG("here: %zu", read); if (!read) { continue; } @@ -2938,6 +3005,7 @@ process_pgp_source(pgp_parse_handler_t *handler, pgp_source_t &src) signed_src_update(ctx.signed_src, readbuf, read); } dst_write(outdest, readbuf, read); + RNP_LOG("here"); if (outdest->werr != RNP_SUCCESS) { RNP_LOG("failed to output data"); res = RNP_ERROR_WRITE; @@ -2961,6 +3029,7 @@ process_pgp_source(pgp_parse_handler_t *handler, pgp_source_t &src) } finish: + RNP_LOG("here: %x", (int) res); free(readbuf); return res; }