O worker Laravel que se matava a cada 80 segundos

Um registro criado por um atendente devia aparecer, em tempo real, na lista que outro atendente tinha aberta. Parou de aparecer. Quem estava do outro lado só via o item depois de recarregar a página — o dado estava salvo, e a notificação nunca chegava.

O que fazia o sintoma parecer bug de código era um detalhe: outro evento de tempo real da mesma aplicação, publicado pelo mesmo Redis, no mesmo pod, com o mesmo provedor de WebSocket, continuava perfeito. Duas telas, mesma infraestrutura, uma funcionando e a outra não. Isso empurra qualquer um para o módulo da tela quebrada.

Estava errado. As duas telas tinham uma diferença que não aparece em lugar nenhum do código de negócio: elas publicavam em filas diferentes, e uma das duas filas tinha um processo só para ela.

A fila que crescia

A primeira coisa útil que eu fiz foi sair do código. O console de debug do provedor de WebSocket, filtrado pelo canal da tela quebrada, não mostrava nada sendo publicado. Isso encerra metade das hipóteses de uma vez: se nada chega ao provedor, o problema é servidor, não front e não provedor.

Daí para a fila foi um passo. Medindo o tamanho de cada uma:

A tela que funcionava publicava na broadcast. A que não funcionava, na default.

Duas ressalvas que custaram tempo e valem para qualquer um que meça isso pelo Laravel. O size() da fila Redis soma pendentes, agendados e reservados num número só — para saber se a fila está crescendo ou só cheia de trabalho reservado, é preciso separar com llen e os dois zcard. E um número sozinho não diz nada: eu li o llen duas vezes, com vinte segundos de intervalo, e o saldo positivo é que provou que a fila crescia em vez de estar drenando devagar. Estava entrando 2,9 jobs por segundo a mais do que saía.

Fila crescendo com worker vivo significa worker que não consome. E aí veio o primeiro engano.

O SIGKILL que não era OOM

O supervisor dentro do pod mostrava o processo com PID altíssimo e uptime de segundos, enquanto os outros workers tinham uptime igual ao boot do container. Crash loop. O log do supervisor datava as mortes:

WARN exited: laravel-worker_00 (terminated by SIGKILL; not expected)

A cada 70 a 95 segundos, havia cinco dias.

SIGKILL num container tem uma explicação favorita, e eu fui direto nela: OOM. É a resposta certa com tanta frequência que quase não se confere. Conferi:

Não era o kernel. Era o próprio Laravel.

O worker registra um handler de alarme antes de processar cada job, e quem dispara esse handler é o pcntl_alarm armado com o timeout. Quando o alarme toca, o caminho termina aqui:

public function kill($status = 0, $options = null, $reason = null)
{
    $this->events->dispatch(new WorkerStopping($status, $options, $reason));

    if (extension_loaded('posix')) {
        posix_kill(getmypid(), SIGKILL); 
    }

    exit($status);
}Illuminate/Queue/Worker.php

O processo manda SIGKILL para si mesmo. É deliberado: um job congelado pode ter deixado o processo em estado irrecuperável, e o framework prefere a morte limpa à tentativa de desenrolar. O efeito colateral é que o diagnóstico desaparece junto. SIGKILL não escreve nada em lugar nenhum: não há stack trace, não há código de saída legível, não há uma linha no log de erro.

O .conf do supervisor não passava --timeout. Sem ele vale o default de 60 segundos, e os intervalos entre as mortes batiam: 60 segundos de alarme mais o tempo até o worker topar com o job congelado seguinte.

A tabela de jobs falhados tinha 16.991 registros acumulados desde março, que ninguém drenava. Um tipo de job dominava a lista com folga, e eu quase o acusei. A falha mais recente dele era de duas semanas antes. Filtrando pela última hora, sobravam 54 linhas e nenhuma delas era ele. Ler tabela cumulativa como estado atual é o erro que mais se repete em investigação de produção, e ele parece evidência.

A hipótese que eu anunciei

O worker rodava assim:

command=php /var/www/artisan queue:work redis --queue=workflow,default --sleep=3 --tries=3
numprocs=1supervisord.d/laravel-worker.conf

Duas filas, um processo. A workflow vazia o tempo todo; a default com três mil jobs represados.

Abri o driver do Redis e achei o que parecia ser a resposta:

public function pop($queue = null, $index = 0)
{
    $this->migrate($prefixed = $this->getQueue($queue));

    $block = ! $this->secondaryQueueHadJob && $index == 0; 

    [$job, $reserved] = $this->retrieveNextJob($prefixed, $block);Illuminate/Queue/RedisQueue.php

O worker só faz pop bloqueante na primeira fila da lista. O block_for dessa conexão estava em 3 segundos — o default do Laravel é null, que não bloqueia, então é um valor que alguém escolheu:

'redis' => [
    'driver' => 'redis',
    'queue' => env('REDIS_QUEUE', 'default'),
    'retry_after' => 120,
    'block_for' => 3,
],config/queue.php

Toda iteração em que a workflow estivesse vazia gastaria até três segundos esperando por ela antes de sequer olhar a default. A fila com volume estava em segundo lugar. Era elegante, explicava o sintoma, e eu tinha como testar sem deploy: subi um processo extra dentro do pod que já rodava, consumindo uma fila só.

php artisan queue:work redis --queue=default --sleep=1 --tries=3 --timeout=60 --memory=192

A fila, que a essa altura já tinha subido para 3750, caiu a zero em poucos minutos e ficou oscilando entre zero e um. Mesmo pod, mesma imagem, mesmo código. A única diferença era a lista de filas. Considerei provado e escrevi assim.

O código-fonte que me desmentiu

A linha que eu destaquei acima tem uma parte que eu li e não processei: ! $this->secondaryQueueHadJob.

Esse flag é ligado quando um job é encontrado numa fila que não é a primeira, e o efeito dele é exatamente desligar o bloqueio na iteração seguinte:

if ($reserved) {
    if ($index > 0) {
        $this->secondaryQueueHadJob = true; 
    }

    return new RedisJob(/* ... */);
}Illuminate/Queue/RedisQueue.php

Traduzindo para o meu caso: o worker paga os três segundos uma vez. Achou job na segunda fila, a volta seguinte não bloqueia na primeira. Enquanto a default tivesse jobs — e ela tinha três mil — o worker rodaria solto. Com essa mitigação no lugar, a ordem das filas não produz o que eu vi.

E ela estava no lugar. Comparando o arquivo nos tags do framework, o flag não existe na v11.0.0 e existe desde a v12.0.0. A aplicação tinha subido para a 12 três semanas antes do incidente.

Então a armadilha da ordem das filas é real, está documentada desde 2019 no rastreador do framework — onde o relator descreve o caso extremo, com block_for em zero, de um worker que “will indefinitely block on the high queue, and the other queues will never be reached” — e continua valendo para quem roda a 11 ou anterior. Ela só não é o que aconteceu comigo.

O que sobrou de pé

Sem a ordem das filas, voltei para os números da janela. Eu tinha 166 segundos de log de saída do worker:

A capacidade existia de sobra: 9,2 contra 5,7. O worker só passava 70% do tempo sem concluir nada, e o reboot depois de cada SIGKILL custa três ou quatro segundos — não explica 112 segundos parados.

Dois jobs congelados, segurando o processo por até 60 segundos cada, fecham a conta. É a única leitura que eu achei compatível com os números, e continua sendo leitura. Um job travado não aparece como inatividade porque o worker esteja ocioso; aparece porque não há linha de conclusão para escrever.

O retry_after da conexão, de 120 segundos, piora o estrago sem ter culpa nele: o job morto no meio fica reservado no Redis até o prazo vencer. Com kill a cada 80 segundos e reentrega a cada 120, o processo passava mais tempo morrendo e reiniciando do que trabalhando.

É a mesma conclusão prática que a hipótese errada dava, por um caminho diferente, e é uma conclusão mais antiga que qualquer detalhe de implementação do Laravel: um processo que atende duas filas acopla a latência das duas. Não importa se quem monopoliza o consumidor é um blpop mal posicionado ou um job que travou numa conexão de rede. Enquanto uma fila de jobs de 20 milissegundos dividir processo com uma fila que pode congelar por um minuto, a primeira herda o pior caso da segunda.

O experimento da mitigação continua válido como prova — ele só provava outra coisa. Um worker dedicado à default é imune a um job que trava na workflow, e é por isso que a fila drenou.

A correção que derrubou dois ambientes

A correção foi apagar o .conf que listava duas filas e criar um arquivo por fila, cada um com --timeout e --memory explícitos. O sistema tem oito filas; o supervisor rodava 7 processos e passou a rodar 11, porque a default ficou com três e a broadcast com dois.

Cada queue:work custa cerca de 104 MB residentes. Eu tinha esse número. O que eu não fiz foi multiplicar por 11 antes de subir para os ambientes de homologação, que tinham limite de memória de 768 MB — o de produção era maior, e foi o de produção que eu olhei.

O supervisor subiu os 11 processos. O container morreu cerca de 85 segundos depois, por OOM de verdade dessa vez. E como agora todas as filas estavam naquele mesmo pod, o resultado foi pior do que o incidente original: nenhuma fila com consumidor, em dois ambientes, em CrashLoopBackOff.

Isolar filas é uma decisão de memória antes de ser uma decisão de configuração. O teto do pod tem que ficar acima de processos × ~110 MB, com folga para o limiar do --memory, que é gatilho de reinício e não reserva.

O teste que não testava nada

Ao cobrir a mudança com teste, escrevi a asserção óbvia: o evento não vai mais para a default. Ela passou. Passava também quando eu removia a propriedade que define a fila do evento — ou seja, não provava nada.

O motivo é que o job que embrulha um evento de broadcast chega ao fake com a propriedade de fila nula: a fila real é guardada à parte pelo próprio fake e entregue como segundo parâmetro do callback.

// passa sempre, inclusive com a propriedade removida do evento
Queue::assertNotPushed(BroadcastEvent::class, fn ($job) => $job->queue === 'default');

// olha o valor certo
Queue::assertNotPushed(
    BroadcastEvent::class,
    fn (BroadcastEvent $job, ?string $queue): bool => $queue === 'default'
);

Teste de roteamento de fila só vale provado por mutação: tire a propriedade do evento e confira que o teste quebra. Se ele continuar verde, ele nunca protegeu nada.

O que eu passei a fazer

A documentação do Laravel ensina justamente a passar a lista separada por vírgula — php artisan queue:work --queue=high,default — para processar uma fila antes da outra. O que essa recomendação pressupõe, sem dizer, é que as filas da lista tenham perfis de duração parecidos. Prioridade e isolamento são objetivos diferentes: a lista ordena o atendimento, e não impede que um job de uma fila segure o processo inteiro.

Fica uma quarta, que não é regra de fila. Eu tinha a linha do pop() na tela, destacada, e li só a metade que confirmava o que eu já achava. O flag que me desmentia estava na mesma expressão, dois tokens antes.

Um experimento que dá o resultado esperado é a hora mais fácil de parar de pensar. A fila zerou, o incidente fechou, e a explicação que eu anunciei estava errada mesmo com a correção certa. Se eu não tivesse voltado ao fonte para escrever isto, ela estaria até hoje documentada internamente como causa raiz — e o próximo a ler acreditaria, porque vinha com a fila zerando junto.