Por que a abreviação assume a saída do log para um processo que não travou?

Question

Versão resumida:

1. Eu tenho um processo de longa execução (proxy da web) que registra (com detalhes) no syslog
2. Algo mal acontece, e abrevia passos em de alguma forma
3. O processo continua a ser executado ...
4. ... mas todas as mensagens de log para o syslog agora são marcadas como "abrt:" em vez de "xfcproxy [1234]:"
5. Alguma ideia do porquê?

Versão longa:

Aqui está um exemplo do que vemos do ponto de vista do log, como "algo acontece" e o processo continua a ser registrado, mas com o nome do processo no syslog sendo alterado. Observe como todas as mensagens do proxy iniciam "uuid = ...", e podemos ver essas mensagens registradas no início deste snippet em "xfcproxy [4808]:" e, na parte inferior deste snippet, em "abrt:"

Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Open client_ip=192.168.3.21 client_port=40973
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e rule=Destination message="Match made" rule=monitoring uri=www.example.com
Aug 27 07:02:55 proxy1 rsyslogd-2177: imuxsock begins to drop messages from pid 4808 due to rate-limiting
Aug 27 07:02:55 proxy1 abrtd: New client connected
Aug 27 07:02:55 proxy1 abrtd: Directory 'pyhook-2014-08-27-07:02:55-4808' creation detected
Aug 27 07:02:55 proxy1 abrt-server[27032]: Saved Python crash dump of pid 4808 to /var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
Aug 27 07:02:55 proxy1 abrtd: Executable '/var/lib/xfcProxy/bin/xfcProxy.py' doesn't belong to any package and ProcessUnpackaged is set to 'no'
Aug 27 07:02:55 proxy1 abrtd: 'post-create' on '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808' exited with 1
Aug 27 07:02:55 proxy1 abrtd: Deleting problem directory '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'
Aug 27 07:03:37 proxy1 rsyslogd-2177: imuxsock lost 1642 messages from pid 4808 due to rate-limiting
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Open client_ip=192.168.3.21 client_port=40976
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 rule=Destination message="Match made" rule=monitoring uri=www.example.com

Usando 'ps', vejo que o PID 4808 que estava em execução ainda está em execução:

[root@proxy1 log]# ps 4808
  PID TTY      STAT   TIME COMMAND
 4808 ?        S      1:34 python /var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 log]#

O 'imuxsock começa a soltar mensagens' é um tanto normal - este daemon é muito falador (eu mostrei apenas um pequeno subconjunto seqüencial de mensagens aqui) e uma enxurrada de mensagens pode disparar a limitação de taxa completamente além desse problema com taxa limitando.

Embora meu conhecimento sobre o abrt seja limitado, parece que ele não tem informações de falha, mas acredita que esse processo caiu relacionado ao tempo dos registros:

[root@proxy1 abrt]# pwd
/var/spool/abrt
[root@proxy1 abrt]# ls -l
total 4
-rw-r--r--. 1 root root  0 Mar 18 15:45 abrt-db
-rw-------  1 root root 33 Aug 27 07:02 last-via-server
[root@proxy1 abrt]# echo 'cat last-via-server '
/var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 abrt]#

O processo em questão é um processo python multithreaded - estou certamente aberto à ideia de que não estou limpando os threads corretamente e, portanto, acionando esse comportamento. É apenas um comportamento estranho.

Esclarecimentos para @Mikel:

• Sim, RHEL 6
• / var / log / messages via rsyslog. Eu não tentei journald, e precisaria reproduzir em um servidor de não produção antes que eu pudesse tentar uma mudança como essa.

Atualize após o período de recompensas:

Temo que não possa conceder a recompensa pela resposta existente de E Carter Young, pelas seguintes razões:

1. O imuxsock rate-limiting não faz, até onde eu sei, ao revisar fontes rsyslog, acionar qualquer tipo de mudança no processo ou envolver abrtd de qualquer forma. Ele simplesmente descarta o fluxo por um tempo e depois retoma a leitura mais tarde.
2. Um processo que grava excessivamente no syslog não é de forma alguma uma situação de estouro de buffer. Utilização de recursos, sim; talvez até negação de serviço, mas só porque é um buffer e só porque está muito cheio não significa que seja um estouro de buffer.
3. As etapas descritas não correspondem à situação; Especificamente na etapa 6, o rsyslog não está buscando do processo abrev, está buscando do processo original; o mistério é porque ele está usando o nome abrt para isso.
4. Eu também não estou convencido de que haja alguma condição de corrida aqui. (Preencher o buffer de log rápido não é uma condição de corrida)

Acho que essa pergunta é muito complexa e carece de dados, e isso se resume a várias perguntas mais simples que poderiam ser feitas com mais dados:

• Por que o abrtd é acionado em um processo que não sai, se, por definição, é acionado em processos que falharem? O que representou uma queda suficiente para se envolver? Eu acho que a resposta está nos logs perdidos, mas eu não acho que os logs em falta sejam a resposta. Não há evidência de que o rsyslog invoque abrtd.
• Por que o rsyslog começa a usar abrt como o nome do processo, uma vez que o abrtd é acionado em um processo (de uma maneira demonstrável, como foi respondido pela pergunta anterior)?

Infelizmente, sem mais dados, não me sinto à vontade para fazer essas perguntas hoje.

Embora eu não possa aceitar essa resposta, acredito que há um valor definitivo:

• Descrição da lista negra abreviada
• Discussão clara e concisa das minhas opções
  • Aumentar ou remover o limite de taxa e os registros de desordem
  • Alterar a verbosidade do processo
  • processo de lista negra com abrt para que nunca entre em

Como tal, estou feliz que metade da recompensa irá para a resposta de E Carter Young como a resposta mais votada quando a recompensa expirar.

    

Answer 1

Se você não quiser que este processo seja tratado por abrtd, adicione-o à lista negra abrtd em este arquivo conf . O Imuxsock está limitando a quantidade de registro porque a limitação de taxa está ativada. Uma vez que o limite é atingido, o abrt não registrará mais o nome do processo real, porque ele foi avisado para não fazer isso, portanto, como o processo ainda está sendo executado, abrt é exibido como uma substituição. Veja este blog . Você pode considerar o uso do Squid

Atualizar
Para entender esta seção de atualização, você precisa ler em Multiplexing , especificamente:

In computer programming, it may refer to using a single in-memory resource (such as a file handle) to handle multiple external resources (such as on-disk files).

O identificador de arquivo para o seu processo incorreto é canalizado para esse recurso de memória. Em circunstâncias normais, a maioria dos serviços e processos para esse assunto tem um código de saída. Uma vez atingido o limite de taxa, o socket immux transfere o controle para o rsyslog para escrever a linha:

o imuxsock começa a abandonar as mensagens do pid 4808 devido a limitação de taxa

Nesse ponto, abrt assume que o processo incorreto terá saído com um código de saída anormal e grava o processo problemático e qualquer saída para /var/spool/abrt/pyhook-(time_date) . Como o script não tem código de saída, na próxima gravação de log, o rsyslog captura o que estiver no buffer do imuxsocket, mas como o buffer de soquete nunca foi esvaziado - veja a etapa 5, porque o processo ainda está em execução, você cria um problema de buffer ... Os hackers geralmente transformam essas situações em estouros de buffer. Essas etapas ocorrem na seguinte ordem:

1. O Imuxsock reporta ao rsyslog que o processo 4808 não deve ser informado.
2. O abrtd está configurado para relatar qualquer comportamento estranho e inicia
3. O rsyslog respeita a solicitação.
4. Seu script, sob o pid 4808, continua escrevendo no log, sem informar código de saída, porque você o projetou dessa maneira.
5. abrtd percebendo que não pode fornecer um código de saída para o rsyslog faz o seguinte (porque o seu processo não sai):

Aug 27 07:02:55 proxy1 abrtd: Deleting problem directory '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'

Se o código de saída tivesse sido informado, o abrtd enviaria um relatório de bug para você, se configurado para isso. Veja a página man abrtd , e você veria o conteúdo de /var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
 6. rsyslog, porque está honrando o passo 2, não pode reportar o processo 4808 busca o item mais recente no buffer de imux, que por acaso é o abrt process, porque abrt ainda está esperando um código de saída do passo 5, mas desde o passo 5 nunca concluído .....

Em termos de programação, isso é chamado de condição de corrida. O programa que você escreveu está preenchendo o buffer de log mais rápido do que o buffer de log pode gravar a saída. Como tal:

• defina SysSock.RateLimit.Interval > 5 segundos e SysSock.RateLimit.Burst > 200
• defina SysSock.RateLimit.Interval = 0 e confunda seu log.
• reescreva seu programa com parâmetros para definir a verbosidade
• execute seu script como um serviço e coloque-o na lista negra nas configurações abrtd