Stetig locken die Logs

Docker ist ganz praktisch. Aber es entstehen auch neue Probleme, die bereits ohne Docker seit Jahrzehnten gelöst waren, z.B. Logging.

Dort war die Lösung entweder Syslog oder eigene Logfiles, alles (hoffentlich) sauber unter /var/log zu finden.

Das kann in Docker auch so sein - und verschwindet dann mit jedem neuen Container eines Images im Nichts. Oder es landet auf Stdout des Containers - was man relativ oft in Beispielen findet. docker logs zeigt diese dann an - bis der Container verschwindet und diese Logs mit nimmt.

Nun haben die Docker-Leute das auch erkannt und deshalb eine Logging in Docker eingebaut, das eben diese Ausgabe an einen Logservice schicken kann. Stopp, ist kein Service, ist ein Plugin von Docker, bei dem einige gleich dabei sind. Das heißt, es gibt mehrere Lösungen um das Logging irgendwo abzulegen.

Letztlich aber alle mit einem Nachteil: Falls die Applikation im Container sauber mit Syslog gearbeitet hat und ihre Levels meldet, ist das erstmal gar nicht so einfach an dieses "neue" Docker-Logging zu melden.

Ich hab es deshalb gar nicht erst versucht und mich dann für "FluentD" ¹ als Logging entschieden.

Im Compose File sieht das dann so aus:

1    logging:
2      driver: fluentd
3      options:
4        fluentd-address: "127.0.0.1:24224"
5        tag: "www"

Ja und genau bei der Adresse wurde es zum ersten mal ärgerlich: Die muss von außen, also dem Docker Host, erreichbar sein. D.h. ein FluentD-Image muss seinen Listen-Port öffnen. Das will doch aber keiner... immerhin, nur ein Listen auf Localhost geht.

1    ports:
2      - "127.0.0.1:24224:24224/tcp"

Dann kommt die Konfiguration von FluentD. Ok, die Syntax von dem Konfig-File ist dumm, die Möglichkeiten gigantisch, die damit entstehenden Komplexität für den Admin erstmal ein Ärgernis.

 1# fluentd/conf/fluent.conf
 2
 3<source>
 4  @type forward
 5  port 24224
 6</source>
 7
 8<source>
 9  @type tail
10  format apache2
11  tag apache.access
12  path /apache-logs/logfile.%Y.%m.%d-*
13</source>
14
15<match *.**>
16  @type copy
17  <store>
18          @type file
19          path /log/${tag[0]}/log_%Y-%m-%d
20          append true
21          <buffer tag,time>
22                timekey 1d
23                flush_mode immediate
24          </buffer>
25          <format>
26                @type stdout
27          </format>
28  </store>
29  <store>
30          @type file
31          path /log/json-${tag[0]}/log_%Y-%m-%d
32          append true
33          <buffer tag,time>
34                timekey 1d
35          </buffer>
36          <format>
37                @type json
38          </format>
39  </store>
40</match>

Es war ein arger Kampf, die Details aus der Doku zu entlocken. Mehr als einmal war ich generft und auch begeistert, was und wie es ging - bis und als es dann ging. Es ging am Ende echt alles!

Was tut das File in der Form (es läuft in einem fluentd Container):

• 1. Source: einen Port 24224 öffnen um dort Fluentd Nachrichten zu empfangen
• 2. Source: vom Volume, in der der Apache seine Logs schreibt (siehe ☛ Apache Logs Statistiken), diese Log lesen und parsen
• weil mir das zu kompliziert war, ein Match auf alle "Tags" (jede Logmeldung kann einen komplexen Tag bekommen, die über eine Punkt-Schreibweise Untertags haben kann, Syslog Typ und Loglevel lässt grüßen)
• weil sich JSON schlecht lesen lässt, ich das aber vielleicht doch für irgendwelche Tools mal haben will, speichere ich beides ab:
  • einmal als Textfile, das auch direkt appendet wird
    • Fluentd würde das sonst nur in einem Zwischenpuffer ablegen und nach einem Zeitplan erst ins finale File speichern
    • als Format stdout, was einem leicht Tail/Less/Grep baren Output am nächsten kommt
  • als JSON File, das aber eben nicht ständig ergänzt wird sondern eben erst im Zwischenpuffer

Der Irrsinn sind diese Filenamen. Also eigentlich ganz logisch. Aber was daraus im Filesystem dann wirklich wird, brachte mich erstmal zum Verzweifeln. Es wird ein Verzeichnis mit eben diese Pattern als Name angelegt, nicht etwa aufgelöst. Dort landet dann der Puffer, in irgendwelchen fancy Zufallsnamen.

Und erst wenn eben diese "Flush", wie sie es nennen, eintritt, wird daraus dann ein Logfile mit dem richtigen Namen. Fast, der Name wird um das Default-Suffix ergänzt, das man explizit abschalten muss.

Wie gesagt, es kann viel, es ging am Ende alles, aber sehr komplex und verwirrend.

Naja, fast alles: log_%Y-%m-%d ging, aber log_%Y-%m-%d-%H mochte er nicht, es würden die Minuten fehlen war die Fehlermeldung. Hat der eine Ahnung was ich machen wollte... Und wenn man im buffer kein time an gibt, gehen diese Platzhalter nicht. Sich sagte ja, verwirrend. Und %Y und dann dieser Shell-Style ${tag[0]} macht es nicht besser ($tag wäre der ganze Tag, mit [0] nur der erste Teil vor dem 1. Punkt).

Es gibt da noch viel mehr, diese Syntax mit "so Ähnlich wie XML" und Fancy @ bei manchen Elementen, macht es nicht schöner.

Fluentd kann auch alles an einen anderen Fluentd weiter reichen, sicherlich im Swarm ganz praktisch für einen zentralen Logservice. Sofern das mit dem Listen auf Localhost:24224 im Swarm-Mode problemlos geht (noch zu testen, aber Swarm und vServer, naja: Kein Docker Swarm mit (diesen) vServern ).