mirror of
https://github.com/unshackle-dl/unshackle.git
synced 2026-03-10 08:29:00 +00:00
feat(debug): add download output verification logging
Add comprehensive debug logging to diagnose N_m3u8DL-RE download failures where the process exits successfully but produces no output files.
This commit is contained in:
@@ -304,9 +304,15 @@ def download(
|
|||||||
arguments.extend(selection_args)
|
arguments.extend(selection_args)
|
||||||
|
|
||||||
log_file_path: Path | None = None
|
log_file_path: Path | None = None
|
||||||
|
meta_json_path: Path | None = None
|
||||||
if debug_logger:
|
if debug_logger:
|
||||||
log_file_path = output_dir / f".n_m3u8dl_re_{filename}.log"
|
log_file_path = output_dir / f".n_m3u8dl_re_{filename}.log"
|
||||||
arguments.extend(["--log-file-path", str(log_file_path)])
|
meta_json_path = output_dir / f"{filename}.meta.json"
|
||||||
|
arguments.extend([
|
||||||
|
"--log-file-path", str(log_file_path),
|
||||||
|
"--log-level", "DEBUG",
|
||||||
|
"--write-meta-json", "true",
|
||||||
|
])
|
||||||
|
|
||||||
track_url_display = track.url[:200] + "..." if len(track.url) > 200 else track.url
|
track_url_display = track.url[:200] + "..." if len(track.url) > 200 else track.url
|
||||||
debug_logger.log(
|
debug_logger.log(
|
||||||
@@ -394,6 +400,14 @@ def download(
|
|||||||
raise subprocess.CalledProcessError(process.returncode, arguments)
|
raise subprocess.CalledProcessError(process.returncode, arguments)
|
||||||
|
|
||||||
if debug_logger:
|
if debug_logger:
|
||||||
|
output_dir_exists = output_dir.exists()
|
||||||
|
output_files = []
|
||||||
|
if output_dir_exists:
|
||||||
|
try:
|
||||||
|
output_files = [f.name for f in output_dir.iterdir() if f.is_file()][:20]
|
||||||
|
except Exception:
|
||||||
|
output_files = ["<error listing files>"]
|
||||||
|
|
||||||
debug_logger.log(
|
debug_logger.log(
|
||||||
level="DEBUG",
|
level="DEBUG",
|
||||||
operation="downloader_n_m3u8dl_re_complete",
|
operation="downloader_n_m3u8dl_re_complete",
|
||||||
@@ -402,10 +416,47 @@ def download(
|
|||||||
"track_id": getattr(track, "id", None),
|
"track_id": getattr(track, "id", None),
|
||||||
"track_type": track.__class__.__name__,
|
"track_type": track.__class__.__name__,
|
||||||
"output_dir": str(output_dir),
|
"output_dir": str(output_dir),
|
||||||
|
"output_dir_exists": output_dir_exists,
|
||||||
|
"output_files_count": len(output_files),
|
||||||
|
"output_files": output_files,
|
||||||
"filename": filename,
|
"filename": filename,
|
||||||
},
|
},
|
||||||
)
|
)
|
||||||
|
|
||||||
|
# Warn if no output was produced - include N_m3u8DL-RE's logs for diagnosis
|
||||||
|
if not output_dir_exists or not output_files:
|
||||||
|
# Read N_m3u8DL-RE's log file for debugging
|
||||||
|
n_m3u8dl_log = ""
|
||||||
|
if log_file_path and log_file_path.exists():
|
||||||
|
try:
|
||||||
|
n_m3u8dl_log = log_file_path.read_text(encoding="utf-8", errors="replace")
|
||||||
|
except Exception:
|
||||||
|
n_m3u8dl_log = "<failed to read log file>"
|
||||||
|
|
||||||
|
# Read meta JSON to see what streams N_m3u8DL-RE parsed
|
||||||
|
meta_json_content = ""
|
||||||
|
if meta_json_path and meta_json_path.exists():
|
||||||
|
try:
|
||||||
|
meta_json_content = meta_json_path.read_text(encoding="utf-8", errors="replace")
|
||||||
|
except Exception:
|
||||||
|
meta_json_content = "<failed to read meta json>"
|
||||||
|
|
||||||
|
debug_logger.log(
|
||||||
|
level="WARNING",
|
||||||
|
operation="downloader_n_m3u8dl_re_no_output",
|
||||||
|
message="N_m3u8DL-RE exited successfully but produced no output files",
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"output_dir": str(output_dir),
|
||||||
|
"output_dir_exists": output_dir_exists,
|
||||||
|
"selection_args": selection_args,
|
||||||
|
"track_url": track.url[:200] + "..." if len(track.url) > 200 else track.url,
|
||||||
|
"n_m3u8dl_re_log": n_m3u8dl_log,
|
||||||
|
"n_m3u8dl_re_meta_json": meta_json_content,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
|
||||||
except ConnectionResetError:
|
except ConnectionResetError:
|
||||||
# interrupted while passing URI to download
|
# interrupted while passing URI to download
|
||||||
raise KeyboardInterrupt()
|
raise KeyboardInterrupt()
|
||||||
@@ -437,11 +488,17 @@ def download(
|
|||||||
)
|
)
|
||||||
raise
|
raise
|
||||||
finally:
|
finally:
|
||||||
|
# Clean up temporary debug files
|
||||||
if log_file_path and log_file_path.exists():
|
if log_file_path and log_file_path.exists():
|
||||||
try:
|
try:
|
||||||
log_file_path.unlink()
|
log_file_path.unlink()
|
||||||
except Exception:
|
except Exception:
|
||||||
pass
|
pass
|
||||||
|
if meta_json_path and meta_json_path.exists():
|
||||||
|
try:
|
||||||
|
meta_json_path.unlink()
|
||||||
|
except Exception:
|
||||||
|
pass
|
||||||
|
|
||||||
|
|
||||||
def n_m3u8dl_re(
|
def n_m3u8dl_re(
|
||||||
|
|||||||
@@ -572,8 +572,64 @@ class DASH:
|
|||||||
for control_file in save_dir.glob("*.aria2__temp"):
|
for control_file in save_dir.glob("*.aria2__temp"):
|
||||||
control_file.unlink()
|
control_file.unlink()
|
||||||
|
|
||||||
|
# Verify output directory exists and contains files
|
||||||
|
if not save_dir.exists():
|
||||||
|
error_msg = f"Output directory does not exist: {save_dir}"
|
||||||
|
if debug_logger:
|
||||||
|
debug_logger.log(
|
||||||
|
level="ERROR",
|
||||||
|
operation="manifest_dash_download_output_missing",
|
||||||
|
message=error_msg,
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_path": str(save_path),
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
raise FileNotFoundError(error_msg)
|
||||||
|
|
||||||
segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
|
segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
|
||||||
|
|
||||||
|
if debug_logger:
|
||||||
|
debug_logger.log(
|
||||||
|
level="DEBUG",
|
||||||
|
operation="manifest_dash_download_complete",
|
||||||
|
message="DASH download complete, preparing to merge",
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_dir_exists": save_dir.exists(),
|
||||||
|
"segments_found": len(segments_to_merge),
|
||||||
|
"segment_files": [f.name for f in segments_to_merge[:10]], # Limit to first 10
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
|
||||||
|
if not segments_to_merge:
|
||||||
|
error_msg = f"No segment files found in output directory: {save_dir}"
|
||||||
|
if debug_logger:
|
||||||
|
# List all contents of the directory for debugging
|
||||||
|
all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
|
||||||
|
debug_logger.log(
|
||||||
|
level="ERROR",
|
||||||
|
operation="manifest_dash_download_no_segments",
|
||||||
|
message=error_msg,
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"directory_contents": [str(p) for p in all_contents],
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
raise FileNotFoundError(error_msg)
|
||||||
|
|
||||||
if skip_merge:
|
if skip_merge:
|
||||||
# N_m3u8DL-RE handles merging and decryption internally
|
# N_m3u8DL-RE handles merging and decryption internally
|
||||||
shutil.move(segments_to_merge[0], save_path)
|
shutil.move(segments_to_merge[0], save_path)
|
||||||
|
|||||||
@@ -650,6 +650,44 @@ class HLS:
|
|||||||
|
|
||||||
# finally merge all the discontinuity save files together to the final path
|
# finally merge all the discontinuity save files together to the final path
|
||||||
segments_to_merge = find_segments_recursively(save_dir)
|
segments_to_merge = find_segments_recursively(save_dir)
|
||||||
|
|
||||||
|
if debug_logger:
|
||||||
|
debug_logger.log(
|
||||||
|
level="DEBUG",
|
||||||
|
operation="manifest_hls_download_complete",
|
||||||
|
message="HLS download complete, preparing to merge",
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_dir_exists": save_dir.exists(),
|
||||||
|
"segments_found": len(segments_to_merge),
|
||||||
|
"segment_files": [f.name for f in segments_to_merge[:10]], # Limit to first 10
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
|
||||||
|
if not segments_to_merge:
|
||||||
|
error_msg = f"No segment files found in output directory: {save_dir}"
|
||||||
|
if debug_logger:
|
||||||
|
all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
|
||||||
|
debug_logger.log(
|
||||||
|
level="ERROR",
|
||||||
|
operation="manifest_hls_download_no_segments",
|
||||||
|
message=error_msg,
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_dir_exists": save_dir.exists(),
|
||||||
|
"directory_contents": [str(p) for p in all_contents],
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
raise FileNotFoundError(error_msg)
|
||||||
|
|
||||||
if len(segments_to_merge) == 1:
|
if len(segments_to_merge) == 1:
|
||||||
shutil.move(segments_to_merge[0], save_path)
|
shutil.move(segments_to_merge[0], save_path)
|
||||||
else:
|
else:
|
||||||
@@ -889,7 +927,8 @@ class HLS:
|
|||||||
elif key.keyformat and key.keyformat.lower() == WidevineCdm.urn:
|
elif key.keyformat and key.keyformat.lower() == WidevineCdm.urn:
|
||||||
return key
|
return key
|
||||||
elif key.keyformat and key.keyformat.lower() in {
|
elif key.keyformat and key.keyformat.lower() in {
|
||||||
f"urn:uuid:{PR_PSSH.SYSTEM_ID}", "com.microsoft.playready"
|
f"urn:uuid:{PR_PSSH.SYSTEM_ID}",
|
||||||
|
"com.microsoft.playready",
|
||||||
}:
|
}:
|
||||||
return key
|
return key
|
||||||
else:
|
else:
|
||||||
@@ -927,9 +966,7 @@ class HLS:
|
|||||||
pssh=WV_PSSH(key.uri.split(",")[-1]),
|
pssh=WV_PSSH(key.uri.split(",")[-1]),
|
||||||
**key._extra_params, # noqa
|
**key._extra_params, # noqa
|
||||||
)
|
)
|
||||||
elif key.keyformat and key.keyformat.lower() in {
|
elif key.keyformat and key.keyformat.lower() in {f"urn:uuid:{PR_PSSH.SYSTEM_ID}", "com.microsoft.playready"}:
|
||||||
f"urn:uuid:{PR_PSSH.SYSTEM_ID}", "com.microsoft.playready"
|
|
||||||
}:
|
|
||||||
drm = PlayReady(
|
drm = PlayReady(
|
||||||
pssh=PR_PSSH(key.uri.split(",")[-1]),
|
pssh=PR_PSSH(key.uri.split(",")[-1]),
|
||||||
pssh_b64=key.uri.split(",")[-1],
|
pssh_b64=key.uri.split(",")[-1],
|
||||||
|
|||||||
@@ -314,8 +314,63 @@ class ISM:
|
|||||||
for control_file in save_dir.glob("*.aria2__temp"):
|
for control_file in save_dir.glob("*.aria2__temp"):
|
||||||
control_file.unlink()
|
control_file.unlink()
|
||||||
|
|
||||||
|
# Verify output directory exists and contains files
|
||||||
|
if not save_dir.exists():
|
||||||
|
error_msg = f"Output directory does not exist: {save_dir}"
|
||||||
|
if debug_logger:
|
||||||
|
debug_logger.log(
|
||||||
|
level="ERROR",
|
||||||
|
operation="manifest_ism_download_output_missing",
|
||||||
|
message=error_msg,
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_path": str(save_path),
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
raise FileNotFoundError(error_msg)
|
||||||
|
|
||||||
segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
|
segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
|
||||||
|
|
||||||
|
if debug_logger:
|
||||||
|
debug_logger.log(
|
||||||
|
level="DEBUG",
|
||||||
|
operation="manifest_ism_download_complete",
|
||||||
|
message="ISM download complete, preparing to merge",
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"save_dir_exists": save_dir.exists(),
|
||||||
|
"segments_found": len(segments_to_merge),
|
||||||
|
"segment_files": [f.name for f in segments_to_merge[:10]], # Limit to first 10
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
|
||||||
|
if not segments_to_merge:
|
||||||
|
error_msg = f"No segment files found in output directory: {save_dir}"
|
||||||
|
if debug_logger:
|
||||||
|
all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
|
||||||
|
debug_logger.log(
|
||||||
|
level="ERROR",
|
||||||
|
operation="manifest_ism_download_no_segments",
|
||||||
|
message=error_msg,
|
||||||
|
context={
|
||||||
|
"track_id": getattr(track, "id", None),
|
||||||
|
"track_type": track.__class__.__name__,
|
||||||
|
"save_dir": str(save_dir),
|
||||||
|
"directory_contents": [str(p) for p in all_contents],
|
||||||
|
"downloader": downloader.__name__,
|
||||||
|
"skip_merge": skip_merge,
|
||||||
|
},
|
||||||
|
)
|
||||||
|
raise FileNotFoundError(error_msg)
|
||||||
|
|
||||||
if skip_merge:
|
if skip_merge:
|
||||||
shutil.move(segments_to_merge[0], save_path)
|
shutil.move(segments_to_merge[0], save_path)
|
||||||
else:
|
else:
|
||||||
|
|||||||
Reference in New Issue
Block a user