From: Kostya Shishkov Date: Sat, 14 Feb 2026 10:54:43 +0000 (+0100) Subject: introduce debug logging X-Git-Url: https://git.nihav.org/?a=commitdiff_plain;ds=inline;p=nihav-encoder.git introduce debug logging --- diff --git a/src/main.rs b/src/main.rs index 07ad781..a3be91c 100644 --- a/src/main.rs +++ b/src/main.rs @@ -111,8 +111,10 @@ macro_rules! parse_id { } fn retrieve_packets(transcoder: &mut Transcoder, mux: &mut Muxer, vdata_size: &mut usize, adata_size: &mut usize, end: bool) -> bool { - while let Some(pkt) = transcoder.queue.get_packet() { + while let Some(pkt) = transcoder.queue.get_packet(&mut transcoder.debug) { + transcoder.debug_log(DebugLog::MUX, &format!(" Got output packet for stream {} ts {:?}/{:?}", pkt.get_stream().get_id(), pkt.ts.pts, pkt.ts.dts)); if transcoder.end != NATimePoint::None && !pkt.ts.less_than(transcoder.end) { + transcoder.debug_log(DebugLog::GENERAL, "Hit end time boundary"); return false; } let pkt_size = pkt.get_buffer().len(); @@ -123,12 +125,15 @@ fn retrieve_packets(transcoder: &mut Transcoder, mux: &mut Muxer, vdata_size: &m }; if mux.mux_frame(pkt).is_err() { println!("error muxing packet"); + transcoder.debug_log(DebugLog::MUX, "Error muxing packet"); return false; } } if end { - while let Some(pkt) = transcoder.queue.get_last_packet() { + while let Some(pkt) = transcoder.queue.get_last_packet(&mut transcoder.debug) { + transcoder.debug_log(DebugLog::MUX, &format!(" Got output packet for stream {} ts {:?}/{:?}", pkt.get_stream().get_id(), pkt.ts.pts, pkt.ts.dts)); if transcoder.end != NATimePoint::None && !pkt.ts.less_than(transcoder.end) { + transcoder.debug_log(DebugLog::GENERAL, "Hit end time boundary"); return false; } let pkt_size = pkt.get_buffer().len(); @@ -139,6 +144,7 @@ fn retrieve_packets(transcoder: &mut Transcoder, mux: &mut Muxer, vdata_size: &m }; if mux.mux_frame(pkt).is_err() { println!("error muxing packet"); + transcoder.debug_log(DebugLog::MUX, " Error muxing packet"); return false; } } @@ -366,6 +372,10 @@ fn main() { "--verbose" | "-v" => transcoder.verbose = 1, "-vv" => transcoder.verbose = 2, "-v-" => transcoder.verbose = 0, + "--debug" => { + next_arg!(args, arg_idx); + transcoder.debug = DebugLog::create(&args[arg_idx]); + }, "--ignerr" => { ignerr = true; }, @@ -431,10 +441,12 @@ fn main() { if transcoder.input_name.iter().flatten().count() == 0 { println!("no input name(s) provided"); + transcoder.debug_log(DebugLog::GENERAL, &format!("no input name(s) provided")); return; } if transcoder.output_name.is_empty() { println!("no output name provided"); + transcoder.debug_log(DebugLog::GENERAL, &format!("no output name provided")); return; } @@ -454,6 +466,7 @@ fn main() { } }); let duration_string = if duration != 0 { format_time(duration) } else { String::new() }; + transcoder.debug_log(DebugLog::GENERAL, &format!("total duration {duration_string}")); let mut ism = StreamManager::new(); let mut is_offset = Vec::with_capacity(demuxers.len()); @@ -493,6 +506,7 @@ fn main() { let ret = decoder.init(&mut dsupp, info.clone()); if ret.is_err() { println!("Error initialising decoder '{}' for stream {}", info.get_name(), str_id); + transcoder.debug_log(DebugLog::GENERAL, &format!("Error initialising decoder '{}' for stream {str_id}", info.get_name())); if !ignerr { return; } else { @@ -506,20 +520,25 @@ fn main() { desc.caps } else if s.get_media_type() == StreamType::Video { println!("No codec description found, using B-frame reorderer."); + transcoder.debug_log(DebugLog::GENERAL, &format!("No codec description found for stream {str_id}, using B-frame reorderer")); register::CODEC_CAP_REORDER } else { 0 }; let reorderer: Box = if (caps & register::CODEC_CAP_COMPLEX_REORDER) != 0 { + transcoder.debug_log(DebugLog::DECODE, &format!(" Stream {str_id} - complex reorderer")); Box::new(ComplexReorderer::new()) } else if (caps & register::CODEC_CAP_REORDER) != 0 { + transcoder.debug_log(DebugLog::DECODE, &format!(" Stream {str_id} - B-frame reorderer")); Box::new(IPBReorderer::new()) } else { + transcoder.debug_log(DebugLog::DECODE, &format!(" Stream {str_id} - no reorderer")); Box::new(NoReorderer::new()) }; transcoder.decoders.push(Some(DecodeContext{ dsupp, decoder, reorderer })); } else { println!("No decoder for stream {} ({}) is found", str_id, info.get_name()); + transcoder.debug_log(DebugLog::GENERAL, &format!("No decoder found for stream {str_id} ({})", info.get_name())); transcoder.decoders.push(None); } } @@ -527,6 +546,7 @@ fn main() { let ret = dmx.seek(transcoder.start); if ret.is_err() { println!(" failed to seek to {} error {:?}", transcoder.start, ret.err().unwrap()); + transcoder.debug_log(DebugLog::GENERAL, &format!("Failed to seek to {}", transcoder.start)); } } } @@ -536,12 +556,18 @@ fn main() { } let output_fmt = if let Some(ref fmtname) = transcoder.output_fmt { + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::MUX, &format!("Forcing {fmtname} as muxer type")); + } fmtname } else if transcoder.output_name.as_str() == "/dev/null" { + transcoder.debug_log(DebugLog::MUX, &format!("Using null muxer")); "null" } else if let Some(fmtname) = detect::detect_format_by_name(transcoder.output_name.as_str()) { + transcoder.debug_log(DebugLog::MUX, &format!("Detected muxer format as {fmtname}")); fmtname } else { + transcoder.debug_log(DebugLog::MUX, &format!("Cannot guess muxer for {}", transcoder.output_name)); println!("Cannot guess muxer for output"); return; }; @@ -550,12 +576,14 @@ fn main() { if ret.is_none() { println!("cannot find muxer '{}'", output_fmt); + transcoder.debug_log(DebugLog::MUX, &format!("cannot find muxer '{output_fmt}'")); return; } let mux_creator = ret.unwrap(); if custom_profile && !profile_name.is_empty() { println!("profile setting is incompatible with custom --ostream options"); + transcoder.debug_log(DebugLog::GENERAL, &format!("profile setting is incompatible with custom --ostream options")); return; } if !profile_name.is_empty() { @@ -564,9 +592,11 @@ fn main() { transcoder.profile = Some(ref_profile.profile); } else { println!("profile '{profile_name}' is not defined for output format '{output_fmt}'"); + transcoder.debug_log(DebugLog::GENERAL, &format!("profile '{profile_name}' is not defined for output format '{output_fmt}'")); } } else { println!("no profiles for output format '{output_fmt}'"); + transcoder.debug_log(DebugLog::GENERAL, &format!("no profiles for output format '{output_fmt}'")); } } @@ -578,6 +608,8 @@ fn main() { transcoder.queue.set_sync(force_sync || !mux_quirks.is_unsync()); if transcoder.calc_len { + transcoder.debug_log(DebugLog::GENERAL, &format!("Calculating total length of input streams")); + let mut sids = Vec::new(); transcoder.nframes.clear(); for (dmx, _) in demuxers.iter_mut() { @@ -595,10 +627,16 @@ fn main() { transcoder.nframes[pos] += 1; } } + for (istr, nf) in transcoder.nframes.iter().enumerate() { + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::GENERAL, &format!(" Stream {istr} {nf} frame(s)")); + } + } // this is necessary since not all demuxers allow to seek even back to the start demuxers.clear(); if !transcoder.create_demuxers(&mut demuxers, &full_reg, false) { println!("failed to re-create demuxer(s)"); + transcoder.debug_log(DebugLog::GENERAL, &format!("failed to re-create demuxer(s)")); return; } } @@ -607,18 +645,21 @@ fn main() { let mut out_sm = StreamManager::new(); if !transcoder.negotiate_stream_map(&ism, mux_caps, &mut out_sm, &full_reg.enc_reg) { println!("cannot determine stream map"); + transcoder.debug_log(DebugLog::GENERAL, &format!("cannot determine stream map")); return; } let ret = File::create(transcoder.output_name.as_str()); if ret.is_err() { println!("cannot open output file"); + transcoder.debug_log(DebugLog::GENERAL, &format!("Cannot open output {}", transcoder.output_name)); return; } let mut bw = FileWriter::new_write(ret.unwrap()); let ret = create_muxer(mux_creator, out_sm, &mut bw); if let Err(err) = ret { println!("cannot create muxer instance {:?}", err); + transcoder.debug_log(DebugLog::GENERAL, &format!("Cannot create muxer: {err:?}")); return; } let mut mux = ret.unwrap(); @@ -637,6 +678,7 @@ fn main() { } } println!(" #{}: {} {}{}", ostr.get_num(), ostr, ostr.get_info().get_name(), if is_copy { " (copy)" } else { "" }); + transcoder.debug_log(DebugLog::MUX, &format!(" #{}: {ostr} {}{}", ostr.get_num(), ostr.get_info().get_name(), if is_copy { " (copy)" } else { "" })); } transcoder.queue.reserve_streams(mux.get_num_streams()); @@ -672,6 +714,7 @@ fn main() { if let Err(DemuxerError::EOF) = pktres { break; } if pktres.is_err() { println!("demuxing error"); + transcoder.debug_log(DebugLog::DEMUX, &format!("Demuxing error: {:?}", pktres.err().unwrap())); break; } let mut pkt = pktres.unwrap(); @@ -680,6 +723,7 @@ fn main() { let ts = pkt.ts; let newstream = ism.get_stream(src_id).unwrap(); pkt.reassign(newstream, ts); + transcoder.debug_log(DebugLog::DEMUX, &format!(" Got packet from input stream {src_id} ts {ts:?}")); if transcoder.verbose > 0 && time.elapsed() >= show_interval { if let Some(pts) = pkt.get_pts() { @@ -702,10 +746,13 @@ fn main() { time = Instant::now(); } match transcoder.encoders[src_id] { - OutputMode::Drop => {}, + OutputMode::Drop => { + transcoder.debug_log(DebugLog::ENCODE, &format!(" Packet from stream {src_id} dropped")); + }, OutputMode::Copy(dst_id) => { let dstr = mux.get_stream(dst_id as usize).unwrap(); pkt.reassign(dstr, pkt.get_time_information()); + transcoder.debug_log(DebugLog::ENCODE, &format!(" Packet from stream {src_id} copied to {dst_id}")); if transcoder.end != NATimePoint::None && !pkt.ts.less_than(transcoder.end) { break 'main_loop; } let pkt_size = pkt.get_buffer().len(); match pkt.get_stream().get_media_type() { @@ -713,11 +760,17 @@ fn main() { StreamType::Audio => { adata_size += pkt_size; }, _ => {}, }; - transcoder.queue.queue_packet(pkt); + transcoder.queue.queue_packet(pkt, &mut transcoder.debug); }, OutputMode::Encode(dst_id, ref mut encoder) => { if let Some(ref mut dec_ctx) = transcoder.decoders[src_id] { let ret = dec_ctx.decoder.decode(&mut dec_ctx.dsupp, &pkt); + if let Some(ref mut dbg) = transcoder.debug { + match &ret { + Ok(_) => dbg.log(DebugLog::DECODE, &format!(" Packet from stream {src_id} decoded")), + Err(err) => dbg.log(DebugLog::DECODE, &format!(" Packet from stream {src_id} decode error {err:?}")), + } + } if let (true, Err(DecoderError::MissingReference)) = (transcoder.start != NATimePoint::None, &ret) { continue; } @@ -732,17 +785,22 @@ fn main() { let frm = ret.unwrap(); dec_ctx.reorderer.add_frame(frm); while let Some(frm) = dec_ctx.reorderer.get_frame() { - match encoder.encode_frame(dst_id, frm, &transcoder.scale_opts, &mut transcoder.queue) { + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::ENCODE, &format!(" Sending frame from stream {dst_id} with ts {:?}/{:?} to encoder", frm.ts.pts, frm.ts.dts)); + } + match encoder.encode_frame(dst_id, frm, &transcoder.scale_opts, &mut transcoder.queue, &mut transcoder.debug) { Ok(true) => {}, Ok(false) => break, Err(err) => { println!("encoder error {err:?}"); + transcoder.debug_log(DebugLog::ENCODE, &format!("Encoder for stream {dst_id} error {err:?}")); break 'main_loop; } } } } else { println!("no decoder for stream {}", src_id); + transcoder.debug_log(DebugLog::DECODE, &format!("No decoder for input stream {src_id}")); break; } }, @@ -752,16 +810,23 @@ fn main() { break; } } + transcoder.debug_log(DebugLog::GENERAL, &format!("Demuxing done, flushing leftover frames")); 'reord_flush_loop: for stream in ism.iter() { let src_id = stream.get_num(); if let OutputMode::Encode(dst_id, ref mut encoder) = transcoder.encoders[src_id] { if let Some(ref mut dec_ctx) = transcoder.decoders[src_id] { while let Some(frm) = dec_ctx.reorderer.get_last_frames() { - match encoder.encode_frame(dst_id, frm, &transcoder.scale_opts, &mut transcoder.queue) { + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::ENCODE, &format!(" Sending frame from stream {dst_id} with ts {:?}/{:?} to encoder", frm.ts.pts, frm.ts.dts)); + } + match encoder.encode_frame(dst_id, frm, &transcoder.scale_opts, &mut transcoder.queue, &mut transcoder.debug) { Ok(true) => {}, Ok(false) => break, Err(err) => { println!("encoder error {err:?}"); + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::ENCODE, &format!("Encoder for stream {dst_id} error {err:?}")); + } break 'reord_flush_loop; } } @@ -769,12 +834,16 @@ fn main() { } } } + transcoder.debug_log(DebugLog::GENERAL, &format!("Flushing encoders")); /*'flush_loop:*/ for enc in transcoder.encoders.iter_mut() { match enc { OutputMode::Encode(str_id, ref mut encoder) => { - let ret = encoder.flush(&mut transcoder.queue); + let ret = encoder.flush(&mut transcoder.queue, &mut transcoder.debug); if ret.is_err() { println!("error flushing encoder for stream {}", str_id); + if let Some(ref mut dbg) = transcoder.debug { + dbg.log(DebugLog::ENCODE, &format!("error flushing encoder for stream {str_id}")); + } break; } }, @@ -782,15 +851,18 @@ fn main() { }; } + transcoder.debug_log(DebugLog::GENERAL, &format!("Flushing encoded packets")); retrieve_packets(&mut transcoder, &mut mux, &mut vdata_size, &mut adata_size, true); if transcoder.verbose > 0 { println!(); } + transcoder.debug_log(DebugLog::MUX, &format!("Finalising muxing")); let ret = mux.end(); if ret.is_err() { println!("error at finalising muxing"); + transcoder.debug_log(DebugLog::MUX, &format!("Error finalising muxing: {:?}", ret.err().unwrap())); } } diff --git a/src/transcoder.rs b/src/transcoder.rs index 0d5ce71..dbbe160 100644 --- a/src/transcoder.rs +++ b/src/transcoder.rs @@ -1,5 +1,5 @@ use std::fs::File; -use std::io::BufReader; +use std::io::{BufReader, Write}; use std::collections::VecDeque; use nihav_core::frame::*; use nihav_core::options::*; @@ -13,6 +13,55 @@ use crate::acvt::*; use nihav_hlblocks::demux::*; use nihav_hlblocks::imgseqdec::*; +pub struct DebugLog { + flags: u32, + file: File, +} + +impl DebugLog { + pub const GENERAL: u32 = 1; + pub const DEMUX: u32 = 1 << 1; + pub const DECODE: u32 = 1 << 2; + pub const ENCODE: u32 = 1 << 2; + pub const SYNC: u32 = 1 << 3; + pub const MUX: u32 = 1 << 4; + + pub fn create(options: &str) -> Option { + let mut flags = 0; + let delimiter = if options.contains('+') { '+' } else { ',' }; + for opt in options.split(delimiter) { + match opt { + "all" => { flags = 0xFFFFFFFF; }, + "general" => { flags |= Self::GENERAL; }, + "demux" => { flags |= Self::DEMUX; }, + "decode" => { flags |= Self::DECODE; }, + "encode" => { flags |= Self::ENCODE; }, + "sync" => { flags |= Self::SYNC; }, + "mux" => { flags |= Self::MUX; }, + _ => { + println!("unknown debug option '{opt}'"); + } + } + } + if flags != 0 { + if let Ok(file) = File::create("debug.log") { + Some(Self{ file, flags }) + } else { + println!("Error creating debug log"); + None + } + } else { + None + } + } + pub fn log(&mut self, level: u32, msg: &str) { + if (self.flags & level) != 0 { + let _ = self.file.write_all(msg.as_bytes()); + let _ = self.file.write_all(b"\n"); + } + } +} + #[derive(Clone,Copy,Debug)] pub struct EncodingProfile { /// video codec to be used @@ -93,8 +142,8 @@ pub struct DecodeContext { } pub trait EncoderInterface { - fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, scale_opts: &[(String, String)], queue: &mut OutputQueue) -> EncoderResult; - fn flush(&mut self, queue: &mut OutputQueue) -> EncoderResult<()>; + fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, scale_opts: &[(String, String)], queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult; + fn flush(&mut self, queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult<()>; } pub struct AudioEncodeContext { @@ -118,7 +167,7 @@ println!("can't generate default channel map for {} channels", info.channels); } impl EncoderInterface for AudioEncodeContext { - fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, _scale_opts: &[(String, String)], queue: &mut OutputQueue) -> EncoderResult { + fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, _scale_opts: &[(String, String)], queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult { let buf = frm.get_buffer(); // check for possible input parameters mismatch and create audio converter if needed if self.cvt.is_none() { @@ -132,17 +181,26 @@ impl EncoderInterface for AudioEncodeContext { let cbuf = if let NABufferType::None = buf { buf } else if let Some(ref mut acvt) = self.cvt { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!(" Queuing audio for stream {dst_id}")); + } if !acvt.queue_frame(buf, frm.get_time_information(), self.vol) { println!("error converting audio for stream {}", dst_id); + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!("Error converting audio for stream {dst_id}")); + } return Ok(false); } while let Some(ofrm) = acvt.get_frame(frm.get_info().clone()) { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!(" Read audio frame for stream {dst_id}")); + } if self.encoder.encode(&ofrm).is_err() { return Ok(false); } while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } } @@ -153,14 +211,14 @@ impl EncoderInterface for AudioEncodeContext { let cfrm = NAFrame::new(frm.get_time_information(), frm.frame_type, frm.key, frm.get_info(), cbuf); self.encoder.encode(&cfrm)?; while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } Ok(true) } - fn flush(&mut self, queue: &mut OutputQueue) -> EncoderResult<()> { + fn flush(&mut self, queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult<()> { self.encoder.flush()?; while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } Ok(()) } @@ -177,14 +235,20 @@ pub struct VideoEncodeContext { } impl EncoderInterface for VideoEncodeContext { - fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, scale_opts: &[(String, String)], queue: &mut OutputQueue) -> EncoderResult { + fn encode_frame(&mut self, dst_id: u32, frm: NAFrameRef, scale_opts: &[(String, String)], queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult { let buf = frm.get_buffer(); let cbuf = if let NABufferType::None = buf { if (self.encoder.get_capabilities() & ENC_CAPS_SKIPFRAME) == 0 { if let NABufferType::None = self.scaler_buf { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!("Encoder for {dst_id} does not support skip frames, skipping")); + } println!("encoder does not support skip frames, skipping"); return Ok(true); } else { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!(" Duplicating frame for {dst_id}")); + } self.scaler_buf.clone() } } else { @@ -194,6 +258,9 @@ impl EncoderInterface for VideoEncodeContext { let cur_ifmt = get_scale_fmt_from_pic(&buf); let last_ifmt = scaler.get_in_fmt(); if cur_ifmt != last_ifmt { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!("Input format change {last_ifmt} -> {cur_ifmt}")); + } let ofmt = scaler.get_out_fmt(); let ret = NAScale::new_with_options(cur_ifmt, ofmt, scale_opts); if ret.is_err() { @@ -204,6 +271,9 @@ impl EncoderInterface for VideoEncodeContext { } let ret = scaler.convert(&buf, &mut self.scaler_buf); if ret.is_err() { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!("Error converting picture for stream {dst_id}")); + } println!("error converting frame for encoding stream {dst_id}"); return Err(EncoderError::Bug); } @@ -235,6 +305,9 @@ impl EncoderInterface for VideoEncodeContext { let mut cur_lts = *last_ts; let mut next_lts = *last_ts + 1; let mut had_frame = false; + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::ENCODE, &format!(" Stream {dst_id} frame for time {cur_lts}..{next_lts}")); + } if cur_ts > cur_lts && (cur_ts - cur_lts) / u64::from(self.tb_den) > 16 { println!("Gap over 16 seconds between consequent frames, that's too much"); return Err(EncoderError::AllocError); @@ -243,7 +316,7 @@ impl EncoderInterface for VideoEncodeContext { cfrm.ts.pts = Some(cur_lts); self.encoder.encode(&cfrm)?; while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } cur_lts = next_lts; next_lts += 1; @@ -258,16 +331,16 @@ impl EncoderInterface for VideoEncodeContext { if !converted { self.encoder.encode(&cfrm)?; while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } } Ok(true) } - fn flush(&mut self, queue: &mut OutputQueue) -> EncoderResult<()> { + fn flush(&mut self, queue: &mut OutputQueue, dbg: &mut Option) -> EncoderResult<()> { self.encoder.flush()?; while let Ok(Some(pkt)) = self.encoder.get_packet() { - queue.queue_packet(pkt); + queue.queue_packet(pkt, dbg); } Ok(()) } @@ -294,15 +367,25 @@ impl OutputQueue { self.packets.push(VecDeque::new()); } } - pub fn queue_packet(&mut self, pkt: NAPacket) { + pub fn queue_packet(&mut self, pkt: NAPacket, dbg: &mut Option) { let stream_no = pkt.get_stream().get_num(); + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, &format!(" sync: got packet for stream {stream_no} ts {:?}/{:?}", pkt.ts.pts, pkt.ts.dts)); + } if stream_no >= self.packets.len() { panic!("wrong packet stream"); } self.packets[stream_no].push_back(pkt); } - pub fn get_packet(&mut self) -> Option { + pub fn get_packet(&mut self, dbg: &mut Option) -> Option { if self.sync { + if let Some(ref mut dlog) = dbg { + let mut msg = " sync: queue fill status -".to_string(); + for queue in self.packets.iter() { + msg += &format!(" {}", queue.len()); + } + dlog.log(DebugLog::SYNC, &msg); + } let mut all_with_time = true; let mut min_ts = None; let mut max_ts = None; @@ -337,29 +420,38 @@ impl OutputQueue { } if !all_with_time { println!("Some packets do not have time set, synchronisation is not possible!"); + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, "Some packets do not have time set, synchronisation is not possible!"); + } self.sync = false; - return self.get_last_packet(); + return self.get_last_packet(dbg); } if !self.had_warning { const THR: u64 = 2000; if let (Some(mints), Some(maxts)) = (min_ts, max_ts) { if mints + THR < maxts { println!("Queue times differ more than by {}s, synchronisation is not possible!", THR as f32 / 1000.0); + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, &format!("Queue times differ more than by {THR}ms, synchronisation is not possible!")); + } self.had_warning = true; self.sync = false; } } } if min_ts.is_some() { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, &format!(" sync: return packet for stream {min_sn} ts {:?}/{:?}", self.packets[min_sn][0].ts.pts, self.packets[min_sn][0].ts.dts)); + } self.packets[min_sn].pop_front() } else { - self.get_last_packet() + self.get_last_packet(dbg) } } else { - self.get_last_packet() + self.get_last_packet(dbg) } } - pub fn get_last_packet(&mut self) -> Option { + pub fn get_last_packet(&mut self, dbg: &mut Option) -> Option { let last_str = self.cur_stream; loop { let idx = self.cur_stream; @@ -368,9 +460,15 @@ impl OutputQueue { self.cur_stream = 0; } if let Some(pkt) = self.packets[idx].pop_front() { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, &format!(" sync: return packet for stream {} ts {:?}/{:?}", pkt.get_stream().get_num(), pkt.ts.pts, pkt.ts.dts)); + } return Some(pkt); } if self.cur_stream == last_str { + if let Some(ref mut dlog) = dbg { + dlog.log(DebugLog::SYNC, &format!(" sync: no packets to output")); + } break; } } @@ -406,6 +504,8 @@ pub struct Transcoder { pub fixed_rate: bool, pub profile: Option, + + pub debug: Option, } impl Transcoder { @@ -1152,12 +1252,18 @@ println!("encoder {} is not supported by output (expected {})", istr.id, istr.ge match (iname, ifmt.as_ref().map(|s| s.as_str())) { (Some(name), Some("imgseq")) => { println!("trying image sequence {}", name); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, &format!("Input {i}: trying image sequence {name}")); + } let mut isdc = ImgSeqDemuxerCreator::new(name.as_str()); parse_and_apply_options!(isdc, &self.demux_opts[i], "input"); let isd = if let Ok(ctx) = isdc.open() { ctx } else { println!("failed to create image sequence demuxer!"); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, &format!("input {i}: failed to create image sequence")); + } return false; }; let dmx = DemuxerObject::create_imgseq(isd); @@ -1168,15 +1274,28 @@ println!("encoder {} is not supported by output (expected {})", istr.id, istr.ge println!(" stream {}({}) - {} {}", i, i + isn_start, s, info.get_name()); } } + if let Some(ref mut dbg) = self.debug { + for i in 0..dmx.get_num_streams() { + let s = dmx.get_stream(i).unwrap(); + let info = s.get_info(); + dbg.log(DebugLog::DEMUX, &format!(" stream {i}({}) - {s} {}", i + isn_start, info.get_name())); + } + } isn_start += dmx.get_num_streams(); demuxers.push((dmx, false)) }, (Some(name), _) => { print!("Input {i}: {name}"); let res = File::open(name); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, &format!("Input {i}: {name}")); + } if res.is_err() { println!(); println!("error opening input"); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, "error opening input"); + } return false; } let file = res.unwrap(); @@ -1200,9 +1319,15 @@ println!("encoder {} is not supported by output (expected {})", istr.id, istr.ge if dmx.is_none() { println!(); println!("cannot create demuxer"); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, &format!("demuxer creation failed")); + } return false; } println!(" type {dmx}"); + if let Some(ref mut dbg) = self.debug { + dbg.log(DebugLog::DEMUX, &format!("input {i}: type {dmx}")); + } parse_and_apply_options!(dmx, &self.demux_opts[i], "input"); if print_info { for i in 0..dmx.get_num_streams() { @@ -1211,6 +1336,13 @@ println!("encoder {} is not supported by output (expected {})", istr.id, istr.ge println!(" stream {}({}) - {} {}", i, i + isn_start, s, info.get_name()); } } + if let Some(ref mut dbg) = self.debug { + for i in 0..dmx.get_num_streams() { + let s = dmx.get_stream(i).unwrap(); + let info = s.get_info(); + dbg.log(DebugLog::DEMUX, &format!(" stream {i}({}) - {s} {}", i + isn_start, info.get_name())); + } + } isn_start += dmx.get_num_streams(); demuxers.push((dmx, false)); }, @@ -1219,4 +1351,9 @@ println!("encoder {} is not supported by output (expected {})", istr.id, istr.ge } true } + pub fn debug_log(&mut self, level: u32, msg: &str) { + if let Some(ref mut dbg) = self.debug { + dbg.log(level, msg); + } + } }