No Podcast Update?

음

이건 무슨 상황일까?
mp3 파일은 레코딩이 제대로 되었고, md 파일도 만들었는데 site를 rebuild했다는 메시지가 오질 않는다. 안그래도 Telegram 을 이용해서 메시지를 보내는 기능을 추가해야 겠다고 생각했을때 아래처럼 정상적으로 동작하는 경우가 아니라 뭔가 문제가 있는 상황을 어떻게 알 수 있을까 하는 고민을 했었는데 생각보다 일찍 그 상황(아마도 많은 경우 중 하나 겠지만) 이 온 듯했다. 이렇게 메시지가 안 온 것으로 뭔가 문제가 있다는 걸 판단하는 건 비효율적인 방법이라 보다 적극적으로 어떤 비정상 상황이고, 가능하면 왜 그런 지도 파악해서 메시지를 보내게 할 필요가 있다는 생각을 했었는데…

집에 와서 우선 상태부터 확인해 보니 mp3 파일은 정상적으로 만들어져 있고, md 파일도 만들어져있는데 사이트 리빌드가 안되었다. Cron에 12시 4분 그리고 5분에 각각 mp3 파일을 mini2에서 가져오고, mp3 파일의 길이를 확인해서 md 파일을 만들고 site를 다시 빌드하는 작업을 하게 했는데 연속으로 있는 이 두 개의 cron 작업 중 하나만 동작하지 않는 것은 아닌 듯 하다. 이틀 연속으로 첫번째 cron job은 동작하고, 두 번째만 동작하지 않을 확률은 거의 없어 보이는데 생각해 보니 md 파일을 만드는 작업 자체가 두 번째 cron job에서 하는 일 중 하나라 두 번째 cron job도 최소한 실행은 정상적으로 된 걸로 판단할 수 있다.

그럼 왜 site rebuild가 안되었을까? Cron에 적어놓은 두 번째 job을 보니 cron의 동작을 /tmp/cron.out 파일에 기록하게 해 놨다는 게 보였다. 그래서 로그 파일을 확인해 보니 아하…

file /XXX/static/podcast/cinema-2020-06-25.mp3 is not found

파일이 없다고?
혹시나 하고 확인해 보니 파일이 멀쩡하게 존재한다.

그럼 저 Cron job이 동작했을 때 파일이 없었다는 건가? 어떻게 확인할 수 있지 라고 고민하려는 순간 파일 시스템에서 파일 시간을 확인할 수 있겠다라는 생각이 들었다. 그래서 확인해 보니

...
-rw-r--r-- 1 cychong cychong 57600879 Jun 26 12:05 cinema-2020-06-24.mp3
-rw-r--r-- 1 cychong cychong 57600879 Jun 26 12:06 cinema-2020-06-25.mp3
-rw-r--r-- 1 cychong cychong 57600879 Jun 26 12:06 cinema-2020-06-26.mp3

정상적으로 사이트 빌드가 된 24일은 12:5분에 파일이 생성되었는데 제대로 사이트 빌드가 되지 않은 25, 26일은 12:6분에 파일이 생성되었다는 게 보였다. 저 시간은 실제로 사이트 빌드 작업을 수행하는 mini1에서 mini2으로부터 파일이 가져온 시점이니까 어떤 이유인 지는 알기 어렵지만 위에서 본 에러를 찍은 두 번째 cron job에서 호출한 스크립트가 동작할 시점에 파일이 없었다는 게 확인된 셈이다. 아마도 내부 네트웍에 뭔가 이슈가 있었던지, mini2나 mini1이 로드가 높았거나 했을 것 같은데 확률적으로는 mini1이 힘들어서 그랬을 것 같고(이틀 연속으로 12:00pm까지는 멀쩡하게 녹음을 한 mini2를 의심하기는 좀 무리인 듯 하니)

이제 원인을 파악했으니 문제를 해결해야 할 차례.
우선 기존에 녹음된 25일과 26일 건은 md 파일의 frontmatter에 적는 mp3 파일의 duration만 고치고 사이트를 다시 빌드하면 될 듯 하다. 지금 script에서 파일파일을 찾지 못하면 duration을 0으로 설정하고 md 파일을 만드는데, 내가 만든 script에서 사이트를 다시 빌드하는 조건을 md 파일과 mp3 파일이 모두 존재하는 경우로 했는데 이번 경우에는 아직 mp3 파일을 다 받아오기 전인 12:5분 상황이라 사이트를 빌드하지 않은 것으로 보인다.

    if options.no_publish == False:
        if os.path.exists(mp3_file) and os.path.exists(md_file):
            logger.info("Rebuild site")
            os.system("cd %s ; /usr/bin/hugo -t zen" %podcast_base)
            tg.send_msg("(%s) Rebuild site" %(hostname))
        else:
            logger.info("file(s) is missing - mp3(%s), md(%s)" %(os.path.exists(mp3_file), os.path.exists(md_file)))
    else:
        logger.info("Skip site build")

앞에서 이야기했던 비정상 상황일 때 telegram으로 알릴 수 있게 하려면 우선 여기부터 log 파일에 기록하는 것 외에 telegram으로 보내면 되겠다.

위 코드에서 적은 로그 내용을 담은 파일을 확인해 보니 앞에서 파악하고 추정했던 바로 그 상황이 로그로 남아있는 걸 알 수 있다. 이것만 그냥 telegram으로 보냈으면 좋았으련만…. 앞에서 파악하고 추정했던 바로 그 상황이 로그로 남아있는 걸 알 수 있다. 이것만 그냥 telegram으로 보냈으면 좋았으련만…. 앞에서 파악하고 추정했던 바로 그 상황이 로그로 남아있는 걸 알 수 있다. 이것만 그냥 telegram으로 보냈으면 좋았으련만…. 앞에서 파악하고 추정했던 바로 그 상황이 로그로 남아있는 걸 알 수 있다. 이것만 그냥 telegram으로 보냈으면 좋았으련만….

...
2020-06-25 12:05:41,506 file(s) is missing - mp3(False), md(True)
...
2020-06-26 12:05:41,024 file(s) is missing - mp3(False), md(True)

지금은 정상적인 로그 상황을 보내고 있는데 뭔가….. 좀 내용을 요약해서 한번에 보내거나 조금 더 안정화 되면 비정상인 경우만 메시지를 보내는 방식으로 바꾸는 것도 고려해 봐야겠다. 충분히 안정화가 되었다는 확신이 생기면

그리고 근본적인 문제였던 12:4분에 시작된 mp3 파일 복사가 12:5분이 되기 전에 끝나지 않아 사이트 빌드가 수행되지 않은 것은 우선 사이트 빌드를 파일을 가져오는 cron job 보다 10분 후에 수행하는 것으로 수정해야겠다. 설마 10분내에는 가져오겠지. 두 개 머신이 그것도 허브에 1Gbps 로 직접 연결되어 있는데 설마….

하는 김에 파일 가져오는 것도 5분에 수행하도록 바꾸고(4분은 이상해….)

05 12 * * * cd /home/cychong/work/cbs-ost/script && ./scp.sh >> /tmp/cron.out 2>&1
15 12 * * * cd /home/cychong/work/cbs-ost/script && ./publish.sh >> /tmp/cron.out 2>&1