メール受信をトリガーにプログラムを動かしたい

Question

メール受信をトリガーにプログラムを実行したいと考えております。

###設定前の状態
CentOS 6.8
postfix + dovecotでメールサーバーを構築。
この時点で送受信を問題無く行なえます。

###行った事
受信時に実行されるプログラム

# -*- encoding: utf-8 -*-
#-------------------------------------------------
# Ruby script to get a mail via alias of postfix.
#-------------------------------------------------
require 'mail'

class GetMail
  def initialize
    dt = Time.now.strftime("%Y%m%d_%H%M%S%L")
    @out_file = "/home/info/Document/txt.txt"
  end

  def execute
    open(@out_file, "w+") do |f|
      mail = Mail.new($stdin.read)
      f.puts "From:    #{mail.from.first}"
      f.puts "To:      #{mail.to.first}"
      f.puts "Date:    #{mail.date}"
      f.puts "Subject: #{mail.subject}"
      f.puts "Body:\n#{mail.body.decoded.encode("UTF-8", mail.charset)}"
    end
  rescue => e
    $stderr.puts "[#{e.class}] #{e.message}"
    e.backtrace.each{|trace| $stderr.puts "\t#{trace}"}
    exit 1
  end
end

exit unless $0 == __FILE__
GetMail.new.execute

postfixの設定

# info: :include:/tmp/TEST
info: "| ruby /home/info/mail_trigger.rb"

上記を内容を「/etc/aliases」に追記した所、外部からのメールが受信できなくなりました。
外部からメールを送信すると「Undelivered Mail Returned to Sende」で帰ってきますが、クライアントではソフトではエラーは出ていません。

main.cfの設定

allow_mail_to_commands = alias,forward,include

postfixの設定とaliasesの設定では変更のたびにnewaliasesとrestartを行っています。

受信時のメールログ

Jan 24 19:02:50 v9193 postfix/smtpd[4313]: connect from mail-pf0-f173.google.com[209.85.192.173]
Jan 24 19:02:50 v9193 postfix/smtpd[4313]: setting up TLS connection from mail-pf0-f173.google.com[209.85.192.173]
Jan 24 19:02:50 v9193 postfix/smtpd[4313]: Anonymous TLS connection established from mail-pf0-f173.google.com[209.85.192.173]: TLSv1.2 with cipher AES128-GCM-SHA256 (128/128 bits)
Jan 24 19:02:51 v9193 postfix/smtpd[4313]: A12D2FC0BEC: client=mail-pf0-f173.google.com[209.85.192.173]
Jan 24 19:02:51 v9193 postfix/cleanup[4318]: A12D2FC0BEC: message-id=<[e-mail]>
Jan 24 19:02:51 v9193 postfix/qmgr[3638]: A12D2FC0BEC: from=<[e-mail]>, size=2736, nrcpt=1 (queue active)
Jan 24 19:02:51 v9193 postfix/local[4319]: A12D2FC0BEC: to=<[e-mail]>, relay=local, delay=0.77, delays=0.76/0.01/0/0.01, dsn=5.3.0, status=bounced (Command died with status 127: " ruby /home/info/mail_trigger.rb". Command output: sh: ruby: command not found )
Jan 24 19:02:51 v9193 postfix/cleanup[4318]: D5598FC0BFD: message-id=<[e-mail]>
Jan 24 19:02:51 v9193 postfix/bounce[4321]: A12D2FC0BEC: sender non-delivery notification: D5598FC0BFD
Jan 24 19:02:51 v9193 postfix/qmgr[3638]: D5598FC0BFD: from=<>, size=4721, nrcpt=1 (queue active)
Jan 24 19:02:51 v9193 postfix/qmgr[3638]: A12D2FC0BEC: removed
Jan 24 19:02:51 v9193 postfix/smtpd[4313]: disconnect from mail-pf0-f173.google.com[209.85.192.173]
Jan 24 19:02:52 v9193 postfix/smtp[4322]: certificate verification failed for gmail-smtp-in.l.google.com[74.125.204.26]:25: untrusted issuer /C=US/O=Equifax/OU=Equifax Secure Certificate Authority
Jan 24 19:02:53 v9193 postfix/smtp[4322]: D5598FC0BFD: to=<[e-mail]>, relay=gmail-smtp-in.l.google.com[74.125.204.26]:25, delay=1.7, delays=0/0.01/0.99/0.7, dsn=2.0.0, status=sent (250 2.0.0 OK 1485252173 s5si18562651plj.103 - gsmtp)
Jan 24 19:02:53 v9193 postfix/qmgr[3638]: D5598FC0BFD: removed

備考
受信時に実行されるプログラムは実行権限をメールユーザーに与えています。
メールユーザーにログインしてプログラムを実行しても、権限関係のエラーなどは出ません。

##質問
このような状況でどこに問題があるのかわかりません。
メールログにはコマンド見つからないとなっていますが、該当ユーザーにスイッチしてプログラムを動かすと問題なく動きます。

どの辺りを見ればいいか教えて頂けないでしょうか？

Answer 1

「Undelivered Mail Returned to Sende」は何かが原因でメールの配送に失敗し、メールが返ってきたことを意味します。原因はたいていPostfixのログに記載されています。そこでログを見るのですが、注目すべきは下記の行です。

Jan 24 19:02:51 v9193 postfix/local[4319]: A12D2FC0BEC: to=<[e-mail]>, relay=local, delay=0.77, delays=0.76/0.01/0/0.01, dsn=5.3.0, status=bounced (Command died with status 127: " ruby /home/info/mail_trigger.rb". Command output: sh: ruby: command not found )

このように、送られてきたメールについて、最終的にどのような処理を行ったのかがログには記録されており、statusの部分がその処理結果ですstatus=bouncedというのは何かしらが原因でメールの配送自体が失敗したことを意味し、続く()の中にその理由が書いています。

Command died with status 127: " ruby /home/info/mail_trigger.rb". Command output: sh: ruby: command not found

これは、パイプで実行されるコマンドが、"command not found"(コマンドが見つからない)が原因でエラーになったという意味です。つまり、"ruby"のコマンドが見つからないからエラーとなっています。コマンドについて"ruby"というコマンド名だけでは書かずに、フルパス"/usr/local/bin/ruby"(実際の場所に合わせてください)等に書き直してください。そうすれば、コマンドが見つかり、実行されるはずです。それでもエラーになる場合は、別のエラーメッセージが表示されるはずですので、それを確認してみてください。

【なぜ、フルパスが必要なのか？】
aliasesの中やcronの中でコマンドを指定するとき、ログインしたときのようなシェルの初期設定(~/.bashrc等に書かれている内容のこと)が行われません。特にPATHに関しては最低限の"/bin"と"/usr/bin"のみ設定されている場合があります(OSなどによってなにが設定されているかは異なります)。"ruby"が"/usr/local/bin/ruby"としてインストールされている場合、PATHには含まれていないため、"ruby"だけでは見つからず、エラーになります。このように、"/bin"と"/usr/bin"以外のコマンドを実行する場合は、"/usr/local/bin/ruby"等のフルパスでコマンドを指定する必要があります。

Comments

[yuki_90453]

なるほど、丁寧な回答ありがとうございます。
さっそく gem environmentでパスを確認し下記のように記述致しました。
info: "| /usr/local/rbenv/versions/2.3.1/bin/ruby /home/info/mail_trigger.rb"

newaliasesとchmodで 770で与え実行。メール送信してみると下記の内容がログに残り、プログラムは動いていませんでした。

Jan 24 21:40:51 v9193 postfix/local[4796]: 38BAAFC0BF8: to=<[e-mail]>, relay=local, delay=0.68, delays=0.66/0.01/0/0.01, dsn=4.3.0, status=deferred (temporary failure. Command output: local: fatal: execvp /usr/local/rbenv/versions/2.3.1/bin/ruby: Permission denied )

権限問題だと思うのですが、下記のような権限を付与していますがこれでは駄目なんでしょうか？
-rwxrwx--- 1 root root 22280960 1月 5 15:02 2017 /usr/local/rbenv/versions/2.3.1/bin/ruby

[raccy]

コマンドを実行するユーザーの権限はmain.cfのdefault_privsで設定できるのですが、デフォルトがnobodyだったはずです。デフォルトであれば、nobodyで実行できる権限でないと動きません。下記も参考にしてください。
http://www.postfix-jp.info/trans-2.3/jhtml/postconf.5.html#default_privs
http://www.postfix-jp.info/trans-2.3/jhtml/local.8.html

[yuki_90453]

頂いたURLの内容が難しく検索しながら設定したので合っているかわかりませんが、「default_privs = info」に変更してみました。
しかしメールログには相変わらずpermision denidと記述されてしまいます。

このinfoというユーザーは、特権ユーザーやpostfixの所有権を持っていないと思います。
またこのユーザーは、nologinで作成したユーザーなのですがそれが権限がないなどの可能性はありますでしょうか？

[yuki_90453]

お世話になっております。rubyの権限を777に変更するとプログラムが動きました。しかしメールその物はユーザーのメールボックスに保存されないのですが、これは仕様なんでしょうか？

[raccy]

権限は755などでもできると思います。ここら辺はLinuxのファイルパーミッションについて一度学ぶことをお勧めします。

aliasは代替、つまり、代わりにするという意味です。本来のメールボックスへ送るという操作の「代わりに」コマンドを実行するというのがその設定になります。メールボックスにも送って、かつ、コマンドも実行するとなると、書き方を変える必要があります。

もし、メールボックスにも送って、かつ、コマンドも実行する書き方について、調べてもわからなかったときは、別枠で質問してみてください。

Answer 2

さしあたり、Rubyスクリプトの1行目は

! /usr/local/bin/ruby

ではなく

#! /usr/local/bin/ruby

かと思いますが（転記ミスかな?）

---

失礼しました。やはり転記ミスでしたね。
スクリプトを動かしてみましたが、起動はされました。
ただ、txt.txtを書き込む際にPermission deniedのエラーになっていたので、/tmp/txt.txtに書き込むようにしたところ、ファイルは書き込まれましたが、ファイルオーナーは nobodyになっていました（Ubuntu15.10にて実行）。
ご参考までに。

Comments

[yuki_90453]

転記ミスですね。削除しました。