pythonプログラムが想定外の動きをするのでログ情報を付加した
「取得した今日明日の天気予報をPythonでLINE Notifyに送付」で毎朝６時50分に、今日と明日の天気をお天気マーク付きで LINE Notify に転送しています。
毎日、朝起きた時に、その日の天気を LINE Notify で確認しているんですが、稀に天気の情報が送付されない日があるんです。
直近では、2021/12/14 がそうでした。13日と15日のお天気情報は送られてきているんですが、何故か 12/14 の天気情報が送られていないんです。
この情報は Python のプログラムで作成し、curl コマンドで Line notify に送付しているので、プログラムが何か想定外の動きをしたと考えられます。今回は、この調査をしてみたいと思います。
何から手を付けるか？
そうは言ったものの現状では全く手掛かりがありません。
天気情報が LINE Notify に送付されない日の syslog を見てみたんですが、起動時間にコマンドが発行されていることだけは確認できましたが、確認できたのはそれだけです。
何かエラーが出ていないか見てみましたが、これといった情報はありませんでした。
エラーがあるのなら除去したいのですが、情報が全くないので、手のつけようがありませんね。
色々考えてみたんですが、まずは、ログを取って手掛かりにすることを思いつきました。問題が発生した際、プログラムがどこまで動いたかわかればデバッグの端緒になります。
プログラムは python で書いています。ネット上で調べると python のログ出力の方法がたくさん出ています。いくつか読んでみたんですが、こういっちゃなんですがスキルの乏しい 60爺には難しくて理解できません。
60爺としては、サンプルプログラムを取り込んでさっさと終わりにしたいという気持ちがあり、技術的なことは深く追及する必要がないんです。
ログ情報組み込み
ログ設定プログラム組み込み
そこで、色々とログに関する記事を読んだんですが、末尾に載せた参考記事にあったプログラムを組み込んでみました。
参考記事の末尾にある「ERROR以上のログだけを出力する」プログラムを、60爺のプログラムに組み込みました。
参考記事では「ERROR以上のログだけを出力する」ようになっていますが、「エラーの原因を特定したい場合に必要な詳細情報」が出力されるように変更しました。
即ち、下記のように5行目と9行目の「ERROR」を「DEBUG」にすればいいですね。
# インスタンスの作成
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG) #DEBUGに変更
# "example.log"を出力先とするファイルハンドラ作成
ch = logging.FileHandler(filename="/home/pi/example.log")
#DEBUGレベルまで見る
ch.setLevel(logging.DEBUG) #DEBUGに変更import文は、プログラムのトップに、25行目以降のクローズ分はプログラムの最後に持ってきました。
import urllib.request
from bs4 import BeautifulSoup
import logging #ログのimport
def main():
……
#クローズ
logger.info('program end')
logger.removeHandler(ch)
ch.close()そして、3行目の「# インスタンスの作成」から17行目の「# logger(インスタンス)にファイルハンドラの情報を与える」までをプログラムの先頭に挿入しました。
### Execute
# インスタンスの作成
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
# "example.log"を出力先とするファイルハンドラ作成
ch = logging.FileHandler(filename="/home/pi/example.log")
#DEBUGレベルまで見る
ch.setLevel(logging.DEBUG)
# ログの記述フォーマット
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
# ファイルハンドラにフォーマット情報を与える
ch.setFormatter(formatter)
# logger(インスタンス)にファイルハンドラの情報を与える
logger.addHandler(ch)
mark_path ="/home/pi/work/tenki_mark/"
LINE_Notify_URL = "https://notify-api.line.me/api/notify"ログ出力の組み込み
① 開始終了時のログ
次に、必要なログ情報をプログラムの各所にセットして情報を取れるようにします。
そうはいっても大層なことではなく、プログラムの開始及び終了時に「program start」、「program end」を、それぞれの関数の先頭と最後に「関数名 start」と「関数名 end」を挿入しただけです。
② url読み込み時のログ
あとは、url読み込み時の「res.read」と title名の表示（下記#ログ追加を参照）を行いました。
def Parser(rssurl):
logger.info('Parser start')
with urllib.request.urlopen(rssurl) as res:
xml = res.read()
logger.info('res.read') #ログ追加
soup = BeautifulSoup(xml, "html.parser")
for item in soup.find_all("item"):
title = item.find("title").string
description = item.find("description").string
logger.info('**item title=%s',title) #ログ追加
if title.find("[ PR ]") == -1:
tenki.append(title)
detail.append(description)
logger.info('Parser end')③ curlコマンド内容
最後に、出力している curlコマンドの内容をログとして出しましょう。
# curl comand
cmd = 'curl -X POST %s -H "%s %s" -F "message=%s" -F "imageFile=@%s"' % (LINE_Notify_URL , H_txt , taken , message , files)
print(cmd)
logger.info('@@cmd-->%s',cmd)
# コマンド発行
os.system(cmd)
logger.info('curl comand out')
logger.info('ck_Weather end')出力されたログ
ログを追加した後、試しにプログラムを実行してみました。
その結果取得できたログは次の通りです。
2022-02-17 08:24:38,718 - __main__ - INFO - program start
2022-02-17 08:24:38,719 - __main__ - INFO - main start
2022-02-17 08:24:38,719 - __main__ - INFO - Parser start
2022-02-17 08:24:39,549 - __main__ - INFO - res.read
2022-02-17 08:24:39,572 - __main__ - INFO - **item title=【 17日（木） 東部（横 浜） 】 晴時々曇 - 9℃/2℃ - Yahoo!天気・災害
2022-02-17 08:24:39,573 - __main__ - INFO - **item title=【 18日（金） 東部（横 浜） 】 晴れ - 11℃/2℃ - Yahoo!天気・災害
2022-02-17 08:24:39,574 - __main__ - INFO - **item title=【 19日（土） 東部（横 浜） 】 曇のち雨 - 12℃/3℃ - Yahoo!天気・災害
2022-02-17 08:24:39,575 - __main__ - INFO - **item title=【 20日（日） 東部（横 浜） 】 曇一時雨 - 13℃/3℃ - Yahoo!天気・災害
2022-02-17 08:24:39,576 - __main__ - INFO - **item title=【 21日（月） 東部（横 浜） 】 晴時々曇 - 10℃/2℃ - Yahoo!天気・災害
2022-02-17 08:24:39,577 - __main__ - INFO - **item title=【 22日（火） 東部（横 浜） 】 晴時々曇 - 12℃/1℃ - Yahoo!天気・災害
2022-02-17 08:24:39,578 - __main__ - INFO - **item title=【 23日（水） 東部（横 浜） 】 晴時々曇 - 11℃/2℃ - Yahoo!天気・災害
2022-02-17 08:24:39,579 - __main__ - INFO - **item title=【 24日（木） 東部（横 浜） 】 晴時々曇 - 11℃/2℃ - Yahoo!天気・災害
2022-02-17 08:24:39,579 - __main__ - INFO - **item title=【 横浜・川崎 】注意報 があります - Yahoo!天気・災害
2022-02-17 08:24:39,580 - __main__ - INFO - **item title=【 湘南 】注意報があり ます - Yahoo!天気・災害
2022-02-17 08:24:39,581 - __main__ - INFO - **item title=【 三浦半島 】注意報が あります - Yahoo!天気・災害
2022-02-17 08:24:39,582 - __main__ - INFO - Parser end
2022-02-17 08:24:39,582 - __main__ - INFO - ck_Weather start i=0
2022-02-17 08:24:39,584 - __main__ - INFO - @@cmd-->curl -X POST https://notify-api.line.me/api/notify -H "Authorization: Bearer **************" -F "message=【 17日（木） 東部（横浜） 】 晴時々曇 - 9℃/2℃ - Yahoo!天気・災害" -F "imageFile=@/home/pi/****/tenki_mark/SunToCloud.jpg"
2022-02-17 08:24:40,514 - __main__ - INFO - curl comand out
2022-02-17 08:24:40,515 - __main__ - INFO - ck_Weather end
2022-02-17 08:24:40,516 - __main__ - INFO - ck_Weather start i=1
2022-02-17 08:24:40,517 - __main__ - INFO - @@cmd-->curl -X POST https://notify-api.line.me/api/notify -H "Authorization: Bearer **************" -F "message=【 18日（金） 東部（横浜） 】 晴れ - 11℃/2℃ - Yahoo!天気・災害" -F "imageFile=@/home/pi/****/tenki_mark/Sun.jpg"
2022-02-17 08:24:41,876 - __main__ - INFO - curl comand out
2022-02-17 08:24:41,877 - __main__ - INFO - ck_Weather end
2022-02-17 08:24:41,877 - __main__ - INFO - main end
2022-02-17 08:24:41,878 - __main__ - INFO - program endこのログが出力されるプログラムでしばらく運用して、「天気情報がLINE Notifyに送付されない」事象が発生した際にログの結果を確認してみようと思います。
urlopen例外処理追加
そう言っていたら、何と、お天気情報が送られてこない日が来ました。ログを確認すると、次の3行のみしか出ていません。
2022-03-06 06:50:02,601 - __main__ - INFO - program start
2022-03-06 06:50:02,602 - __main__ - INFO - main start
2022-03-06 06:50:02,602 - __main__ - INFO - Parser startここから推測すると、どうやら urlopen でエラーが発生した模様です。上述していますが、その部分のソースコードを再掲します。
## Parser : 天気情報WebページのHTMLタグから天気情報を抽出してパースするメソッド ####################
def Parser(rssurl):
logger.info('Parser start')
with urllib.request.urlopen(rssurl) as res:
xml = res.read()
logger.info('res.read')
soup = BeautifulSoup(xml, "html.parser")
for item in soup.find_all("item"):
title = item.find("title").string
description = item.find("description").string
logger.info('**item title=%s',title)
if title.find("[ PR ]") == -1:
tenki.append(title)
detail.append(description)
logger.info('Parser end')
### Executeここに例外処理を追加します。
そして、エラーが発生した場合は、エラーコードをログとして吐き出しすようにしました。
with urllib.request.urlopen(rssurl) as res:
try:
xml = res.read()
logger.info('res.read')
soup = BeautifulSoup(xml, "html.parser")
for item in soup.find_all("item"):
title = item.find("title").string
description = item.find("description").string
logger.info('**item title=%s',title)
if title.find("[ PR ]") == -1:
tenki.append(title)
detail.append(description)
except Exception as e:
logger.info('!! error !!=%s',e)この状態で同じ現象の再現を待つことにします。
衝撃！yahoo!天気 RSSサービス撤退
4/1 になって、さっそく天気情報が表示されない状況に陥りました。しかも、上記の例外処理を入れたにもかかわらず、その対応が生かされていないこともわかりました。
しかも、4/2 , 4/3 も同様の状況です。
そして分かったのがこちらです。
何と、yahoo!天気 RSSサービス撤退のお知らせです！yahoo まで RSS サービスを撤退してしまったのでした。
これでは、天気の情報が表示されないのも当たり前です。
ムムム、この先、どう対応したらよいでしょうか。しばらく、対応策を考えたいと思います！
参考
【Python】ログの出力してプログラムの実行記録を残す
60爺
60路を越え、RaspberryPi と出会い、その関係でブログ開設（2017/2～）となりました。始めてみると、コツコツやるのが性に合ってしまい、漢字の記事から家の補修・将棋・windows10関係・別名・言い方などジャンルを拡大して今に至ってます。まだまだ、元気なので新たな話題を見つけて皆様に提供できればと思っています。「プロフィールはこちら」