はじめに
小ネタです。
作成するプログラムの要件で、コマンドを起動して、そのコマンドが「継続」している/していないことを確認する、という要件があります。
具体的には、pingコマンドを普通に打つと、コマンド自体は永遠に終わらず、
標準出力に延々と出続けます。
人が見るには標準出力にずっと出力し続けるのはいいですが、
プログラム的に処理する場合は、通常3回ぐらいで終わらせるものです。
が、、まぁ要件としてあるとしましょう。
そういう場合にPythonで書いてみました。
sarge
というライブラリがあります。
https://sarge.readthedocs.io/en/latest/overview.html
pythonに元々あるSubprocessを、簡単に使用するためのライブラリです。
特に、Subprocessを素で使うと面倒な処理に向いているようです。なので使ってみました。
ちなみに他も使ってみたのですが、むしろSubprocessより面倒だったという理由もあります。
環境
動作した環境は以下のとおりです。
- python 3.8.5
- sarge 0.1.6
$ pip install sarge
サンプルプログラム
以下がサンプルプログラムです。sargeのチュートリアルをほぼ丸パクリしました。
import sys
import threading
from multiprocessing import Value
import time
import logging
from sarge import capture_stdout, run, Capture
logger = logging.getLogger(__name__)
def progress(capture, d):
while True:
s = capture.readline(timeout=10.0)
if not s:
# timeoutのときにここに入る
logger.debug('No more data, breaking out')
with d.get_lock():
d.value = 100
break
logger.debug(f'cmd output {s}')
with d.get_lock():
d.value += 1
if d.value >= 5:
logger.debug(f'progress exited at {d.value}')
break
def main():
logger.debug(f'main start')
cmd = 'ping 192.168.132.128'
# cmd = 'ping 10.0.0.1' # エラーで出力しない場合はこちらを有効にする。
p = capture_stdout(cmd, async_=True)
d = Value('i')
d.value = 0
time.sleep(0.01)
t = threading.Thread(target=progress, args=(p.stdout, d))
t.start()
while(p.returncodes[0] is None):
p.commands[0].poll()
time.sleep(0.05)
if d.value >= 5:
break
t.join()
logger.debug(f'main exited')
if __name__ == '__main__':
logging.basicConfig(level=logging.DEBUG, filename='test_progress.log',
filemode='w', format='%(asctime)s %(threadName)-10s %(name)-15s %(lineno)4d %(message)s')
sys.exit(main())
プログラムの内容は見てのとおりですがサンプルと違うのは
- スレッド起動した関数と、メイン関数の間でd変数を用意
- スレッド内でd変数を変更
- main関数でチェック
- 5以上ならループを終了
です。pingが延々と帰ってこない場合も制御できているかを確認したかったので追加しました。
ログ
どのように動作しているか、細かく見るためにログを追加し、出力してみました。実際に動かしてみないとわからない人でして。。
以下は、ping 192.168.132.128(実在するIPアドレス)に出力した場合です。
pingコマンドの出力を取り出せているのが分かります。
2021-06-03 00:12:09,129 MainThread __main__ 28 main start
2021-06-03 00:12:09,129 MainThread sarge.parse 854 starting parse of 'ping 192.168.132.128'
2021-06-03 00:12:09,129 MainThread sarge.parse 996 returning CommandNode(command=['ping'] redirects={})
2021-06-03 00:12:09,129 MainThread sarge.parse 996 returning CommandNode(command=['192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 MainThread sarge.parse 939 returning CommandNode(command=['ping', '192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 MainThread sarge.parse 922 returning CommandNode(command=['ping', '192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 MainThread sarge.parse 893 returning CommandNode(command=['ping', '192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 MainThread sarge.parse 877 returning CommandNode(command=['ping', '192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 MainThread sarge 1067 thread Thread-1 started to run node: CommandNode(command=['ping', '192.168.132.128'] redirects={})
2021-06-03 00:12:09,130 Thread-1 sarge 1335 started: CommandNode(command=['ping', '192.168.132.128'] redirects={}), None, True
2021-06-03 00:12:09,130 Thread-1 sarge 629 Command('ping 192.168.132.128') created
2021-06-03 00:12:09,130 Thread-1 sarge 665 About to call Popen: ['ping', '192.168.132.128'], {'stdout': -1, 'stderr': None, 'stdin': None}
2021-06-03 00:12:09,149 Thread-1 sarge 674 Popen: Command('ping 192.168.132.128'), {'stdout': -1, 'stderr': None, 'stdin': None} -> {'_waitpid_lock': <unlocked _thread.lock object at 0x7f05a8eea120>, '_input': None, '_communication_started': False, 'args': ['ping', '192.168.132.128'], 'stdin': None, 'stdout': <_io.BufferedReader name=4>, 'stderr': None, 'pid': 5290, 'returncode': None, 'encoding': None, 'errors': None, 'text_mode': None, '_sigint_wait_secs': 0.25, '_closed_child_pipe_fds': True, '_child_created': True}
2021-06-03 00:12:09,150 Thread-1 sarge 215 Created thread Thread-2 as reader for Capture-1
2021-06-03 00:12:09,151 Thread-2 sarge 237 Capture-1: reader thread about to read line
2021-06-03 00:12:09,151 Thread-1 sarge 219 Capture-1: reader thread kicked off, waiting start
2021-06-03 00:12:09,151 Thread-1 sarge 221 Capture-1: reader thread now started
2021-06-03 00:12:09,151 Thread-1 sarge 697 returning Command('ping 192.168.132.128') (Popen(returncode=None stdin=None stdout=<_io.BufferedReader name=4> stderr=None))
2021-06-03 00:12:09,170 Thread-2 sarge 246 queued chunk of length 68 to <queue.Queue object at 0x7f05a97caf70>: b'PING 192.168.132.128 (192.168.'
2021-06-03 00:12:09,170 Thread-2 sarge 246 queued chunk of length 86 to <queue.Queue object at 0x7f05a97caf70>: b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 1'
2021-06-03 00:12:09,182 Thread-3 __main__ 20 cmd output b'PING 192.168.132.128 (192.168.132.128) 56(84) \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe3\x81\xae\xe3\x83\x87\xe3\x83\xbc\xe3\x82\xbf\n'
2021-06-03 00:12:09,182 Thread-3 __main__ 20 cmd output b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 192.168.132.128: icmp_seq=1 ttl=64 \xe6\x99\x82\xe9\x96\x93=0.023\xe3\x83\x9f\xe3\x83\xaa\xe7\xa7\x92\n'
2021-06-03 00:12:10,159 Thread-2 sarge 246 queued chunk of length 86 to <queue.Queue object at 0x7f05a97caf70>: b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 1'
2021-06-03 00:12:10,159 Thread-3 __main__ 20 cmd output b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 192.168.132.128: icmp_seq=2 ttl=64 \xe6\x99\x82\xe9\x96\x93=0.030\xe3\x83\x9f\xe3\x83\xaa\xe7\xa7\x92\n'
2021-06-03 00:12:11,183 Thread-2 sarge 246 queued chunk of length 86 to <queue.Queue object at 0x7f05a97caf70>: b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 1'
2021-06-03 00:12:11,184 Thread-3 __main__ 20 cmd output b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 192.168.132.128: icmp_seq=3 ttl=64 \xe6\x99\x82\xe9\x96\x93=0.061\xe3\x83\x9f\xe3\x83\xaa\xe7\xa7\x92\n'
2021-06-03 00:12:12,208 Thread-2 sarge 246 queued chunk of length 86 to <queue.Queue object at 0x7f05a97caf70>: b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 1'
2021-06-03 00:12:12,208 Thread-3 __main__ 20 cmd output b'64 \xe3\x83\x90\xe3\x82\xa4\xe3\x83\x88\xe5\xbf\x9c\xe7\xad\x94 \xe9\x80\x81\xe4\xbf\xa1\xe5\x85\x83 192.168.132.128: icmp_seq=4 ttl=64 \xe6\x99\x82\xe9\x96\x93=0.025\xe3\x83\x9f\xe3\x83\xaa\xe7\xa7\x92\n'
2021-06-03 00:12:12,208 Thread-3 __main__ 24 progress exited at 5
2021-06-03 00:12:12,222 MainThread __main__ 46 main exited
ping失敗時ログ
ping 10.0.0.1(存在しないIPアドレス)のコマンドは以下のようになります。
“No more data, breaking out”が出た後、main関数を抜けているのが分かります。
2021-06-03 00:20:04,075 MainThread __main__ 30 main start
2021-06-03 00:20:04,075 MainThread sarge.parse 854 starting parse of 'ping 10.0.0.1'
2021-06-03 00:20:04,075 MainThread sarge.parse 996 returning CommandNode(command=['ping'] redirects={})
2021-06-03 00:20:04,075 MainThread sarge.parse 996 returning CommandNode(command=['10.0.0.1'] redirects={})
2021-06-03 00:20:04,076 MainThread sarge.parse 939 returning CommandNode(command=['ping', '10.0.0.1'] redirects={})
2021-06-03 00:20:04,076 MainThread sarge.parse 922 returning CommandNode(command=['ping', '10.0.0.1'] redirects={})
2021-06-03 00:20:04,076 MainThread sarge.parse 893 returning CommandNode(command=['ping', '10.0.0.1'] redirects={})
2021-06-03 00:20:04,076 MainThread sarge.parse 877 returning CommandNode(command=['ping', '10.0.0.1'] redirects={})
2021-06-03 00:20:04,076 MainThread sarge 1067 thread Thread-1 started to run node: CommandNode(command=['ping', '10.0.0.1'] redirects={})
2021-06-03 00:20:04,077 Thread-1 sarge 1335 started: CommandNode(command=['ping', '10.0.0.1'] redirects={}), None, True
2021-06-03 00:20:04,077 Thread-1 sarge 629 Command('ping 10.0.0.1') created
2021-06-03 00:20:04,077 Thread-1 sarge 665 About to call Popen: ['ping', '10.0.0.1'], {'stdout': -1, 'stderr': None, 'stdin': None}
2021-06-03 00:20:04,082 Thread-1 sarge 674 Popen: Command('ping 10.0.0.1'), {'stdout': -1, 'stderr': None, 'stdin': None} -> {'_waitpid_lock': <unlocked _thread.lock object at 0x7f35c2e122a0>, '_input': None, '_communication_started': False, 'args': ['ping', '10.0.0.1'], 'stdin': None, 'stdout': <_io.BufferedReader name=4>, 'stderr': None, 'pid': 5408, 'returncode': None, 'encoding': None, 'errors': None, 'text_mode': None, '_sigint_wait_secs': 0.25, '_closed_child_pipe_fds': True, '_child_created': True}
2021-06-03 00:20:04,082 Thread-1 sarge 215 Created thread Thread-2 as reader for Capture-1
2021-06-03 00:20:04,086 Thread-2 sarge 237 Capture-1: reader thread about to read line
2021-06-03 00:20:04,086 Thread-1 sarge 219 Capture-1: reader thread kicked off, waiting start
2021-06-03 00:20:04,086 Thread-1 sarge 221 Capture-1: reader thread now started
2021-06-03 00:20:04,086 Thread-1 sarge 697 returning Command('ping 10.0.0.1') (Popen(returncode=None stdin=None stdout=<_io.BufferedReader name=4> stderr=None))
2021-06-03 00:20:24,103 Thread-3 __main__ 18 No more data, breaking out
2021-06-03 00:20:24,141 MainThread __main__ 48 main exited
終わりに
ログを出してみて、どんな感じで動作しているかを確認することができました。ある程度は理解できたと思います。
参考
- https://sarge.readthedocs.io/en/latest/tutorial.html
サンプルプログラムの参考にした
