SfB: AlwaysOn Logging

So betrieben Sie ein permanentes Logging auf ihrer Skype for Business Umgebung um bei Fehlern sehr schnell auch die Details zu erhalten. Mit Lync mussten Sie immer erst das Logging aktivieren und den Fehler reproduzieren. das geht mit Skype for Business ebenfalls aber mit dem Scenario "AlwaysOn" haben sie ein mächtiges Werkzeug, um die meisten Fehler auch noch im Nachhinein zu analysieren. Allerdinge benötigen Sie etwas Platz auf dem Server. Doch dazu gleich mehr.

AlwaysOn auf Skype for Business

CLSLogging wird normalerweise „bei Bedarf“ gestartet und protokolliert gemäß der Szenarien bestimmte Informationen in einem ETL-Trace, welches durchsuchbar ist. Allerdings werden diese Traces per Default nach 4 Stunden wieder gestoppt. Damit werden die Systeme weniger belastet, Speicherplatz gespart und natürlich ist auch Datenschutz ein Thema, da in den Traces doch sehr genaue Analysen von SIP-Meldungen möglich sind.

The AlwaysOn scenario has no default duration. This scenario will run until you explicitly stop it with the Stop-CsClsLogging cmdlet. For details, see Stop-CsClsLogging. For all other scenarios, the default duration is 4 hours
Quelle: Start or stop CLS log capture in Skype for Business Server 2015 https://docs.microsoft.com/en-us/skypeforbusiness/management-tools/centralized-logging-service/start-or-stop-log-capture

Allerdings gibt es unter den 44 per Default eingerichteten Szenarien auch ein besonderes Szenario mit dem Namen „Global/AlwaysOn“. Dieses Szenario ist darauf ausgelegt, permanent aktiv zu sein.

The default scenario is called AlwaysOn. The intended purpose for AlwaysOn is to run the scenario constantly, as the name of the scenario implies. The AlwaysOn scenario collects Info level information (note that Info logging level includes Fatal, Error, and Warning in addition to Info messages) for many of the most common server components. AlwaysOn collects information before, during, and after a problem occurs.
Quelle: Start or stop CLS log capture in Skype for Business Server 2015 https://docs.microsoft.com/en-us/skypeforbusiness/management-tools/centralized-logging-service/start-or-stop-log-capture

Über die globale Konfiguration wird gesteuert, wie lange die Dateien vorgehalten werden. Entsprechend kann ähnlich dem Exchange Messagetracking in die Vergangenheit gesucht werden.

Globale Konfiguration

Die Standardeinstellungen für CLSLogging sind:

Get-CsClsConfiguration

Identity                      : Global
Scenarios                     : {Name=AlwaysOn, Name=NonTopologyAlwaysOn, Name=MediaConnectivity,
                                Name=ApplicationSharing...}
SearchTerms                   : {Type=Phone;Inserts=ItemE164,ItemURI,ItemSIP,ItemPII,
                                Type=URI;Inserts=ItemURI,ItemSIP,ItemPII,
                                Type=CallId;Inserts=ItemCALLID,ItemURI,ItemSIP,ItemPII,
                                Type=ConfId;Inserts=ItemCONFID,ItemURI,ItemSIP,ItemPII...}
SecurityGroups                : {}
Regions                       : {}
EtlFileFolder                 : %TEMP%\Tracing
EtlFileRolloverSizeMB         : 20
EtlFileRolloverMinutes        : 60
TmfFileSearchPath             :
CacheFileLocalFolders         : %TEMP%\Tracing
CacheFileNetworkFolder        :
CacheFileLocalRetentionPeriod : 14
CacheFileLocalMaxDiskUsage    : 80
ComponentThrottleLimit        : 5000
ComponentThrottleSample       : 3
MinimumClsAgentServiceVersion : 6
NetworkUsagePacketSize        : 64
NetworkUsageThreshold         : 10
Version                       : 6.0.9319.0

Interessant sind hier die Werte für ETLFile* und „CacheFile*, da diese für alle Server bestimmen, wie lange diese Dateien aufbewahrt werden. CLSLogging erstellt erst die ETL-Dateien und konvertiert diese dann in entsprechende Cache-Dateien.

Die Logging-Dienste laufen als „NetworkService,

Get-WmiObject win32_service | ?{$_.name -eq "RTCCLSAGT"}| format-list name,startname

name      : RTCCLSAGT
startname : NT AUTHORITY\NetworkService

Damit ist %temp% eigentlich in „C:\Windows\ServiceProfiles\NetworkService\AppData\Local\Temp\tracing” zu finden. In dem Verzeichnis werden Sie ggfls. auch alte Traces finden. Sicher ein Verzeichnis, welches auf Wachstum überwacht werden muss, denn nicht immer werden die Dateien sauber gelöscht.

Standardmäßig loggt CLSLogging, bis die Festplatte zu 80% gefüllt ist, d.h. wenn die Festplatte einen Füllgrad von 80% erreicht hat, dann stoppt CLSLogging. Diesen Wert können Sie anpassen. Wer also eine sehr große Festplatte hat, bei dem sind vielleicht auch bei 90% Füllgrad noch einige GB frei. Wer aber nur eine kleine Partition bereitgestellt hat, für den können 20% "Restkapazität" schon zu wenig sein. Dann muss man das runterstellen.

Set-CsClsConfiguration -CacheFileLocalMaxDiskUsage 70

Die Änderung hat interessanterweise bewirkt, dass alle Cache-Dateien einmal entfernt wurden und das Logging neu startet. Dennoch sollten Sie die Verzeichniss hinsichtlich des Platzbedarfs und das Volume auf den freien Speicher hin überwachen.

Sie haben aber vieleicht auch gesehen, dass es den Parameter CacheFileNetworkFolder gibt, über den Sie die Ablage der Log auf einem Share konfigurieren können.

After two weeks (that is, the timeframe is configurable using the Set-CsClsConfiguration cmdlet) these files are copied to a file share and deleted from the local computer.
Quelle: https://docs.microsoft.com/en-us/skypeforbusiness/management-tools/centralized-logging-service/centralized-logging-service

Dabei ist dieser Platz kein Lagerort zweite Klasse, denn er kann ebenfalls durchsucht werden.

Files that are moved to the file share from the local computer can be searched by ClsAgent. Once ClsAgent moves the files to the file share, the aging and removal of files is not maintained by ClsAgent. You should define an administrative task to monitor the size of the files in the file share and delete them or archive them
Quelle: https://docs.microsoft.com/en-us/skypeforbusiness/management-tools/centralized-logging-service/centralized-logging-service

Microsoft hat so direkt ins Produkt einen Weg eingebaut, die Logs auch über einen längeren Zeitraum aufzubewahren. Sie müssen nur den Platz vorhalten. Da leider nicht ausgeschlossen ist, dass mehrere Server Dateien mit dem gleichen Namen anlegen, sollte jeder Server sein eigenes Verzeichnis haben. Es kann aber durchaus ein gemeinsamer Share sein. Wenn der Copy durch „Network System“ erfolgt, müssten wohl die Rechte an die Gruppe „RTCServer“ vergeben werden.

Interessant könnte es auch sein, diese Logs von 20 MB auf einen kleineren Wert zu stellen, diese dann schnell abzuholen und in einer eigenen Software zur Auswertung bereit zu stellen. Die CACHE-Dateien sind durchaus lesbar.

Netzwerk Share

Sie haben sicher gesehen, dass es in der Konfiguration einen Parameter "CacheFileNetworkFolder" gibt, mit dem Sie den CLSAgent anweisen können, die Dateien auf einen zentralen Share abzulegen. Wenn Sie dies nicht tun, dann könnte es passieren, dass immer wieder im Eventlog der folgende Fehler erscheint

Log Name:      Lync Server
Source:        LS Centralized Logging Agent
Event ID:      33020
Task Category: (1007)
Level:         Error
Keywords:      Classic User:          N/A
Description:
Centralized Logging Service Agent Error while moving cache files to network share.

Path: C:\Windows\ServiceProfiles\NetworkService\AppData\Local\Temp\Tracing\CLS_WPP_07-20-2017-23-03-34.cache 
Exception(s): NetworkCacheDirForAgent not set in Cls Configuration. Use Set-CsClsConfiguration to set it
Cause: Examine exception details to determine cause.
Resolution:
Examine exception details to determine resolution.

Sie können den Fehler ignorieren oder eben einen Share Anlege, auf dem NetworkSysteme Schreibrechte hat. Dort wird dann pro Server ein Unterverzeichnis angelegt, indem dann die Archivierten Logs landen.

Allerdings löscht niemand diese Logs automatisch, wenn Sie nicht selbst ein Skript zum Löschen umsetzen.

Auch sind die dazu erforderlichen SMB-Verbindungen vom CLSAgent zum FileShare in einem Diagramm oder Portliste enthalten. Das dürfte zumindest die Edge-Server daran hindern, ihre archivierten Logs mit auf den Dateishare zu legen. Auch die Freigabe eines SMB-Share als "NetworkSystem" und nicht explizit an die Server oder ein Dienstkonto, ist nicht überall erlaubt. Dann wäre wohl ein lokales Verzeichnis mit einem selbst zu entwickelnden "Einsammelprozess" eine Alternative. 

AlwaysOn Szenario

In der Einleitung habe ich schon geschrieben, dass es ein gesondertes "Szenario" namens "AlwaysOn" gibt. Get-CsCLSScenario liefert weitere Details zu AlwaysOn

Get-CsClsScenario Global/AlwaysOn

Identity : Global/AlwaysOn
Provider : {Name=AsMcu;Type=WPP;Level=Info;Flags=TF_COMPONENT,TF_PROTOCOL;Guid=;Role=,
           Name=AcpMcu;Type=WPP;Level=Info;Flags=TF_COMPONENT;Guid=;Role=,
           Name=ApiModule;Type=WPP;Level=Info;Flags=TF_COMPONENT,TF_PROTOCOL;Guid=;Role=,
           Name=Autodiscover;Type=WPP;Level=Info;Flags=All;Guid=;Role=...}
Name     : AlwaysOn

Ein Blick auf die Provider liefert 119 Einträge. Interessant finde ich dazu folgende Einträge:

(Get-CsClsScenario global/AlwaysOn).provider | ft

Name                Type   Level Flags
----                ----   ----- -----
ABCommon             WPP Warning All
ABServer             WPP Warning All
InboundRouting       WPP    Info TF_COMPONENT,TF_PROTOCOL,TF_DIAG
MediationServer      WPP    Info TF_COMPONENT,TF_PROTOCOL,TF_CONNECTION,TF_DIAG
OutboundRouting      WPP    Info TF_COMPONENT,TF_PROTOCOL
Sipstack             WPP    Info TF_PROTOCOL,TF_CONNECTION,TF_SECURITY,TF_DIAG

Speziell die Protokollierung für den SIP-Stack und Mediation sollte durch diese Einstellung genug Details für Telefonie liefern.

Starten und Stoppen

Wenn Sie ihren Skype for Business Server installieren, dann werden zwar alle Szenarien installiert aber es wird keines gestartet. Von allen normalen Szenarien kann immer nur ein Szenario manuell gestartet werden und aktiv sein. Die Ausnahme dabei ist das Szenario AlwaysOn, welches parallel laufen kann und auch nicht nach 4 Stunden beendet wird.

Start-CsClsLogging -Scenario alwayson

    PoolFqdn: fepool1.msxfaq.net
MachineFqdn          ResponseMessage     AlwaysOn ScenarioName     Remaining ProductVersion
                                                                        Mins
-----------          ---------------     -------- ------------     --------- --------------
fe01.msxfaq.net                          True                      0         6.0.9319.0
fe02.msxfaq.net                          True                      0         6.0.9319.0

Mehr bekommen Sie aber auch erst mal nicht zu sehen. Das Szenario läuft einfach.

Genauso wichtig ist natürlich auch das Beenden des Szenarioa

Stop-CsClsLogging -Scenario alwayson

Die Trace-Dateien werden aber nicht umgehend gelöscht, sondern auch erst wieder nach der konfigurierten Haltezeit

Scenario Status anzeigen

Über Show-CsClsLogging kann schnell ermittelt werden, dass „AlwaysOn“ auch wirklich aktiv ist.

Show-CsClsLogging | select machinefqdn,alwayson

MachineFqdn                        AlwaysOn
-----------                        --------
fe01.msxfaq.net             True
fe02.msxfaq.net             True

Agenten-Status anzeigen

Auf jedem Server können Sie natürlich auch den Status des Agenten anzeigen. Hier sehen Sie dann auch den realen "Logpath"

Get-CsClsAgentStatus

ClsAgentExeVersion : 6.0.9319.0 built by: lcs_se_w16_ship(rtbldlab)
ServiceStatus      : Running
TracingFolder      : {default.tmx, default.xml}
ServiceStartStop   : {Started: 7/20/2017 3:50:27 AM, Started: 7/18/2017...}
EventLogs          : {fe01.msxfaq.net}
AgentState         : <?xml version="1.0" encoding="utf-16"?>
                     <AgentState xmlns:xsd="http://www.w3.org/2001/XMLSchema"
                     xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
                       <DefaultEnabled>true</DefaultEnabled>
                       <DefaultScenarioHash>516221430</DefaultScenarioHash>
                       <ScenarioHash>0</ScenarioHash>
                       <DurationMins>0</DurationMins>
                       <RequestUser>NT AUTHORITY\NETWORK SERVICE</RequestUser>
                       <RequestTime>0001-01-01T00:00:00</RequestTime>
                     </AgentState>
LogPath            : C:\Windows\ServiceProfiles\NetworkService\AppData\Local\Temp\tracing
OldestFile         : CLS_WPP_07-19-2017-16-13-20.cache
NewestFile         : CLS_WPP_07-20-2017-14-50-30.cache
LogAge             : 00:02:52
LogFileCount       : 5
LogDateRanges      : 07-20:07-19
DaysOfLogs         : 2
TotalLogMB         : 0
DailyLogMB         : 0
ByDayLogMB         : {[7/20/2017 12:00:00 AM, 0], [7/19/2017 12:00:00 AM, 0]}
ByHourLogMB        : {[7/20/2017 2:00:00 PM, 0], [7/20/2017 1:00:00 AM, 0],
                     [7/19/2017 4:00:00 PM, 0]}
DriveFreeGB        : 16
DriveSizeGB        : 99
DriveFreePercent   : 16.74
AllFiles           : {CLS_WPP_07-20-2017-14-50-30.cache,
                     CLS_WPP_07-19-2017-16-15-55.cache...}
LogStartTime        : 7/19/2017 4:50:50 PM
EndTime          : 7/19/2017 5:20:50 PM
SuccessfulAgents : {fepool1.msxfaq.net\fe01.msxfaq.net, fepool1.msxfaq.net\fe02.msxfaq.net...}
FailedAgents     : {}

Gut zu sehen sind auch die Daten zu "DriveFreeGB" und "DriveSizeGB" und einige andere Daten. Sie können auch ermitteln, wann der Dienst selbst gestoppt und gestartet wurde, um so "Lücken" zu erkennen

(Get-CSCLSAgentstatus).ServiceStartStop

Event   Time
-----   ----
Started 7/20/2017 7:39:13 PM
Stopped 7/20/2017 7:39:05 PM
Started 7/20/2017 7:38:54 PM
Stopped 7/20/2017 7:38:51 PM
Started 7/9/2017 2:46:25 PM
Stopped 7/9/2017 2:46:20 PM
Started 4/10/2017 8:03:44 AM
Stopped 4/9/2017 5:35:01 PM
Started 4/9/2017 5:33:38 PM
Stopped 4/9/2017 5:32:49 PM
Started 4/9/2017 5:05:30 PM
Started 4/9/2017 4:09:39 PM
Started 4/9/2017 3:53:05 PM

Selbst auf die Eventlogs des Agenten haben Sie direkt Zugriff.

(Get-CSCLSAgentstatus).EventLogs

   Index Time          EntryType   Source                 InstanceID Message
   ----- ----          ---------   ------                 ---------- -------
  125998 Jul 20 19:42  Error       LS Centralized Lo...   3287253244 Central...
  125997 Jul 20 19:39  Error       LS Centralized Lo...   3287253244 Central...
  125996 Jul 20 19:39  Error       LS Centralized Lo...   3287253250 Central...
  125995 Jul 20 19:39  Information LS Centralized Lo...   1139769578 Central...
  125994 Jul 20 19:39  Information LS Centralized Lo...   1139769613 Central...

Interessant ist hier, dass das Fehlen eines Netzwerklaufwerks auch als Fehler gemeldet wird:

(Get-CSCLSAgentstatus).EventLogs[0] | fl

Index              : 125998
EntryType          : Error
InstanceId         : 3287253244
Message            : Centralized Logging Service Agent Error while moving cache files to network share.
                     Path: C:\Windows\ServiceProfiles\NetworkService\AppData\Lo
                     cal\Temp\Tracing\CLS_WPP_07-20-2017-17-39-14.cache
                     Exception(s): NetworkCacheDirForAgent not set in Cls
                     Configuration. Use Set-CsClsConfiguration to set it
                     Cause: Examine exception details to determine cause.
                     Resolution:
                     Examine exception details to determine resolution.
Category           : LS Centralized Logging Agent
CategoryNumber     : 1007
ReplacementStrings : {C:\Windows\ServiceProfiles\NetworkService\AppData\Local\T
                     emp\Tracing\CLS_WPP_07-20-2017-17-39-14.cache,
                     NetworkCacheDirForAgent not set in Cls Configuration. Use
                     Set-CsClsConfiguration to set it}
Source             : LS Centralized Logging Agent
TimeGenerated      : 7/20/2017 7:42:03 PM
TimeWritten        : 7/20/2017 7:42:03 PM UserName           :

Das sind aber erst mal nur die Grundlagen für eine spätere Suche, wenn die Logs nicht funktionieren.

Logs durchsuchen

Die aufgesammelten Logs können Sie mit dem Commandlet "Search-CSCLSLogging" nach bestimmten Kriterien durchsuchen. Sie können natürlich auch die Logs aller Server gesammelt ausgeben lassen.

Search-CsClsLogging -OutputFilePath c:\temp\log.txt
Using start time 7/20/2017 7:26:46 PM
Using end time 7/20/2017 7:56:46 PM
Starting search against 2 computers

ResponseMessage  : Successful on 2 agents

OutputFile       : c:\temp\log.txt
StartTime        : 7/20/2017 7:26:46 PM
EndTime          : 7/20/2017 7:56:46 PM
SuccessfulAgents : {fepoo1.msxfaq.net\fe01.msxfaq.net,fepoo1.msxfaq.net\fe02.msxfaq.net}
FailedAgents     : {}

Die angegebene Textdatei kann allerdings sehr groß werden, auch wenn nur 30 Minuten Logs per Default enthalten sind. Sie sollte bei der Fehlersuche aber nicht nur den Zeitraum vorgeben, sondern auch zumindest einen Teilnehmer, der das zu untersuchende Problem hatte. Per Parameter sind sehr viele Einschränkungen möglich, z.B.:

  • -Uri <String>
    SIPAdresse eines Teilnehmers
  • -ConferenceId <String>
    KonferenzID um alle Events zu eier Konferenz zu erhalten. Damit könnte man durchaus auch "Join/Leave-Events" auswerten
  • -IP <IPAddress>
  • -Phone <String>

Wenn Sie mehrere Parameter angeben, dann sollten Sie auch den Parameter "-MatchAll" angeben, wenn alle Bedingungen zutreffen sollten. Ansonsten werden die Bedingungen "OR"-verknüpft, was dem Parameter "-MatchAny" entspricht. Eine Liste der möglichen Parameter finden Sie auf der Hilfeseite zum Commandlet

Die Textdatei ist dann wieder das „übliche“ Format, welches in Snooper einfach ausgewertet werden kann. Den Pfad sollte man „vollständig“ angeben, da die Datei ansonsten nicht immer angelegt wird.

Potential

Die Möglichkeit einer permanenten Protokollierung bestimmter Events mit nachträglicher Auswertung finde ich sehr hilfreich und auf der einen Seite wundere ich mich, dass ein WebServer (IIS) zwar jeden unwichtigen Request protokolliert aber bei Skype for Business per Default das Logging nicht aktiv ist. Sie sollten wirklich prüfen, was sie an ihrer Umgebung ändern müssen, um sich diese Möglichkeit einer rückwirkenden Analyse von Fehlern zu ermöglichen. Allerdings gibt es einige Dinge zu beachten

  • Platzbedarf
    Je länger Sie die Protokolle aufheben wollen, desto mehr Platz müssen sie vorhalten. Eventuell macht eine eigene Partition oder ein eigenes Volume hierfür Sinn, um die Datenmengen separat zu halten und Mangelsituationen auf wichtigen Disks zu vermeiden.
  • CPU/IOPS-Bedarf
    Das Protokollieren und Wegschreiben der Ausgaben ist natürlich mit zusätzlichen Aufwand verbunden. Ich konnte aber zumindest auf meinen Servern nicht wirklich eine messbare Mehrbelastung sehen.
  • Datenschutz
    Die Logs kann jeder Admin einsehen oder wer sonst noch ein "Search-CSCLSLogging" ausführen darf. Die gewonnenen Daten enthalten auch die SIP-Pakete zwischen Endpunkten und sind damit aus meiner Sicht "personenbezogene Daten". Zwar sind weder der Inhalte der Instant Messages noch die Audio/Video-Daten enthalten aber die Metadaten sind auch schon aufschlussreich genug

Auf der anderen Seite lassen sich mit den Daten durchaus interessante Aufgaben bewältigen wie z.B.

  • Helpdesk-Support
    Wäre es nicht praktisch, wenn der 1st-Level den Namen oder Rufnummer einer Problemverbindung eingibt und eine Software mehr Details aus dem Trace beziehen kann?
  • Ermitteln von Verbindungen ohne QoE/CDR-Datenbank
    Alle Verbindung sind enthalten. Ohne ein QoE/CDR-Deployment wird zwar der Client keine Daten senden aber auch aus den SDPs beim Verbindungsaufbau und Abbau können nützliche Metadaten ermittelt werden
  • Einsammeln von Fehlermeldungen
    In den Log tauchen natürlich auch alle SIP-Fehler aber auch interne Skype Server Fehler auf. Das können gute Frühwarnindikatoren sein
  • Es gibt sicher noch mehr Informationen..
    die nur passend aufbereitet werden müssten

Ich kenne aber noch kein Auswertetool oder Skript, welches das Szenario "AlwaysOn" als Basis für solche Auswertungen nutzt.

Weitere Links