メール通知が届かない

[irgaly]

メール通知機能ですが、最近利用できなくなりました。

利用できていた以前の状況：

• Knowledge 5.0 ~ Knowledge 5.1
• H2 Database (初期データベース)
• GmailのSMTP認証ありで送信

利用できなくなった現状：

• Knowledge 5.2
• PostgreSQLへ以降済
• メール設定変わらず

ログを確認しましたがメールを送信しようとしているそれらしいログはないようです。
調査方法などありましたら教えていただけないでしょうか。

[koda-masaru]

ご迷惑をかけ申し訳ありません。
なぜ送れないのか、直ぐに答えられれば良いのですが、今のところ原因がわかりません。
これから少し調べてみようと思います。
私の環境（PostgreSQLへ以降済）ではメールは送信出来ているのですが、、、

調査方法は、やはりログを出すのが良いと思うのですが、メール送信時のログは出力していませんでした。この辺も少しやり方を検討しようと思います。

[koda-masaru]

Postgres環境でメールが送れない原因がわからないので、
メール送信のログを出力するように修正してみました。
あとでリリースしますので、試してもらえますでしょうか？
（検索機能の強化も少し入っています）

[irgaly]

早速ご対応いただきありがとうございます！
メール機能は環境への依存が大きいと思いますので、地道に調査してみたいと思います。

（原因の切り分けがまだできていなかったのでissue名を変更させていただきました。）

[koda-masaru]

メール送信の際のログをファイルに出力するようにしてみました。
これで原因の切り分けができると良いのですが、、、

お試し願います。

[irgaly]

0.5.3 Pre1で確認しました。
ログは出力されているようですが、記事を作成してみても10秒間隔で「[MailSendBat(97)] MAIL sended. count: 0」と表示されており、そもそもメール送信しようとしていないようです...

現状ですが、「メール送信設定」で以下のように設定しております。

SMTPホスト名：smtp.gmail.com
SMTPポート番号：587
認証：認証する
SMTP認証ID/SMTPパスワード/送信元アドレス/送信者名を設定

試したこと

1. 既存アカウントの「通知設定」を確認する
   -> メール通知：通知する、全項目：通知するとなっている
2. 記事を作成する
3. 「MAIL sended. count: 0」...

---

1. 既存アカウントの「通知設定」を通知しない設定で保存する
2. 既存アカウントの「通知設定」を通知する設定に戻して保存する
3. 記事を作成する
4. 「MAIL sended. count: 0」...

---

1. 新規にアカウントを作成し「通知設定」を通知するように設定する
2. 記事を作成する
3. 「MAIL sended. count: 0」...

---

1. 「メール送信設定」を削除する
2. 「メール送信設定」を再度設定し保存する
3. 記事を作成する
4. 「MAIL sended. count: 0」...

---

1. PostgreSQL -> H2DBへ逆マイグレーションする
2. H2DBを参照するように設定する
3. 記事を作成する
4. 「Mail sended. count: 0」 ...

---

現在の環境ですが、CentOS 7.1, Tomcat 8.0.21で、0.5.0(H2 DB) -> 0.5.1(H2 DB) -> 0.5.1(Postgres) -> 0.5.2(Postgres) -> 0.5.3 Pre1(Postgres)とマイグレーションしてきており、0.5.1(H2 DB)のころまでメール送信されていました。

[koda-masaru]

ご確認ありがとうございます。

「Mail sended. count: 0」とログに出ているので、メール送信のバッチじたいは定期的に起動しているようです。
ただ、count:0 と表示されているので、文字通り「送信先の対象がいない」という事になります。
エラーなどが出力されていないので、DBが問題では無く、メールの送信先の抽出がうまくいっていないのかもしれません。

上記の操作の中で、通知設定の状態がおかしくなり、記事を作成した際の通知先の抽出で対象にならないのかもです。

そのあたりの情報を元に、もう少し原因調査してみます。
何かわかれば、またご連絡しますね。

[irgaly]

ありがとうございます。

エラーなどが出力されていないので、DBが問題では無く、メールの送信先の抽出がうまくいっていないのかもしれません。

こちらの処理を追ってみたいのですが、調査する方法はあるでしょうか。
たとえばDBの中身を直接確認してみようかと思うのですが、どこを確認したら良いなどはあるでしょうか？

[koda-masaru]

ログの出力ディレクトリに「NotifyMailBat.log」というファイルが出力されているでしょうか？

このログを出力している処理が、ナレッジが登録・更新された後、通知先を検索して送信メール情報を作成している処理になります。
この処理で、送信先の抽出に該当していないのかも？と思ったのですが、いかがでしょうか？

[irgaly]

確認しました。NotifyMailBat.logは存在していますが0バイトでした。(@0.5.3pre1)

[koda-masaru]

確認ありがとうございます。

NotifyMailBat.logが0バイトということは、やはり、ナレッジを登録／更新したイベントを通知する対象の抽出処理がうまくいっていないと思います。

ちなみにDBを直接見ることはできますでしょうか？

処理としては、以下の流れで実行しているので、データを見て、どこまでがうまくいっているのかを知りたいと思っています。

---

★ナレッジ更新情報のメール通知の処理手順

１．ナレッジを登録／更新
　　→更新されたので、通知のキューテーブルにデータを登録（notify_queuesテーブル）
　　→ナレッジのIDをキューに登録
　　→delete_flagはNULL

２．通知のキューに登録された「ナレッジの更新の通知」を、通知先を検索してメール送信テーブルに登録（mailsテーブル）
　　→ナレッジが公開される範囲のユーザに対して通知メール情報を作成
　　→通知先が多くある場合があり、ユーザ毎に通知する／しないの設定などもあり、処理に時間がかかるかもしれないので、バッチで非同期に処理しています（NotifyMailBat）
　　→mailsテーブルに送信するメールを登録したら、notify_queuesテーブルから削除（delete_flag=1)

３．メール通知テーブルに登録された内容に従い、メールを送信
　　→メール送信処理も時間がかかる事があるのでバッチで非同期に実行（MailSendBat）
　　→メールが送信できた場合、mailsテーブルから削除（delete_flag=1）

---

上記の処理の中の「２」の処理がうまくいっていないと思うので、notify_queuesテーブル、mailsテーブルの情報が変化したかどうかがわかると嬉しいです。

テーブルの情報を見ることが難しいのであれば、次回のリリースで、NotifyMailBatのログ出力の内容を増やして、原因が特定できるようにしておこうと思います。

[irgaly]

以下の手順で確認してみました。

データベース確認コマンド

% psql -U tomcat -d knowledge > out2.txt <<EOF
\d notify_queues;
select * from notify_queues;
\d mails;
select * from mails;
EOF

データベースの内容取得

上記コマンドで現状のデータを抽出

結果

             テーブル "public.notify_queues"
       列        |             型              |  修飾語  
-----------------+-----------------------------+----------
 hash            | character varying(32)       | not null
 type            | integer                     | not null
 id              | bigint                      | not null
 insert_user     | integer                     | 
 insert_datetime | timestamp without time zone | 
 update_user     | integer                     | 
 update_datetime | timestamp without time zone | 
 delete_flag     | integer                     | 
インデックス:
    "notify_queues_pkc" PRIMARY KEY, btree (hash)

              hash              | type | id  | insert_user |     insert_datetime     | update_user |     update_datetime     | delete_flag 
--------------------------------+------+-----+-------------+-------------------------+-------------+-------------------------+-------------
 zCsAsk77UtX5V4nre9fXOOqV0MH4bG |    1 |   1 |           2 | 2015-04-23 05:26:23.839 |           0 | 2015-04-23 14:26:27.04  |           1
 GU4KsLKXGe3aInQWZUIsb1pGfiSPv4 |   21 |   1 |           0 | 2015-04-23 05:42:02.456 |           0 | 2015-04-23 14:42:05.065 |           1
...(省略)
 HnmXgZUdUKoT7jU6BWazNMoFI78SXA |    2 | 135 |           5 | 2015-07-14 07:11:57.605 |           5 | 2015-07-14 07:11:57.605 |           0
 YTwbPCNPOCERoUhd2mPKAdu6AG8z2A |    1 | 136 |           6 | 2015-07-15 03:20:01.064 |           6 | 2015-07-15 03:20:01.064 |           0
(455 行)
                 テーブル "public.mails"
       列        |             型              |  修飾語  
-----------------+-----------------------------+----------
 mail_id         | character varying(64)       | not null
 status          | integer                     | not null
 to_address      | character varying(256)      | not null
 to_name         | character varying(256)      | 
 from_address    | character varying(256)      | 
 from_name       | character varying(256)      | 
 title           | character varying(256)      | not null
 content         | text                        | 
 row_id          | character varying(64)       | 
 insert_user     | integer                     | 
 insert_datetime | timestamp without time zone | 
 update_user     | integer                     | 
 update_datetime | timestamp without time zone | 
 delete_flag     | integer                     | 
インデックス:
    "mails_pkc" PRIMARY KEY, btree (mail_id)
    "idx_mails_status" btree (status)

 mail_id | status | to_address | to_name | from_address | from_name |  title | content | row_id | insert_user | insert_datetime | update_user | update_datetime | delete_flag
...（データが大きいので省略）
...（2015-04-23 18:10:17.01...2015-07-09 01:53:56.838のタイムスタンプのデータがあるようでした）
(372 行)

記事を作成する

記事ID 137で記事を作成しました。

データベースの内容取得

コマンドを実行してデータベースの内容を取得する

結果

前回の結果からdiff -u したものを載せます。notify_queuesテーブルに1件追加、mailsテーブルに変化なしでした。

--- out.txt 2015-07-15 14:19:45.000000000 +0900
+++ out2.txt    2015-07-15 14:19:50.000000000 +0900
@@ -469,7 +469,8 @@
  eiEjNuJGxsyLHCbvIkqXp3Crv1pYoI |    1 | 135 |           5 | 2015-07-14 07:10:03.69  |           5 | 2015-07-14 07:10:03.69  |           0
  HnmXgZUdUKoT7jU6BWazNMoFI78SXA |    2 | 135 |           5 | 2015-07-14 07:11:57.605 |           5 | 2015-07-14 07:11:57.605 |           0
  YTwbPCNPOCERoUhd2mPKAdu6AG8z2A |    1 | 136 |           6 | 2015-07-15 03:20:01.064 |           6 | 2015-07-15 03:20:01.064 |           0
-(455 行)
+ bKtHoN2EuSZ8isSTs233yE3eR6wtEG |    1 | 137 |           2 | 2015-07-15 05:15:13.763 |           2 | 2015-07-15 05:15:13.763 |           0
+(456 行)

                  テーブル "public.mails"
        列        |             型              |  修飾語  

ログ出力を確認する

• NotifyMailBat.logのログ
  • 0バイトから変化なし
• MailSendLog.txtのログ

...
INFO  2015-07-15 14:16:32,485 [MailSendBat(97)] MAIL sended. count: 0
INFO  2015-07-15 14:16:43,485 [MailSendBat(97)] MAIL sended. count: 0
INFO  2015-07-15 14:16:52,367 [MailSendBat(97)] MAIL sended. count: 0

[koda-masaru]

確認ありがとうございます！

NotifyMailBatがDBの「notify_queues」テーブルの情報をとれていないために、メール通知ができないようです。
どうして「notify_queues」テーブルの情報が取れないのかの原因を調べてみると、たぶん原因を見つけました。

その原因は、Knowledgeのデータディレクトリ(.knowlede)を変更出来るようにしたのですが、（#32）その環境変数が、バッチ処理にわたっていない？かもです。

また確認になってしまうのですが、環境変数「KNOWLEDGE_HOME」でデータディレクトリを変更していますでしょうか？

[irgaly]

KNOWLEDGE_HOMEは設定しておらず、tomcatのホームディレクトリに.knowledgeが作成されています。

[koda-masaru]

原因の解析のために、NotifyMailBatのバッチ処理が出力するログを増やしてみました。
お手数ですが、Release 0.5.3 Pre2 を試していただき、NotifyMailBat.logのログの内容を教えていただけないでしょうか。

NotifyMailBatの起動処理の部分を少し修正したので、もしかするとメールが送信されるようになおったかもしれません。それを含めてご確認いただけるとありがたいです。

[irgaly]

ありがとうございます。0.5.3 Pre2でNotifyMailBatのログを確認しました。
ちなみに、記事を作成してみましたがメールは送信されていないようです。
10秒おきにログが出力され、Custom connection setting is exists.で止まっているようです。

...
INFO  2015-07-22 12:02:41,761 [AbstractBat(26)] NotifyMailBat is start.
INFO  2015-07-22 12:02:41,765 [AbstractBat(27)] Env [KNOWLEDGE_HOME] is [null].
INFO  2015-07-22 12:02:42,158 [AbstractBat(28)] Config :{"basePath":"/srv/tomcat/.knowledge","databasePath":"/srv/tomcat/.knowledge/db/","hashIterations":100,"indexPath":"/srv/tomcat/.knowledge/index/","languages":[{"label":"Japanese","value":"ja"},{"label":"English","value":"en"}],"systemName":"knowledge","time_zone":"Asia/Tokyo","tmpPath":"/srv/tomcat/.knowledge/tmp/","uploadMaxMBSize":500,"webRealPath":""}
INFO  2015-07-22 12:02:42,307 [DBConnenctionLogic(35)] Custom connection setting is exists.
INFO  2015-07-22 12:02:51,751 [AbstractBat(26)] NotifyMailBat is start.
INFO  2015-07-22 12:02:51,754 [AbstractBat(27)] Env [KNOWLEDGE_HOME] is [null].
INFO  2015-07-22 12:02:52,155 [AbstractBat(28)] Config :{"basePath":"/srv/tomcat/.knowledge","databasePath":"/srv/tomcat/.knowledge/db/","hashIterations":100,"indexPath":"/srv/tomcat/.knowledge/index/","languages":[{"label":"Japanese","value":"ja"},{"label":"English","value":"en"}],"systemName":"knowledge","time_zone":"Asia/Tokyo","tmpPath":"/srv/tomcat/.knowledge/tmp/","uploadMaxMBSize":500,"webRealPath":""}
INFO  2015-07-22 12:02:52,304 [DBConnenctionLogic(35)] Custom connection setting is exists.

[koda-masaru]

ご連絡ありがとうございます。

なんとかメール通知を治そうとして、Release 0.5.3 Pre2を出してみたのですが、
よけいにメール送信できなくなっているようです（デモ環境で確認）
メール通知処理以外は動いているのですが、、、メール通知部分は作り壊したようです 😢

次のリリースまでに、ちゃんと送信できるように修正しますので、
それまで少々お待ちください。

[koda-masaru]

メールの処理を見なおした、Release0.5.3pre3を作成しました。
これで、メール通知されるようになるでしょうか？

[irgaly]

ありがとうございます。0.5.3 pre3でメールが送信されるようになりました。

0.5.3pre3へアップデート後に記事を作成したところ、一度は以下のログでメールが送れなかったのですが、改めてメールアカウントとパスワードを入力し設定した後は、次の記事からメールが送信されるようになりました。

たびたびご対応いただきありがとうございました。

ERROR 2015-07-28 23:54:53,162 [MailSendBat(187)] Mail send error
javax.mail.AuthenticationFailedException: 535-5.7.8 Username and Password not accepted. Learn more at
535 5.7.8  https://support.google.com/mail/answer/14257 pm4sm6403247pdb.36 - gsmtp

        at com.sun.mail.smtp.SMTPTransport$Authenticator.authenticate(SMTPTransport.java:826)
        at com.sun.mail.smtp.SMTPTransport.authenticate(SMTPTransport.java:761)
        at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:685)
        at javax.mail.Service.connect(Service.java:317)
        at javax.mail.Service.connect(Service.java:176)
        at javax.mail.Service.connect(Service.java:125)
        at javax.mail.Transport.send0(Transport.java:194)
        at javax.mail.Transport.send(Transport.java:124)
        at org.support.project.knowledge.bat.MailSendBat.mailSend(MailSendBat.java:176)
        at org.support.project.knowledge.bat.MailSendBat.start(MailSendBat.java:91)
        at org.support.project.knowledge.bat.MailSendBat.main(MailSendBat.java:63)

[koda-masaru]

確認＆ご連絡ありがとうございます 😄
メール送信が正しく出来て安心しました。

[koda-masaru]

動作確認もできたため、リリースしました。issueはクローズします。