常設チャットをはじめよう（第4回）トラブルシュート編

  • Article

こんばんは、 Lync サポートチームの吉野です。
連続シリーズ（？）常設チャットも今回がいったんラストとなります。
サポートらしくトラブルシュート編をお送りします。

では事例をもとに解説していきます。

 

 

 

…と、言いたかったのですが、ありません。事例…。

お伝えしました通り、まだ日本ではあまり展開されていないためトラブル事例がないのです。
ということで、実際に問題が起きたらどうする？という観点で説明していきます。

まず、常設チャットの通信の流れを Snooper で見ていきましょう。参考文献は以下です。

https://technet.microsoft.com/ja-JP/library/jj683096.aspx

1. Lync クライアントは最初に SIP SUBSCRIBE を送信し、インバンド プロビジョニング ドキュメントをサーバーから取得します。このドキュメントは、常設チャットがユーザーに対して有効になっているか無効になっているか、および常設チャット サーバー プールの SIP URI の一覧を示します。
2.Lync クライアントは SIP INVITE メッセージを、前の手順で取得した常設チャット サーバーの SIP URI に送信します。（以下略）

ということなので SUBSCRIBE （のレスポンス）を見てみましょう。

 

ありました。

確かに、EnabledPersistentChatや常設チャットの SIP URI が記載されています。常設チャットのアイコンが表示されない場合、ここを確認して意図したポリシーが適用されているか確認しましょう。

その後確かにINVITEを送っていますね。

3. Lync クライアントは、XCCOS getserverinfo コマンドが含まれる SIP INFO メッセージを送信します。常設チャット サーバーは、常設チャット サービス構成に関する情報が含まれる新しい SIP INFO メッセージで応答します。

ということなので SIP INFO メッセージを見てみましょう。

 

たしかに XCCOS getserverinfo を送っていますね。応答もありました。

その後 4~6 の処理もあり最終的に

7. Lync クライアントは、XCCOS getinv (つまり、招待の取得) コマンドが含まれる SIP INFO メッセージを送信し、クライアントがまだ確認していない新しいルーム招待を要求します。別の SIP INFO メッセージでは、常設チャット サーバーがこれらのルームの一覧を返します。

こちらのレスポンスとして以下を受け取っています。前回作った会議の情報はサインイン時に取っていることがわかりました。

 

購読時のやりとりもこちらのページに書いてありますので、クライアント側からの調査は UCCP ログを見れば調査ができることがわかりました。

 

次にサーバー側です。

Lync Server 2013 Debugging Tools にある OCSLogger を利用してみましょう。

Chatから始まるのが PersistentChat のモジュールです。どのコンポーネントで何がわかるか？という点は名前から推測できそうですが、このような場合基本的にすべてにチェックを入れます。
つまり以下のようにします。

また、それとは別に、SIPStack/S4 は常にONにしておきます。例えば先ほどのクライアントの  XCCOS のメッセージなんかもこちらに記録されます。

ではとりあえず New-CsPersistentChatRoom で新しい部屋を作ってみましょう。

そして View Log Files でログを見てみます。

Roomがないという警告が出ていますが、 New-Cs～で新しく作った部屋なので当然です。「想定されたエラー・警告」も出力されますので注意してください。

TL_INFO(TF_COMPONENT) [0]0CB0.1E08::09/18/2014-05:14:56.081.000004e5 (ChatCommon,ServerCluster.BuildGraphData:3398.idx(57))(000000000309C2FC)The largest active clique of servers contains server IDs: 1
TL_INFO(TF_COMPONENT) [0]0CB0.1E08::09/18/2014-05:14:56.096.000004e6 (ChatCommon,PeerServerManager.OnActiveClusterUpdated:2623.idx(346))(00000000005EC3F1)List of active servers in the pool are: ServerIdentity: 1, ActiveServersList: { 1 }
TL_INFO(TF_COMPONENT) [0]0CB0.2BC8::09/18/2014-05:14:56.219.000004ee (ChatServer,PSWCFService.constructor:1981.idx(42))[PSWCFService]Called the empty constructor
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.256.000004fa (ChatServer,RoutingProcessor.Process:587.idx(162))(000000000199CF26)Processed ActiveClusterChangedMessage. |S: Avg: 5, Max: 197, Min: 0, #: 83, Sum: 419, Span: 02:44:12.5194032, PT(ms): 43, QT(ms): 114.9989, OQ1: 0, OQ2(MB): 0, TM: 0, CM: 0|, ID: 0:0, Receipt:0@2014/09/18 5:14:56, From:
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.294.00000519 (ChatServer,RoutingProcessor.Process:587.idx(162))(000000000199CF26)Processed LookupCategoryUriCommandMessage. |S: Avg: 503, Max: 4969, Min: 0, #: 10, Sum: 5035, Span: 02:36:57.9209961, PT(ms): 35, QT(ms): 17.002, OQ1: 0, OQ2(MB): 0, TM: 1, CM: 0|, ID: 8870254510192997847:1, Receipt:0@2014/09/18 5:14:56, From: sip:systemuser
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.526.00000549 (ChatCommon,BaseNodeParser.ParseScopeLists:2522.idx(139))(0000000001792A66)Processed <0> scope entries. Elapsed: 00:00:00.0000024
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.526.0000054a (ChatCommon,BaseNodeParser.ParseRoleLists:2522.idx(164))(0000000001792A66)Processed <0> role entries. Elapsed <00:00:00.0000018>
TL_WARN(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.527.0000054b (ChatCommon,DataAccess.GetNode:2927.idx(502))(000000000020E3AE)Node <logtest> not found in the database
TL_WARN(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.527.0000054c (ChatCommon,ServerNodeManager.Get:190.idx(262))(0000000003FA70CA)node not found: logtest
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.527.00000554 (ChatCommon,Node.Save:143.idx(235))(FFFFFFFFFFFFFFFF)Updating DB for node <logtest> with user <sip:systemuser>
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.540.0000056a (ChatCommon,BaseNodeParser.ParseScopeLists:2522.idx(139))(000000000322AA51)Processed <1> scope entries. Elapsed: 00:00:00.0000884
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.540.0000056b (ChatCommon,BaseNodeParser.ParseRoleLists:2522.idx(164))(000000000322AA51)Processed <0> role entries. Elapsed <00:00:00.0000031>
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.540.0000056c (ChatCommon,Node.Load:143.idx(940))(0000000000000006)Loading node <ma-chan://blog.net/660b951f-5a5c-4519-9462-6c84e8be33c7> with data from <6>
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.540.0000056e (ChatCommon,Node.setNodeSettings:143.idx(968))(0000000000000006)Set Node setting <urn:parlano:ma:info:visibility> with value <SCOPED> for <ma-chan://blog.net/660b951f-5a5c-4519-9462-6c84e8be33c7>
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.540.0000056f (ChatCommon,Node.PopulateRolesAndScope:143.idx(633))(0000000000000006)Populated roles for <ma-chan://blog.net/660b951f-5a5c-4519-9462-6c84e8be33c7>
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.553.00000579 (ChatServer,InviteGenerator.RecalculateInvites:2660.idx(66))(00000000003B8BCB)Recalculate invites for channel (name: logtest, id: 6, uri: ma-chan://blog.net/660b951f-5a5c-4519-9462-6c84e8be33c7)
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.553.0000057a (ChatServer,InviteGenerator.RecalculateInvites:2660.idx(107))(00000000003B8BCB)Recalculating invites (allflag = False)
TL_INFO(TF_COMPONENT) [0]0CB0.10A0::09/18/2014-05:14:56.553.0000057e (ChatServer,RoutingProcessor.Process:587.idx(162))(000000000199CF26)Processed CreateCommandMessage. |S: Avg: 47, Max: 102, Min: 0, #: 3, Sum: 143, Span: 01:48:43.0242537, PT(ms): 30, QT(ms): 0, OQ1: 0, OQ2(MB): 0, TM: 2, CM: 0|, ID: 8870254510192997848:1, Receipt:0@2014/09/18 5:14:56, From: sip:systemuser
TL_INFO(TF_COMPONENT) [0]0CB0.14C8::09/18/2014-05:14:56.864.0000058f (ChatCommon,DataAccess.RecalculateInvites:2927.idx(2333))(000000000020E3AE)Recalculating invites in the database (channelDbId=6, prinDbId=-1)...
TL_INFO(TF_COMPONENT) [0]0CB0.14C8::09/18/2014-05:14:56.942.00000595 (ChatCommon,DataAccess.RecalculateInvites:2927.idx(2339))(000000000020E3AE)Recalculated invites in the database. Elapsed time 00:00:00.0772346

Room名や ChatRoom URI が New-CsPersistentChatRoom の出力結果と同じになっています。部屋を作った人もわかります（ここでは systemuser ですが...）
正常時の出力結果を持っておき、なにか異常があった際に正常時と比較することは常設チャットだけでなくすべての現象において重要になってきます。

以上でひとまず常設チャットについては終わりです。省略したアドインやアダプターなどより深い話題が必要になったら第5回を投稿するかもしれません。
それでは快適な常設 Lync ライフをご満喫ください。

関連 Blog
Skype for Business Server 2015 常設チャット Part1 展開の計画https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2017/08/10/sfbpc_part1/ 

Skype for Business Server 2015 常設チャット Part2 展開https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2017/08/10/sfbpc_part2/

Skype for Business Server 2015 常設チャット Part3 アーキテクチャーhttps://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2017/08/10/sfbpc_part3/

Skype for Business Server 2015 常設チャット Part4 トラブル シューティングhttps://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2017/08/10/sfbpc_part4/ 

Skype for Business Server 2015 常設チャット Part5 リソース キット
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2017/08/10/sfbpc_part5/

常設チャットをはじめよう（第1回）
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/09/15/1/

常設チャットをはじめよう（第2回）インストール編
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/09/17/2/

常設チャットをはじめよう（第3回）管理編
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/09/17/3/

常設チャットをはじめよう（第4回）トラブルシュート編
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/09/18/432232/

常設チャットをはじめよう（第5回）アドイン編
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/12/02/5/

Lync 2013 常設チャットにファイル添付で Crash
https://blogs.msdn.microsoft.com/lync_support_team_blog_japan/2014/12/09/lync-2013-crash/

本情報の内容 (添付文書、リンク先などを含む) は、作成日時点でのものであり、予告なく変更される場合があります。