スクリプトのお勉強

Pythonでコマンド非同期起動

投稿日:

はじめに

小ネタです。

作成するプログラムの要件で、コマンドを起動して、そのコマンドが「継続」している/していないことを確認する、という要件があります。

具体的には、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
    サンプルプログラムの参考にした

-スクリプトのお勉強

執筆者:

関連記事

Python3 – django-webtest

忙しいので断片だけ。。 DjangoでWebブラウザからアクセスする感じでテストする、やり方の一つです。以前にやったように、 Seleniumからやってもいいのすが、そこまでじゃない場合の単体テスト方 …

Webフレームワーク「Django 3.2」を使ってみる

LTSリリースなので、現状でアップデートしてないDjangoプロジェクトをDjango 3.2にしていこうかと思いました。例として、自分のDjango 2.0のプロジェクトをDjango 3.2にしま …

Python Django REST Framework(REST API)の作成

1.はじめに 今回は、pythonの「Django」というWebアプリケーションフレームワークを使用し、REST APIを作成します。作成するREST APIは、これから作るであろう、Nuxt.jsか …

Nuxt.js – CRUDアプリケーションのフォーム/一覧を作成する

前回で作ったAPIのフロントエンドアプリケーションを作ろうと思います。 どういうアプリ? サンプルとして作ったAPIが住所録的だったので、住所録を作りました。 以下の機能があります。 登録(確認付き) …

VMware player(workstation) から WSL2に乗り換える

いままで、VMware player(今のVMWare Workstation Player)上で、作って確認していたけど、いちいち起動するのがだるいです。 ついでにやたらとリソースを使用するので、こ …