Skip to content

Commit afc011b

Browse files
rrahrrah
committed
Better logging
1 parent e226adc commit afc011b

2 files changed

Lines changed: 133 additions & 75 deletions

File tree

‎formvideo.py‎

Lines changed: 130 additions & 72 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,9 @@
77
import os.path
88
import shutil
99

10+
# Set default logger (is overwritten within certain functions)
1011
logger = logging.getLogger(__name__)
12+
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
1113

1214
FFMPEG_BIN = "ffmpeg"
1315
IMAGEMAGICK_BIN = "convert"
@@ -51,8 +53,43 @@ def timecode_to_timestamp(timecode, framerate = FRAMERATE):
5153

5254
return "{:02d}:{:02d}:{:02d}.{:02d}".format(hours, minutes, seconds, int(frames*100/framerate))
5355

56+
class FileLogger():
57+
def critical(self, *args, **kwargs):
58+
self.main.critical(*args, **kwargs)
59+
self.file.critical(*args, **kwargs)
5460

55-
def form_video(video, talk, start_tc, end_tc, framerate = FRAMERATE, out_dir = OUT_DIR, temp_dir = TEMP_DIR):
61+
def exception(self, *args, **kwargs):
62+
self.main.exception(*args, **kwargs)
63+
self.file.exception(*args, **kwargs)
64+
65+
def error(self, *args, **kwargs):
66+
self.main.error(*args, **kwargs)
67+
self.file.error(*args, **kwargs)
68+
69+
def warning(self, *args, **kwargs):
70+
self.main.warning(*args, **kwargs)
71+
self.file.warning(*args, **kwargs)
72+
73+
def debug(self, *args, **kwargs):
74+
self.main.debug(*args, **kwargs)
75+
self.file.debug(*args, **kwargs)
76+
77+
def info(self, *args, **kwargs):
78+
self.main.info(*args, **kwargs)
79+
self.file.info(*args, **kwargs)
80+
81+
def __init__(self, request_id, task_log):
82+
self.main = logging.getLogger(__name__).getChild(str(request_id))
83+
self.file = logging.getLogger(str(request_id))
84+
self.file.propagate = False
85+
86+
file_handler = logging.FileHandler(task_log)
87+
file_handler.setFormatter(formatter)
88+
self.file.setLevel(logging.DEBUG)
89+
self.file.addHandler(file_handler)
90+
91+
92+
def form_video(task, video, talk, start_tc, end_tc, framerate = FRAMERATE, out_dir = OUT_DIR, temp_dir = TEMP_DIR):
5693

5794
temp_dir = Path(temp_dir).resolve()
5895
out_dir = Path(out_dir).resolve()
@@ -106,16 +143,25 @@ def form_video(video, talk, start_tc, end_tc, framerate = FRAMERATE, out_dir = O
106143
except KeyError:
107144
filename = start_timestamp
108145

109-
Path.joinpath(Path(temp_dir), Path(filename)).mkdir(parents=True, exist_ok=True)
146+
job_temp_dir = Path.joinpath(Path(temp_dir), Path(filename))
147+
job_temp_dir.mkdir(parents=True, exist_ok=True)
110148

111149
copr_file = Path.joinpath(Path(temp_dir), Path(filename), copr_file)
112150
spres_file = Path.joinpath(Path(temp_dir), Path(filename), spres_file)
113151
stalk_file = Path.joinpath(Path(temp_dir), Path(filename), stalk_file)
114152

115153
output_file = Path(filename + ".mp4")
116-
log_file = Path(filename + ".log")
117154
output_path = Path.joinpath(Path(out_dir), output_file)
118-
log_path = Path.joinpath(Path(LOG_DIR), log_file)
155+
156+
# Setup log paths
157+
job_log_dir = Path.joinpath(Path(LOG_DIR), Path(str(task.request.id)))
158+
job_log_dir.mkdir(parents=True, exist_ok=True)
159+
build_log = Path.joinpath(job_log_dir, Path("main_build.log"))
160+
loud_log = Path.joinpath(job_log_dir, Path("loudness_analysis.log"))
161+
task_log = Path.joinpath(job_log_dir, Path(filename + ".log"))
162+
163+
# And set up the logger
164+
logger = FileLogger(task.request.id, task_log)
119165

120166
start_title_args = [
121167
IMAGEMAGICK_BIN,
@@ -148,18 +194,19 @@ def form_video(video, talk, start_tc, end_tc, framerate = FRAMERATE, out_dir = O
148194
"-f", "null", "-"
149195
]
150196

151-
with open(log_path, "a") as error_log:
152-
153-
# Build all the text assets
154-
logger.info("Building text assets.")
155-
subprocess.check_output(start_title_args)
156-
subprocess.check_output(start_pres_arg)
157-
subprocess.check_output(copyright_args)
197+
# Build all the text assets
198+
logger.info("Building text assets.")
199+
subprocess.check_output(start_title_args)
200+
subprocess.check_output(start_pres_arg)
201+
subprocess.check_output(copyright_args)
158202

159-
# First FFmpeg pass for getting loudness stats
160-
logger.info("Detecting loudness information.")
161-
logger.debug(ffmpeg_loudness_args)
162-
analysis = subprocess.check_output(ffmpeg_loudness_args, stderr=subprocess.STDOUT, cwd=working_dir).decode("utf-8").split("\n")
203+
# First FFmpeg pass for getting loudness stats
204+
logger.info("Detecting loudness information.")
205+
logger.debug(ffmpeg_loudness_args)
206+
with open(loud_log, "a") as error_log:
207+
loud_output = subprocess.check_output(ffmpeg_loudness_args, stderr=subprocess.STDOUT, cwd=working_dir).decode("utf-8")
208+
error_log.writelines(loud_output)
209+
analysis = loud_output.split("\n")
163210

164211
json_detect = False
165212
json_string = ""
@@ -170,63 +217,66 @@ def form_video(video, talk, start_tc, end_tc, framerate = FRAMERATE, out_dir = O
170217
if json_detect:
171218
json_string += line
172219
loud_vals = json.loads(json_string)
220+
logger.info("Extracted loudness information.")
221+
logger.debug(loud_vals)
222+
223+
# Build file metadata list
224+
metadata = [
225+
"-metadata", "title={}".format(talk["title"]),
226+
"-metadata", "artist={}".format(talk["presenter"]),
227+
"-metadata", "year=2024",
228+
]
173229

174-
# Build file metadata list
175-
metadata = [
176-
"-metadata", "title={}".format(talk["title"]),
177-
"-metadata", "artist={}".format(talk["presenter"]),
178-
"-metadata", "year=2024",
179-
]
180-
181-
try:
182-
metadata.extend(("-metadata", "synopsis={}".format(talk["description"])))
183-
except KeyError:
184-
pass
185-
186-
# Run the final build FFmpeg
187-
ffmpeg_args = [
188-
FFMPEG_BIN,
189-
"-ss", start_ts, "-to", end_ts, "-i", video.name, #0
190-
"-stream_loop", "-1", "-r", str(framerate), "-i", BKGD_FILE, #1
191-
"-loop", "1", "-framerate", str(framerate), "-i", TRANSP_FILE, #2
192-
"-loop", "1", "-framerate", str(framerate), "-i", spres_file, #3
193-
"-loop", "1", "-framerate", str(framerate), "-i", stalk_file, #4
194-
"-loop", "1", "-framerate", str(framerate), "-i", LOGO_FILE, #5
195-
"-loop", "1", "-framerate", str(framerate), "-i", SPONS_FILE, #6
196-
"-loop", "1", "-framerate", str(framerate), "-i", copr_file, #7
197-
"-filter_complex", ("[0:a]afade=in:d={in_:.2f},afade=out:st={out_st:.2f}:d={out:.2f},adelay={title_end:.2f}:all=1,".format(in_ = afade_in, out = afade_out, out_st = afade_offset, spn_dur = spn_dur, title_end = title_end * 1000) +
198-
"loudnorm=I={target:.2f}:TP=-1.5:measured_I={mI}:measured_tp={mTP}:measured_LRA={mLRA}:measured_thresh={mTH}:offset={off}:linear=true:print_format=json[a1];".format(
199-
target = LOUD_LEVEL,
200-
mI = loud_vals["input_i"],
201-
mTP = loud_vals["input_tp"],
202-
mLRA = loud_vals["input_lra"],
203-
mTH = loud_vals["input_thresh"],
204-
off = loud_vals["target_offset"]) +
205-
"[5:v]split[l1][l2];" +
206-
"[1:v]settb=1/{framerate:.2f},split[bg1][bg2];".format(framerate = framerate) +
207-
"[0:v]settb=1/{framerate:.2f}[m1];".format(framerate = framerate) +
208-
"[2:v][3:v]overlay=x=60:y=640:shortest=1[s2];" +
209-
"[s2][4:v]overlay=x=60:y=320:shortest=1[s3];" +
210-
"[s3][l1]overlay=shortest=1[s4];" +
211-
"[6:v][s4]xfade=offset={spn_dur:.2f}:duration={spn_fade_out:.2f}[s5];".format(spn_dur = spn_dur, spn_fade_out = spn_fade_out) +
212-
"[bg1]trim=start=0:end={title_end:.2f}[bg3];".format(title_end = title_end) +
213-
"[bg3][s5]overlay[s6];" +
214-
"[bg2][l2]overlay[e1];" +
215-
"[e1][7:v]overlay=x=870:y=70:shortest=1,trim=start=0:end={end_tdur:.2f}[e2];".format(end_tdur = end_tdur) +
216-
"[m1][e2]xfade=offset={eb_start:.2f}:duration=1,fade=out:st={eb_end:.2f}:d={end_fade:.2f}[m2];".format(eb_start = fade_offset, eb_end = eb_end, end_fade = end_fade) +
217-
"[s6][m2]xfade=offset={title_end:.2f}:duration={title_fade_out:.2f},fade=in:d={spn_fade_in:.2f}[p1]".format(title_fade_out = title_fade_out, title_end = title_end, spn_fade_in = spn_fade_in)
218-
219-
),
220-
"-map", "[p1]", "-map", "[a1]", "-map_metadata", "-1",
221-
*metadata,
222-
"-c:v", "h264", "-crf", "16", "-g", str(math.floor(framerate/2)), "-flags", "+cgop",
223-
"-c:a", "aac", "-ar", "48000", "-b:a", "128k",
224-
"-r", str(framerate), "-pix_fmt", "yuv420p", "-movflags", "+faststart", output_path, "-y"
225-
]
226-
logger.info("Running main build.")
227-
logger.debug(ffmpeg_args)
230+
try:
231+
metadata.extend(("-metadata", "synopsis={}".format(talk["description"])))
232+
except KeyError:
233+
pass
234+
235+
# Run the final build FFmpeg
236+
ffmpeg_args = [
237+
FFMPEG_BIN,
238+
"-ss", start_ts, "-to", end_ts, "-i", video.name, #0
239+
"-stream_loop", "-1", "-r", str(framerate), "-i", BKGD_FILE, #1
240+
"-loop", "1", "-framerate", str(framerate), "-i", TRANSP_FILE, #2
241+
"-loop", "1", "-framerate", str(framerate), "-i", spres_file, #3
242+
"-loop", "1", "-framerate", str(framerate), "-i", stalk_file, #4
243+
"-loop", "1", "-framerate", str(framerate), "-i", LOGO_FILE, #5
244+
"-loop", "1", "-framerate", str(framerate), "-i", SPONS_FILE, #6
245+
"-loop", "1", "-framerate", str(framerate), "-i", copr_file, #7
246+
"-filter_complex", ("[0:a]afade=in:d={in_:.2f},afade=out:st={out_st:.2f}:d={out:.2f},adelay={title_end:.2f}:all=1,".format(in_ = afade_in, out = afade_out, out_st = afade_offset, spn_dur = spn_dur, title_end = title_end * 1000) +
247+
"loudnorm=I={target:.2f}:TP=-1.5:measured_I={mI}:measured_tp={mTP}:measured_LRA={mLRA}:measured_thresh={mTH}:offset={off}:linear=true:print_format=json[a1];".format(
248+
target = LOUD_LEVEL,
249+
mI = loud_vals["input_i"],
250+
mTP = loud_vals["input_tp"],
251+
mLRA = loud_vals["input_lra"],
252+
mTH = loud_vals["input_thresh"],
253+
off = loud_vals["target_offset"]) +
254+
"[5:v]split[l1][l2];" +
255+
"[1:v]settb=1/{framerate:.2f},split[bg1][bg2];".format(framerate = framerate) +
256+
"[0:v]settb=1/{framerate:.2f}[m1];".format(framerate = framerate) +
257+
"[2:v][3:v]overlay=x=60:y=640:shortest=1[s2];" +
258+
"[s2][4:v]overlay=x=60:y=320:shortest=1[s3];" +
259+
"[s3][l1]overlay=shortest=1[s4];" +
260+
"[6:v][s4]xfade=offset={spn_dur:.2f}:duration={spn_fade_out:.2f}[s5];".format(spn_dur = spn_dur, spn_fade_out = spn_fade_out) +
261+
"[bg1]trim=start=0:end={title_end:.2f}[bg3];".format(title_end = title_end) +
262+
"[bg3][s5]overlay[s6];" +
263+
"[bg2][l2]overlay[e1];" +
264+
"[e1][7:v]overlay=x=870:y=70:shortest=1,trim=start=0:end={end_tdur:.2f}[e2];".format(end_tdur = end_tdur) +
265+
"[m1][e2]xfade=offset={eb_start:.2f}:duration=1,fade=out:st={eb_end:.2f}:d={end_fade:.2f}[m2];".format(eb_start = fade_offset, eb_end = eb_end, end_fade = end_fade) +
266+
"[s6][m2]xfade=offset={title_end:.2f}:duration={title_fade_out:.2f},fade=in:d={spn_fade_in:.2f}[p1]".format(title_fade_out = title_fade_out, title_end = title_end, spn_fade_in = spn_fade_in)
267+
268+
),
269+
"-map", "[p1]", "-map", "[a1]", "-map_metadata", "-1",
270+
*metadata,
271+
"-c:v", "h264", "-crf", "16", "-g", str(math.floor(framerate/2)), "-flags", "+cgop",
272+
"-c:a", "aac", "-ar", "48000", "-b:a", "128k",
273+
"-r", str(framerate), "-pix_fmt", "yuv420p", "-movflags", "+faststart", output_path, "-y"
274+
]
275+
logger.info("Running main build.")
276+
logger.debug(ffmpeg_args)
277+
with open(build_log, "a") as error_log:
228278
subprocess.check_output(ffmpeg_args, stderr=error_log, cwd=working_dir)
229-
logger.info("Completed main build.")
279+
logger.info("Completed main build.")
230280

231281
return str(output_path)
232282

@@ -261,7 +311,15 @@ def ingest_video(input_path, output_dir, framerate = FRAMERATE):
261311
return str(output_path)
262312

263313
if __name__ == "__main__":
264-
logging.basicConfig()
314+
315+
logging.basicConfig(level=logging.INFO)
316+
317+
class Object(object):
318+
pass
319+
320+
task = Object()
321+
task.request = Object()
322+
task.request.id = 1
265323
talk_data = {
266324
"title": "'This is Britain' – British cultural propaganda films of the 1930s-1940s, their creation, and their far-reaching global legacy",
267325
"presenter": "Sarah Cole"
@@ -274,4 +332,4 @@ def ingest_video(input_path, output_dir, framerate = FRAMERATE):
274332
"presenter": "Kim M"
275333
}
276334

277-
form_video("static/video/stagea/bbb_sunflower_2160p_60fps_normal.mp4", talk_data, "00:05:05:00", "00:05:20:00", out_dir=Path("/mnt/vid_working/output"))
335+
form_video(task, "static/video/source/bbb_50.mp4", talk_data, "00:05:05:00", "00:05:20:00")

‎tasks.py‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,9 +18,9 @@
1818
class ErrSigTerm(Exception):
1919
pass
2020

21-
@celery.shared_task(ignore_result=False)
22-
def build_video(*args, **kwargs):
23-
result = formvideo.form_video(*args, **kwargs)
21+
@celery.shared_task(ignore_result=False, bind=True)
22+
def build_video(self, *args, **kwargs):
23+
result = formvideo.form_video(self, *args, **kwargs)
2424
return result
2525

2626
@celery.shared_task(ignore_result=False)

0 commit comments

Comments
 (0)