こんにちは。Fluentdのメンテナーの福田です。

Fluentdを使うと、いい感じに様々なアプリケーションのログを集中管理できて便利です。 例えば、メール転送エージェント（MTA）であるPostfixのログをFluentdに送信して管理することができます。

クリアコードはFluentdの法人様向けサポートサービスを行っていますが、 Fluentdに送信したPostfixの特定のログが途中で途切れてしまっている、 という問題がとあるお客様で発生し、調査して原因を明らかにしました。 結論としては、Postfixの仕様の問題でした。

この記事では、このサポート事例について紹介します。 Fluentdの使用例、トラブルシューティングの仕方に興味がある方はぜひご覧ください。 また、クリアコードのFluentdサポートサービスに興味のある方もぜひご覧ください。

PostfixのログをFluentdに送信する

今回紹介するサポート事例は、PostfixのログをFluentdに送信する際の問題に関してです。

Postfixは、メール転送エージェント(MTA）として有名なフリーソフトウェアであり、デフォルトで自身の動作ログをSyslogとして出力します。 今回の事例では、この動作ログをFluentdに送信するケースを考えます。

Fluentd側では、次のようなInputプラグインを設定してSyslogを受信します。

• in_syslog
  • Syslog受信用のプラグイン
  • 特に理由がなければこれ
• in_udp
  • 一般的なUDP受信用のプラグイン
• in_tcp
  • 一般的なTCP受信用のプラグイン

Postfix側では、mailファシリティのSyslogをFluentdのInputプラグインに送信するようにSyslogの設定をします。

このように、PostfixのログをSyslogとしてFluentdに送信するケースにおいて、とある問題が発生しました。

Postfixの特定のログが途切れてしまう

その問題とは、とあるPostfixのログが途中で途切れてしまうことでした。 具体的には、次のようなログの{詳細情報}の部分が途中で途切れてしまっていました。

improper command pipelining after EHLO from {アドレス}: {詳細情報}

今回のサポート事例では、お客様からこのような問題のご相談を受けて、その原因を調査しました。

結論から言えば、原因はPostfixの仕様でした。 少なくともPostfix 3.5.8では、このログの{詳細情報}の部分の長さを100文字に制限していました。

以下では、その調査の過程を紹介します。

Fluentd側の調査

当初はFluentd側の問題である可能性を考えて調査をしました。 その結果、Fluentd側の問題ではない可能性が高いことが分かりました。

調べたのは次の3点です。

• A: Inputプラグインにおいて、ログの長さに制限をかけていないか？
• B: Inputプラグインにおいて、受信したデータのパースに失敗していないか？
• C: Inputプラグイン以外のプラグインが、データを加工してしまっていないか？

Aについては、例えばin_tcpプラグインにはmessage_length_limitという設定があり、 サイズが大きすぎるログを処理せずにスキップすることができます。 しかし、問題が発生していた環境では、そういった設定は一切されていませんでした。 また、他に受信できているログを確認したところ、より長いログを途切れずに受信できていたため、 Fluentd側で何らかの長さ制限が働いた可能性は低いと考えました。

Bについては、以下の理由で可能性が低いと考えました。

• Fluentdの動作ログを確認すると、パースに失敗したことを示すような異常なログが一切出ていなかった
• 受信データの切りどころを間違えたとするならば発生するはずの以下の現象が発生していなかった
  • 途切れた後続の部分が、次のログとして出力される
  • 途切れた後続の部分が、想定外のフォーマットのデータとしてパースエラーを招く

Cについては、全体のFluentd設定を確認したところ、 受信データを加工する可能性のある設定が他に存在しなかったため、可能性が低いと考えました。

以上から、Fluentd側の問題である可能性は低いと考えました。

Postfix側の調査

Fluentdを調査したところ、Fluentd側の問題ではない可能性が高いと分かったため、 原因を切り分けるためPostfix側の調査をしました。

この事例の契約上、Postfixの問題調査は契約範囲外だったのですが、 原因の切り分けの一貫として調査を行いました。 (Postfixもフリーソフトウェアであり、直接ソースコードを調査できるため、クリアコードの得意分野です)。

Postfixのソースコードで、improper command pipeliningというログを出力している箇所を探すと、 少なくともPostfix 3.5.8では、このログの{詳細情報}の部分を最大100文字に制限していることが分かりました。

improper command pipelining after EHLO from {アドレス}: {詳細情報}

該当部分のソースコードは次の通りです。

Postfix 3.5.8 /src/smtpd/smtpd.c:

5396 if (state->expand_buf == 0)
5397     state->expand_buf = vstring_alloc(100);
5398 escape(state->expand_buf, vstream_peek_data(state->client),
5399        vstream_peek(state->client) < 100 ?
5400        vstream_peek(state->client) : 100);
5401 msg_info("improper command pipelining after %s from %s: %s",
5402          cmdp->name, state->namaddr, STR(state->expand_buf));

これによって、この問題はPostfixの仕様であったことが明らかとなりました。

まとめ

本記事では、Fluentdサポート事例として、Fluentd以外の部分に原因があった事例について紹介しました。

Fluentdはその性質上、他の様々なアプリケーションとセットでシステムを構成する形となります。 そのため、何か想定外の現象が起こったときに、その原因を調べることは必ずしも簡単ではありません。

クリアコードはこのような問題解決が得意です！ クリアコードはフリーソフトウェアとビジネスの両立を理念としており、フリーソフトウェア全般を得意としています。 今回の事例ではFluentdにログを送信するPostfixが問題となったわけですが、 このように関連するソフトウェアがフリーソフトウェアであれば、クリアコードの腕の見せ所というわけです！

現時点でのFluentdサポートの記載では明記されていませんが、 Fluentdとその周辺のフリーソフトウェア（K8s, nginx, Embulkなど）をセットでサポートする事例やご相談もあります。

もしFluentdとその周辺のアプリケーションの運用でお困りのことがありましたら、 ぜひお問い合わせフォームからお気軽にご相談ください。

ツイートする

フォローする