JDBC, Linux und reiner Zufall

Manche Probleme — besonders die, die nur sporadisch auftreten — sind nicht so leicht zu diagnostizieren und erfordern einen tieferen Einstieg in die Materie. In diesem Praxisbeispiel bedeutet das: SQL*Net Tracing und Verständnis für die Funktionsweise des Betriebssystems, speziell die Generierung von Zufallszahlen.

Der vorliegende Fall eignet sich daher sehr gut, um eine Vorgehensweise beim Troubleshooting von Verbindungen zur Datenbank exemplarisch darzulegen.

Szenario

Ein in Java geschriebener Batch-Job führt regelmäßig einen Datenabgleich mit einer entfernten Datenbank durch. Dazu werden von der Anwendung bis zu fünf Verbindungen kurz hintereinander aufgebaut.

Dabei kommt es gelegentlich zu Timeouts beim Verbindungsaufbau, so daß nur ein Teil der Verbindungsversuche erfolgreich ist. Ein genauerer Blick in die Logfiles der Anwendung zeigt, daß viele Verbindungen in weniger als einer Sekunde aufgebaut werden, wohingegen andere über 20s benötigen.

DB-Server: Oracle Linux 5, Oracle EE 11.2.0.3

JDBC: Oracle ojdbc6.jar, Version 11.2.0.3

Differentialdiagnose

Erste Anlaufstelle ist das Logfile der Anwendung, aus dem hervorgeht, daß einzelne Verbindungen ~30s zum Aufbau benötigen:

---
2013-11-04 10:50:45,479 register driver oracle.jdbc.driver.OracleDriver
2013-11-04 10:50:45,638 connect to jdbc:oracle:thin:@dbsvr:1521:ORCL
2013-11-04 10:51:13,045 connection established
---

Steigt die Verbindungsdauer über 60s, kommt es zu einem Abbruch der Verbindung durch den Server, der im Alert Log zu sehen ist:

Fatal NI connect error 12170.
VERSION INFORMATION:
 TNS for Linux: Version 11.2.0.3.0 - Production
 Oracle Bequeath NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production
 TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production
 Time: 30-OCT-2013 08:47:36
 Tracing not turned on.
 Tns error struct:
 ns main err code: 12535
TNS-12535: TNS:operation timed out
 ns secondary err code: 12606
 nt main err code: 0
 nt secondary err code: 0
 nt OS err code: 0
 Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.20.30.40)(PORT=33600))
WARNING: inbound connection timed out (ORA-3136)

Erste Erkenntnisse

Das Eröffnen einer Session in Oracle läuft wie folgt ab:

  1. Client schickt einen Request an den Oracle-Listener
  2. Listener prüft, ob er eine DB-Instanz bzw. einen Service für den Request kennt
  3. Listener geht an den pmon-Hintergrundprozeß der Datenbankinstanz
  4. pmon startet einen Serverprozess auf dem Datenbankserver (sichtbarer Prozeß auf OS-Ebene)
  5. Der Serverprozess allokiert einen freien IP-Port auf dem Datenbankserver im Bereich von üblicherweise 9000-64000 (s.o., dort war es Port 33600)
  6. pmon schickt die Information über den gestarteten Serverprozeß mit OS-Port an den Listener
  7. Listener schickt die Information an den Client
  8. Ab jetzt hat der Listener mit der Datenbankverbindung nichts mehr zu tun!
  9. Client startet eine neue IP-Verbindung DIREKT zum Serverprozeß mit dem vom Listener ausgehandelten Port
  10. Der Serverprozess fordert nun den Client zur Authentifizierung auf.

Erfolgt die Authentifizierung nicht innerhalb des vorgegebenen Timeouts, dann beendet der pmon den Serverprozess und schließt die IP-Verbindung zum Client. Diese Aktion wird im alert.log von Oracle protokolliert und ist oben zu beobachten.

Es ist also schon einmal klar, daß die Verbindung zwischen Client und Server grundsätzlich immer zustande kommt, es dann aber gelegentlich nicht zu einer erfolgreichen Authentifizierung innerhalb des vorgegebenen Zeitfensters kommt.

Erster Workaround

Eine erste Maßnahme, um das Problem zu umgehen, ist die Anpassung der Dateien „listener.ora“ und „sqlnet.ora“ (in $ORACLE_HOME/network/admin) mit einem höheren Timeout:

sqlnet.ora: SQLNET.INBOUND_CONNECT_TIMEOUT = 120

listener.ora: INBOUND_CONNECT_TIMEOUT_<listener_name> = 110

Das Timeout wird dabei in Sekunden angegeben, wobei das Timeout vom Listener kürzer gesetzt werden sollte als das von der Datenbank, damit noch etwas Spielraum für die Verbindungsübergabe an den Server-Prozess bleibt. Siehe MOS-Dokument: „Troubleshooting ORA-3136: WARNING Inbound Connection Timed Out“ (Doc ID 465043.1)

Mit diesen Einstellungen traten die Verbindungsabbrüche dann zwar nicht mehr auf, aber die Ursache für die Zeitverzögerungen war damit natürlich nicht behoben. Außerdem sind zwei Minuten Wartezeit für eine Verbindung in vielen Umgebungen schlicht zu hoch.

Trace als weiteres Beweismittel

Um  noch klarer zu belegen, daß das Problem nicht auf Seiten des DB-Servers liegt, bietet sich ein Tracing des SQL*Net-Protokolls an, bei dem detailliert jeder Schritt des Verbindungsaufbaus dargelegt wird.

Das Tracing kann an zwei Stellen erfolgen: Am Listener und am Serverprozess. Aus den ersten Erkenntnissen wissen wir bereits, daß der Listener seine Arbeit erfolgreich durchgeführt hat. Daher muss für den Serverprozess eine weitere Einstellung in der Datei „sqlnet.ora“ gemacht werden:

TRACE_LEVEL_SERVER=16

Die Einstellung greift sofort ab dem Abspeichern für alle neu gestarteten Serverprozesse, kann also in kurzer Zeit sehr viele und große Dateien erzeugen. Sie sollte daher schnellstmöglich wieder abgeschaltet werden!

Um die Tracefiles in ein lesbareres Format zu bringen, liefert Oracle das Tool „trcasst“ mit. Die passende Kommandozeile für unseren Anwendungsfall ist „trcasst -o“ und liefert folgende Ausgabe (auch hier nur auszugsweise):

---
<--- Received 158 bytes - Data packet timestamp=04-NOV-2013 10:50:46:024
Start of user function (TTIFUN)
Get the session key (OSESSKEY)

---> Send 210 bytes - Data packet timestamp=04-NOV-2013 10:50:46:031
Return opi parameter (TTIRPA)

<--- Received 992 bytes - Data packet timestamp=04-NOV-2013 10:51:13:023
Start of user function (TTIFUN)
Generic authentication call (OAUTH)
---

„Send“ steht hier für den Server, „Receive“ für empfangene Nachrichten vom Client.

Man sieht hier, daß der Server zunächst eine Anfrage erhalten hatte, diese nach 7 ms bereits beantwortete und der Client daraufhin nach etwa 27 s erst wieder antwortete. Die weitere Authentifizierung lief dann schnell und ist hier nicht mehr dargestellt.

Eine Überprüfung der Netzwerkaktivität mit Wireshark belegte desweiteren, daß die gesendeten 210 Bytes auch nicht irgendwo im Netzwerk „hängen geblieben“ waren sondern mit den üblichen Latenzen ausgeliefert wurden. Der Client war nun eindeutig als Ort der Zeitverzögerung identifiziert!

Diagnose

Ein SR beim JDBC-Team von Oracle Support brachte schnell die Ursache für die gelegentlichen Ausfälle ans Licht:

  • Mit Oracle 11g wurde das alte Authentifizierungsverfahren „O3logon“ durch das neue „O5logon“ abgelöst (und in die Version 10.2.0.5 zurück portiert).
  • Das neue Verfahren erfordert hinreichend zufällige Zahlen, die vom Betriebssystem generiert werden.
  • Unter neueren Linuxen werden diese Zufallszahlen über die Devices „/dev/random“ und „/dev/urandom“ geliefert.
  • Dieses Verfahren erfordert eine gewisse Entropie, die über externe Quellen wie z.B. Tastatur und Maus generiert wird (was bei einem Server in einem Rechenzentrum recht unpraktisch ist). Detaillierte Infos dazu siehe „Weblinks“ unten.
  • Wie etliche Authentifizierungsverfahren nutzt auch O5logon „/dev/random“ als Quelle für Zufallszahlen.
  • „/dev/random“ blockiert (wartet), wenn keine ausreichende Entropie vorhanden ist und liefert weitere Zufallszahlen erst wieder, wenn der „Entropy Pool“ ausreichend gefüllt ist. Das kann durchaus bis zu einer Minute dauern.
  • Der „Entropy Pool“ kann sich zu schnell leeren, wenn zu viele O5logon-Verfahren in kürzester Zeit gestartet werden; auch durch andere Anwendungen, die Zufallszahlen benötigen, verbrauchen den Pool.

Den endgültigen Beweis für den Entropy Pool als Ursache lieferten mehrere Ansätze:

  1. Das alte Authentifizierungsverfahren verwenden. Dies geht über den Java-Kommandozeilenparameter:
    -Doracle.jdbc.thinLogonCapability=o3
    (Wegen einer Sicherheitslücke im neuen Protokoll wäre das bis zum Einsatz eines 12c-Clients übergangsweise sogar sinnvoll!)
  2. Das nicht blockierende Device „/dev/urandom“ benutzen. Dies geht über die Java-Kommandozeilenparameter:-Djava.security.egd=file:/dev/./urandom -Dsecurerandom.source=file:/dev/./urandom
  3. Den Entropy Pool überwachen; dieser liegt üblicherweise bei ca. 3000 Bytes. Sinkt er deutlich unter 500, ist auch das ein Anzeichen für einen austrocknenden Pool. Sekündliches Überwachen geht mit der Linux-Kommandozeile:
    watch -n 1 cat /proc/sys/kernel/random/entropy_avail
    Dabei ist allerdings anzumerken, daß die Messung selbst die Messwerte beeinflusst; größere Zeitabstände (z.B. 3s) verringern die Größe der Verfremdung.

Dem Zufall auf die Sprünge helfen

Drei Lösungsansätze wurden betrachtet:

  1. Dauerhaftes Ändern des Batch-Aufrufes, so daß künftig das nicht blockierende „/dev/urandom“ benutzt wird. Dies geht über die Java-Kommandozeilenparameter:
    -Djava.security.egd=file:/dev/./urandom -Dsecurerandom.source=file:/dev/./urandom
    , was letztlich die bevorzugte Lösung wurde.
  2. Einsatz des „rngd„, um Zufallszahlen schneller zu generieren.
  3. Ändern der Applikation, um nicht so viele Verbindungen gleichzeitig zu öffnen.
    Dies wurde auf unbestimmt verschoben, da es nicht klar war, ob der Verbrauch an Entropie nicht von anderen Anwendungen verursacht wurde.

Das Erzeugen von Zufallszahlen in eigentlich deterministischen Systemen ist nicht trivial. Grundsätzlich ist aber ein hohes Maß an „Zufälligkeit“ wichtig für sicherheitsrelevante Systeme, damit ein Angreifer nicht durch „kluges Raten“ einen Sicherheitsmechanismus aushebeln kann. Für besonders sensitive Bereiche gibt es daher auch kommerzielle Generatoren (z.B. hier).

Weblinks

Über Entropie und Zufallszahlen in Linux:

Schreibe einen Kommentar

Trage deine Daten unten ein oder klicke ein Icon um dich einzuloggen:

WordPress.com-Logo

Du kommentierst mit Deinem WordPress.com-Konto. Abmelden / Ändern )

Twitter-Bild

Du kommentierst mit Deinem Twitter-Konto. Abmelden / Ändern )

Facebook-Foto

Du kommentierst mit Deinem Facebook-Konto. Abmelden / Ändern )

Google+ Foto

Du kommentierst mit Deinem Google+-Konto. Abmelden / Ändern )

Verbinde mit %s