Se você estiver executando aplicativos em contêineres e estiver usando o GELF logging driver do Docker (ou estiver considerando usá-lo), as reflexões a seguir podem ser relevantes para seus interesses.

Um pouco de contexto

Quando você executa aplicativos em contêineres, o método de logging mais fácil é gravar na saída padrão. Você não terá nada mais simples do que isso: apenas echo, print, write (ou o equivalente em sua linguagem de programação!) e o mecanismo de contêiner irá capturar a saída do seu aplicativo.

Outras abordagens ainda são possíveis, é claro; por exemplo:

• você pode usar syslog, executando um daemon syslog em seu contêiner ou expondo um soquete/dev/log;
• você pode escrever em arquivos normais e compartilhar esses arquivos de log com seu host ou com outros contêineres, colocando-os em um volume;
• seu código pode conversar diretamente com a API de um serviço de logging.

No último cenário, este serviço pode ser:

• um mecanismo de logging proprietário operado pelo seu provedor de nuvem, por exemplo, AWS CloudWatch ou Google Stackdriver;
• fornecido por terceiros especializados no gerenciamento de logs ou eventos, por exemplo, Honeycomb, Loggly, Splunk, etc;
• algo sendo executado em casa, que você mesmo implanta e mantém.

Se a sua aplicação é muito concisa ou se ela serve muito pouco tráfego (porque tem três usuários, incluindo você e seu cão), você pode certamente executar o seu serviço de logging em casa. Em meu workshop de orchestration tem uma parte sobre o logging que pode lhe dar a falsa ideia de que executar o seu próprio cluster ELK é sempre maravilhoso e mágico, enquanto a verdade é muito diferente e executar sistemas confiáveis ​​de logging em escala é difícil.

Sendo assim, você certamente quer a possibilidade de enviar seus logs para outra pessoa que vai lidar com a complexidade (e a dor) do armazenamento em tempo real, indexação e consulta de dados semiestruturados. Vale a pena mencionar que essas pessoas podem fazer mais do que apenas gerenciar seus logs. Alguns sistemas como Sentry são particularmente adequados para extrair insights de erros (pense em traceback dissection); e muitas ferramentas modernas, como Honeycomb irão lidar não só com logs, mas também com qualquer tipo de evento, permitindo fazer uma referência cruzada de tudo para descobrir a causa real daquela desagradável interrupção às 3 da manhã.

Mas antes de chegar lá, você quer começar com algo fácil de implementar e gratuito (tanto quanto possível).

É aí que o logging de contêiner é útil. Basta escrever seus logs em stdout e deixar a engine de seu contêiner fazer todo o trabalho. No começo, ela escreverá arquivos chatos; mas mais tarde, você pode reconfigurá-la para fazer algo mais inteligente com seus logs – sem alterar o código do aplicativo.

Note que as ideias e ferramentas que eu discuto aqui são ortogonais para a plataforma de orquestração que você pode ou não estar usando: Kubernetes, Mesos, Rancher, Swarm… Elas podem alavancar os drivers de logging do Docker Engine.

O driver de log padrão: json-file

Por padrão, o Docker Engine irá capturar a saída padrão (e erro padrão) de todos os seus contêineres e gravá-los em arquivos usando o formato JSON (daí o nome json-file para este driver de logging padrão). O formato JSON anota cada linha com sua origem (stdout ou stderr) e seu timestamp e mantém cada log de contêiner em um arquivo separado.

Quando você usa o comando docker log (ou o API endpoint equivalente), o Docker Engine lê desses arquivos e te mostra o que foi impresso pelo seu contêiner. Por enquanto, tudo bem.

O driver json-file, no entanto, tem (pelo menos) dois pontos críticos:

• por padrão, os arquivos de log crescerão sem limites, até que você fique sem espaço no disco;
• você não pode fazer consultas complexas como “mostre-me todas as solicitações HTTP para o virtual host container.church entre 2h e 7h da manhã com um tempo de resposta de mais de 250ms, mas somente se o código de status HTTP for 200/OK”.

O primeiro problema pode ser facilmente corrigido fornecendo alguns parâmetros extras para o driver json-file no Docker para habilitar a rotação de log. O segundo, no entanto, requer um desses serviços de log que eu estava me referindo.

Mesmo que suas consultas não sejam tão complexas, você vai querer centralizar seus logs de alguma forma, para que:

• os logs não sejam perdidos para sempre quando a instância da nuvem que executa o contêiner desaparece;
• você pode, pelo menos, fazer um grep dos logs de vários recipientes sem fazer um dumping total através da Docker API ou ter que utilizar SSH.

Observação: quando eu ainda tinha um pager e cuidava da plataforma dotCloud, nossa técnica de análise de log preferida era chamada de “Ops Map/Reduce” e envolvia fabric, conexões SSH paralelas, grep e alguns outros truques. Antes de você rir de nossas técnicas antiquadas, me responda como sua equipe de seis engenheiros lidou com os arquivos de log de 100 mil contêineres 5 anos atrás e vamos comparar nossas cicatrizes de batalha e problemas relacionados com contas de terapia tomando uma xícara de chá, cerveja ou outra bebida adequada.  ♥

Além do json-file

Tudo bem, você pode começar a desenvolver (e até mesmo implementar) com o driver json-file padrão, mas em algum momento, você precisará de algo a mais para lidar com a quantidade de logs gerados por seus contêineres.

É aí que os drivers de logging são úteis: sem alterar uma única linha de código em seu aplicativo, você pode pedir à fiel engine de seu contêiner que envie os logs em outro lugar. Massa, né?

Docker suporta muitos outros drivers de logging, incluindo, mas não limitado a:

• awslogs, se você estiver executando na nuvem da Amazon e não planeja migrar para qualquer outra, nunca;
• gcplogs, se você é uma pessoa mais do Google;
• syslog, se você já tem um servidor syslog centralizado e deseja alavancá-lo para seus contêineres;
• gelf

Eu vou parar a lista por aqui porque GELF tem algumas características que o tornam particularmente interessante e versátil.

GELF

GELF significa Graylog Extended Log Format. Inicialmente foi projetado para o sistema de logging Graylog. Se você ainda não tinha ouvido falar sobre o Graylog, é um projeto de código aberto que foi pioneiro em sistemas de logging “modernos” como o ELK. Na verdade, se você quiser enviar logs do Docker para o seu cluster ELK, você provavelmente usará o protocolo GELF! É um padrão aberto implementado por muitos sistemas de logging (abertos ou proprietário).

O que há de tão bom no protocolo GELF? Ele aborda algumas (se não a maioria) das falhas do protocolo syslog.

Com o protocolo syslog, uma mensagem de log é principalmente uma sequência em bruto, com muito pouco metadados. Há algum tipo de acordo entre os emissores e receptores; uma mensagem syslog válida deve ser formatada de uma maneira específica, permitindo extrair as seguintes informações:

• uma priority: é uma mensagem de debugging, um aviso, algo puramente informativo, um erro crítico, etc;
• uma timestamp mostrando quando a coisa aconteceu;
• um hostname indicando onde a coisa aconteceu (ou seja, em qual máquina);
• uma facility que indica se a mensagem vem do sistema de correio, do kernel e tal e tal;
• um nome e número de processo;

Esse protocolo foi ótimo nos anos 80 (e até nos anos 90), mas tem algumas deficiências:

• como ele evoluiu ao longo do tempo, há quase 10 diferentes RFCs para especificar, estender e adaptar para vários casos de uso;
• o tamanho da mensagem é limitado, o que significa que mensagens muito longas (por exemplo: rastreamento) têm de ser truncadas ou divididas entre mensagens;
• no final das contas, mesmo que alguns metadados possam ser extraídos, a carga é uma simples cadeia de texto sem adornos.

GELF fez um movimento muito arriscado e decidiu que cada mensagem de log seria um dict (ou um mapa ou um hash ou como você quiser chamá-los). Este “dict” teria os seguintes campos:

• versão;
• host (que enviou a mensagem em primeiro lugar);
• timestamp;
• versão curta e longa da mensagem;
• qualquer campo extra que você quiser!

Num primeiro momento, você pode pensar: “OK, qual é o problema?” Mas isso significa que, quando um servidor web faz uma solicitação, em vez de ter uma string raw como esta:

127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326

Você obtém um dict como este:

{
  "client": "127.0.0.1",
  "user": "frank",
  "timestamp": "2000-10-10 13:55:36 -0700",
  "method": "GET",
  "uri": "/apache_pb.gif",
  "protocol": "HTTP/1.0",
  "status": 200,
  "size": 2326
}

Isso também significa que os logs ficam armazenados como objetos estruturados, em vez de strings raw. Como resultado, você pode fazer consultas elaboradas (algo como SQL) em vez de cavar expressões regulares com o grep como se fosse um roedor.

OK, então GELF é um formato conveniente que o Docker pode emitir e que é compreendido por uma série de ferramentas como Graylog, Logstash, Fluentd e muitas outras.

Além disso, você pode alternar do padrão json-file para GELF muito facilmente; o que significa que você pode começar com json-file (ou seja, não configure nada em seu cluster Docker) e mais tarde, quando você decidir que essas entradas de log podem ser então úteis, mude para GELF sem mexer em nada no seu aplicativo e automaticamente tenha seus logs centralizados e indexados em algum lugar.

Usando um driver de logging

Como podemos mudar para GELF (ou qualquer outro formato)?

Docker fornece duas flags de linha de comando para isso:

• –log-driver para indicar qual driver usar;
• –log-opt para passar as opções arbitrárias para o driver.

Essas opções podem ser passadas para docker run, indicando que você quer este contêiner específico para usar um mecanismo de logging diferente; ou para o Docker Engine em si (quando iniciá-lo) para que se torne a opção padrão para todos os contêineres.

(Se você estiver usando o Docker API para iniciar seus contêineres, essas opções são passadas para a chamada create, dentro da estrutura HostConfig.LogConfig)

As “opções arbitrárias” variam para cada driver. No caso do driver do GELF, você pode especificar um monte de opções mas há uma que é obrigatória: o endereço do receptor GELF.

Se nós temos um receptor GELF na máquina 1.2.3.4 no padrão UDP porta 12201, você pode começar seu contêiner como segue:

docker run \
–log-driver gelf –log-opt gelf-address=udp://1.2.3.4:12201 \
alpine echo hello world

As seguintes coisas vão acontecer:

• o Docker Engine vai puxar a imagem alpine (se necessário)
• o Docker Engine irá criar e iniciar o nosso contêiner
• o contêiner irá executar o comando echo com argumentos hello world
• o processo no contêiner vai escrever hello world para a saída padrão
• a mensagem hello world será passada para quem está assistindo (ou seja, você, já que você começou o contêiner em primeiro plano)
• a mensagem hello world vai também ser pega por Docker e enviada para o driver de logging
• o driver de logging gelf irá preparar uma mensagem GELF completa, incluindo o nome do host, o timestamp, a string hello world, mas também um monte de informações sobre o contêiner, incluindo seu ID completo, nome, nome da imagem e ID, variáveis de ambiente e muito mais;
• esta mensagem GELF será enviada através de UDP para 1.2.3.4 na porta 12201.

Então, é esperado que 1.2.3.4 recebe o pacote UDP, processa-o, escreve a mensagem para alguma loja indexada persistente e permite que você o recupere ou o consulte.

É esperado.

Gostaria de dizer-lhe uma piada sobre UDP, mas…

Se você já esteve de plantão ou responsável pelo código de outras pessoas, você provavelmente está se encolhendo agora. Nossas preciosas mensagens de logging estão dentro de um pacote UDP que pode ou não chegar ao nosso servidor de logging (UDP não tem nenhuma garantia de transmissão). Se o nosso servidor de logging vai embora (uma bela expressão para “falhou horrivelmente”), o nosso pacote deve chegar, mas a nossa mensagem será obviamente ignorada e nós não saberemos nada sobre isso. (Tecnicamente, deveremos obter uma mensagem de ICMP nos dizendo que o host ou a porta está inacessível, mas nesse momento será tarde demais, porque nem mesmo saberemos a qual mensagem isto se refere!)

Talvez possamos viver com algumas mensagens descartadas (ou um monte, se o servidor de logging estiver sendo reiniciado, por exemplo). Mas e se estivermos na Nuvem e nosso servidor evaporar? Sério: e se eu estiver enviando minhas mensagens de log para uma instância do EC2, e por alguma razão essa instância tenha que ser substituída por outra? A nova instância terá um endereço IP diferente, mas as minhas mensagens de log continuarão a obstinadamente ir para o endereço antigo.

DNS para o resgate

Uma técnica fácil de trabalhar com endereços IP voláteis é usar o DNS. Em vez de especificar 1.2.3.4 como nosso alvo GELF, usaremos gelf.container.church e nos certificaremos de que isso aponte para 1.2.3.4. Dessa forma, sempre que precisarmos enviar mensagens para uma máquina diferente, nós apenas atualizaremos o registro DNS e nosso Docker Engine felizmente enviará as mensagens para a nova máquina.

Ou não?

Se você tiver que escrever algum código enviando dados para uma máquina remota (digamos, gelf.container.church na porta 12345), a versão mais simples ficará assim:

1. Determine container.church para um endereço IP (A.B.C.D)
2. Crie um soquete
3. Ligue este soquete à A.B.C.D, na porta 12345
4. Envie dados no soquete.

Se você precisa enviar dados várias vezes, você manterá o soquete aberto, tanto para fins de conveniência quanto de eficiência. Isto é particularmente importante com soquetes TCP, porque antes de enviar os seus dados, você tem que passar pelo “3-way handshake” para estabelecer a conexão TCP; em outras palavras, o terceiro passo na nossa lista acima é muito caro (em comparação com o custo de enviar um pequeno pacote de dados).

No caso de soquetes UDP, você pode ser tentado a pensar: “Ah, já que eu não preciso fazer o 3-way handshake antes de enviar dados (o terceiro passo na nossa lista acima é essencialmente livre), eu posso passar por todos os 4 passos cada vez que eu precisar enviar uma mensagem! “Mas na verdade, se você fizer isso, você vai rapidamente perceber que está amarrado no primeiro passo, a resolução de DNS. A resolução de DNS é mais barata do que um 3-way handshake TCP, mas não é bem assim: ainda requer uma viagem de ida e volta para o seu resolvedor de DNS.

Observação: sim, é possível ter resolvedores de DNS locais muito eficientes. Algo como pdns-recursor ou dnsmasq executando em localhost fará você ter algum tempo de resposta rápido de DNS para consultas em cache. No entanto, se você precisar fazer um pedido de DNS cada vez que enviar uma mensagem de log, ele adicionará um custo indireto, mas significativo, ao seu aplicativo, já que cada linha de log gerará não apenas um syscall, mas três. E algumas pessoas (como quase todas as pessoas que executam o EC2) estão usando o serviço de DNS do provedor de nuvem. Essas pessoas irão incorrer em dois pacotes de rede extras para cada linha de log. E quando o DNS do provedor de nuvem estiver desativado, o logging será interrompido. Isso não é legal.

Conclusão: se você efetuar log em UDP, não determoine o endereço do servidor de logging toda vez que você enviar uma mensagem.

Hmmm… TCP para o resgate, então?

Faria sentido usar uma conexão TCP e mantê-la o tempo que for necessário. Se algo horrível acontece ao servidor de logging, podemos confiar na máquina de estado TCP para detectar isso eventualmente (por causa dos timeouts e whatnots) e nos notificar. Quando isso acontece, podemos então determinar novamente o nome do servidor e reconectar. Nós só precisamos de um pouco de lógica extra no mecanismo de contêiner, para lidar com o cenário infeliz onde o write no soquete nos dá um erro EPIPE, também conhecido como “Broken pipe” ou simplesmente “a outra extremidade não está mais prestando atenção em nós.”

Vamos falar com o nosso servidor GELF usando TCP e o problema será resolvido, certo?

Certo?

Infelizmente, o driver de logging GELF no Docker suporta apenas UDP.

(╯°□°)╯︵ ┻━┻

Neste ponto, se você ainda está conosco, pode ter concluído que a computação é apenas um tipo especializado de inferno, que os contêineres são o anticristo e Docker é o prenúncio da desgraça disfarçada.

Antes de tirar conclusões precipitadas, vamos dar uma olhada no código.

Quando você cria um contêiner utilizando o driver GELF, esta função é invocada e cria um novo objeto gelfWriter chamando gelf.NewWriter.

Em seguida, quando o contêiner imprime algo, eventualmente, a função Log do driver GELF é invocada. Ele essencialmente escreve a mensagem para o gelfWriter.

Este objeto GELF writer é implementado por uma dependência externa, github.com/Graylog2/go-gelf.

Olha, eu vejo isso chegando, ele vai fazer um te mostrar o dedo e colocar a culpa no código de outra pessoa. Desprezível!

Batata quente

Vamos investigar este pacote, em particular a função NewWriter, o método Write e os outros métodos chamados pelo último, WriteMessage e writeChunked. Mesmo se você não for muito familiarizado com Go, você verá que essas funções não implementam qualquer tipo de lógica de reconexão. Se algo ruim acontece, o erro vai subir de volta e é isso.

Se conduzirmos a mesma investigação com o código do lado Docker (com os links na seção anterior), chegamos às mesmas conclusões. Se ocorrer um erro ao enviar uma mensagem de log, o erro é passado para a camada acima. Não há tentativa de reconexão, nem no código de Docker, nem no go-gelf.

Isso, a propósito, explica por que Docker só suporta o transporte UDP. Se você quiser suportar TCP, você tem que suportar mais condições de erro do que UDP. Para expressar as coisas de forma diferente: suporte TCP seria mais complicado e com mais linhas de código.

Haters gonna hate

Uma possível reação é ficar bravo com a alma corajosa que implementou go-gelf ou com aquele que implementou o driver GELF no Docker. Outra reação melhor é agradecer que escreveram esse código, em vez de nenhum código!

Soluções alternativas

Vamos ver como resolver nosso problema de logging.

A solução mais fácil é reiniciar nossos contêineres sempre que precisarmos “reconectar” (tecnicamente, resolver e reconectar). Isso funciona, mas é muito chato.

Uma solução ligeiramente melhor é enviar logs para 127.0.0.1:12201 e, em seguida, executar um redirecionador de pacotes para “saltar” ou “espelhar” esses pacotes para o logger real; por exemplo:

socat UDP-LISTEN: 12201 UDP: gelf.container.church: 12201

Isso precisa ser executado em cada host de contêiner. É muito leve, e sempre que gelf.container.church é atualizado, em vez de reiniciar seus contêineres, basta reiniciar socat.

(Você também pode enviar seus pacotes de log para um IP virtual e usar algumas belas regras iptables -t nat … -j DNAT para reescrever o endereço de destino dos pacotes indo para este IP virtual).

Outra opção é executar Logstash em cada node (em vez de apenas socat). Pode parecer exagerado no início, mas isso lhe dará muita flexibilidade extra com seus logs: você pode fazer algumas análises locais, filtragem e até mesmo “forking”, ou seja, decidir enviar seus logs para vários lugares ao mesmo tempo. Isto é particularmente conveniente se você estiver mudando de um sistema de logging para outro, porque ele permitirá que você alimente ambos os sistemas em paralelo por um tempo (durante um período de transição).

Executar o Logstash (ou outra ferramenta de logging) em cada node também é muito útil se você quiser ter certeza de que não perderá nenhuma mensagem de log, porque seria o lugar perfeito para inserir uma fila (usando Redis para cenários simples ou Kafka se você tiver requisitos mais rigorosos).

Mesmo se você acabar enviando seus logs para um serviço usando um protocolo diferente, o driver GELF é provavelmente o mais fácil de configurar para conectar a Docker, por exemplo, Logstash ou Fluentd e, em seguida, Logstash ou Fluentd falar com o serviço de log com o outro protocolo.

Os pacotes UDP enviados para o localhost não podem ser perdidos, exceto se o soquete UDP ficar sem espaço de buffer. Isso pode acontecer se o seu remetente (Docker) for mais rápido do que o seu receptor (Logstash / Fluentd), razão pela qual mencionamos uma fila mais cedo: a fila permitirá ao receptor drenar o buffer UDP o mais rápido possível para evitar overflows. Combine isso com um buffer UDP grande o suficiente e você estará seguro.

Direções futuras

Mesmo se a execução de um socat de todo o cluster for relativamente fácil (especialmente com o modo Swarm e o docker service create –mode global), preferimos ter um bom comportamento fora da caixa.

Já existem alguns issues no GitHub relacionados a isso: #23679, #17904 e #16330. Um dos mantenedores se juntou à conversa e há algumas pessoas na Docker Inc. que adorariam ver isso melhorado.

Uma possível correção é determinar novamente o nome do servidor GELF de vez em quando, e quando uma alteração for detectada, atualizar o endereço de destino do soquete. Como o DNS fornece informações TTL, ele pode até ser usado para saber quanto tempo o endereço IP pode ser armazenado em cache.

Se você precisa de melhor apoio GELF, tenho uma boa notícia: você pode ajudar! Não vou dizer “basta fazer um pull request ha ha ha!”, porque eu sei que apenas um número muito pequeno de pessoas têm tempo e experiência para fazer isso – mas se você é um deles, então por todos os motivos, faça! Existem outras maneiras de ajudar, no entanto.

Primeiro, você pode monitorar as issues do GitHub mencionadas acima (#23679 e #17904). Se os colaboradores e mantenedores pedirem por feedback, indique o que funcionaria (ou não) para você. Se você vir uma proposta que faz sentido e você só quer dizer “+1”, você pode fazer isso com as reações do GitHub (o emoji do joinha funciona perfeitamente para isso). E se alguém propõe um pull request, testá-lo será extremamente útil e prático para torná-lo aceito.

Se você olhar para uma dessas issues no GitHub, você verá que já havia um patch proposto há muito tempo; mas a pessoa que pediu pelo recurso em primeiro lugar nunca testou, e como resultado, nunca foi feito o merge. Não me interpretem mal, eu não estou colocando a culpa nessa pessoa! É um bom começo para ter uma issue como uma espécie de “ponto de encontro” para pessoas que precisam de um recurso e outras que podem implementá-lo.

É muito provável que, em poucos meses, metade deste artigo se torne obsoleto porque o driver GELF irá suportar conexões TCP e/ou corrigirá corretamente endereços para endereços UDP!

 

***

Este artigo é do Docker Core Engineering. A tradução do artigo foi feita pela Redação iMasters com autorização, e você pode acompanhar o artigo em inglês no link: https://blog.docker.com/2017/02/adventures-in-gelf/