Can not run "daemon run": timed out while waiting for state ready_for_test error

[wynxel]

Hello,

I need to containerize logstash tests for the sake of CI. Since the v2 has interesting features (mocks, export_outputs..) I am trying to get the daemon setup working. As @oneingan pointed in issue-183, this can be achieved using sh entrypoint. I am now trying to get the minimal demo example working, but stuck now on some internal state timeout issue. The error says:

logstash-filter-verifier: error: failed to teardown connection: rpc error: code = Unknown desc = destroy of session failed: no valid session found for id "iSKA6MGJ", root cause: rpc error: code = Unknown desc = timed out while waiting for state: ready_for_test

The logstash configuration and test file is basic pipeline example and basic test example.

Demo example:

.
├── conf.d
│   └── logstash.conf
├── Dockerfile
├── entrypoint.sh
├── Makefile
└── testcases
    └── test.json

Can be build using: docker build -t validator-demo -f Dockerfile . Can be run using: docker run --rm -it --name validator-demo-container -v ./conf.d:/test/conf.d:ro -v ./testcases:/test/testcases:ro validator-demo

Entrypoint:

#!/bin/bash

TMPDIR=$(mktemp -d)

./logstash-filter-verifier daemon start \
  --socket "$TMPDIR"/logstash-filter-verifier.sock \
  --logstash-path /usr/share/logstash/bin/logstash \
  --loglevel DEBUG --keep-env PATH \
  --wait-for-state-timeout 120s &

sleep 10

echo "[ENTRYPOINT]: Launching tests"

./logstash-filter-verifier daemon run --logstash-config /test/conf.d \
  --testcase-dir /test/testcases --socket "$TMPDIR"/logstash-filter-verifier.sock \
  --add-missing-id --loglevel DEBUG

sleep 2

./logstash-filter-verifier daemon shutdown --socket "$TMPDIR"/logstash-filter-verifier.sock

rm -rf "$TMPDIR"

Dockerfile:

# Build logstash-filter-verifier for pipeline unit testing:
FROM golang:1.22 as logstash-verifier
RUN go version

# Copy files
WORKDIR /build
ENV REPO "https://github.com/magnusbaeck/logstash-filter-verifier.git"
RUN git clone $REPO /build

ENV VERSION "v2.0.0-beta.2"
RUN git checkout $VERSION

# Build logstash-filter-verifier
RUN go build

# Run tests:
FROM debian:12.5-slim

RUN apt-get update \
    && apt-get install -y apt-transport-https gnupg2 xz-utils wget \
    && apt-get clean

# Install Logstash
ENV LOGSTASH_BIN logstash-8.8.2-amd64.deb
RUN wget https://artifacts.elastic.co/downloads/logstash/$LOGSTASH_BIN -O $LOGSTASH_BIN
RUN dpkg -i $LOGSTASH_BIN
RUN rm $LOGSTASH_BIN

ENV WORKDIR /test
WORKDIR $WORKDIR
COPY --from=logstash-verifier /build/logstash-filter-verifier $WORKDIR/logstash-filter-verifier

COPY ./entrypoint.sh /usr/local/bin/entrypoint.sh
RUN chmod +x /usr/local/bin/entrypoint.sh

ENTRYPOINT ["/usr/local/bin/entrypoint.sh"]

See here the whole output from the container

``` ❯ make run docker run --rm -it --name validator-demo-container \ -v ./conf.d:/test/conf.d:ro \ -v ./testcases:/test/testcases:ro \ validator-demo config: socket: /tmp/tmp.1R84opUvp6/logstash-filter-verifier.sock config: logstash-path: /usr/share/logstash/bin/logstash Temporary directory for daemon created in "/tmp/lfv-1654176308" state change: "created" -> "started" by "start" start stdout scanner Waiting for /tmp/lfv-1654176308/logstash-instance/nTfk5zsE/logstash.log to appear... start stderr scanner Daemon listening on /tmp/tmp.1R84opUvp6/logstash-filter-verifier.sock stdout: Using bundled JDK: /usr/share/logstash/jdk [ENTRYPOINT]: Launching tests Reading test case file: /test/testcases/test.json (/test/testcases/test.json) Current TestCaseSet after converting fields: {File: InputPlugin:stdin Codec:line IgnoredFields:[@timestamp @version event] InputFields:map[type:syslog] InputLines:[test case message test case message 2] ExpectedEvents:[map[message:test case message tags:[main2_passed sut_passed] type:syslog] map[message:test case message 2 tags:[main2_passed sut_passed] type:syslog]] ExportMetadata:false ExportOutputs:false TestCases:[{InputLines:[test case message test case message 2] InputFields:map[] ExpectedEvents:[map[message:test case message tags:[main2_passed sut_passed] type:syslog] map[message:test case message 2 tags:[main2_passed sut_passed] type:syslog]] Description:}] Events:[map[type:syslog] map[type:syslog]] descriptions:[ ]} socket to daemon "/tmp/tmp.1R84opUvp6/logstash-filter-verifier.sock" waitForState: ready stdout: Sending Logstash logs to /tmp/lfv-1654176308/logstash-instance/nTfk5zsE which is now configured via log4j2.properties taillog: -> pipeline started: output taillog: -> pipeline started: stdin taillog: -> pipeline running: [output stdin] Ready to process tests state change: "started" -> "ready" by "pipeline-ready" state change: "ready" -> "setting_up_test" by "setup-test" waitForState: ready_for_test taillog: -> pipeline started: lfv_output_stdout taillog: -> pipeline running: [output stdin lfv_output_stdout] state change: "unknown" because of waitForState timeout waitForState: ready_for_test logstash-filter-verifier: error: failed to teardown connection: rpc error: code = Unknown desc = destroy of session failed: no valid session found for id "iSKA6MGJ", root cause: rpc error: code = Unknown desc = timed out while waiting for state: ready_for_test state change: "created" -> "started" by "start" start stderr scanner Waiting for /tmp/lfv-1654176308/logstash-instance/KR7VR0vU/logstash.log to appear... start stdout scanner stdout: Using bundled JDK: /usr/share/logstash/jdk Shutdown initiated. broadcast shutdown for waitForState shutdown log reader shutdown log reader broadcast shutdown for waitForState ```

test.zip

Would anyone have an idea what is wrong? :pray:

[jgough]

I seem to remember I had issues with running a similar script when sending the daemon to the background with &

In the end I got things working in gitlab ci by launching a docker container containing the daemon and then using docker exec to run the tests inside that container.

Something like this:

script:
  - docker run --rm -d --name lfv-daemon my-image logstash-filter-verifier daemon start --wait-for-state-timeout 120s --no-cleanup
  - sleep 10
  - docker exec lfv-daemon logstash-filter-verifier daemon run --pipeline /usr/share/logstash/config/pipelines.yml --pipeline-base /usr/share/logstash/ --testcase-dir /usr/share/logstash/tests/
after_script:
  - docker rm --force lfv-daemon

[breml]

Hi @wynxel, just to be sure, the same configuration (your version of LFV, Logstash, Logstash config and test cases) does work on your machine, but just not inside docker / CI, correct?

[wynxel]

Hi @breml and thank you for the reply! I have not tested this on local machine (in my setup this will not be the use case). I was, however, able to get the standalone version working without any hitch. Does this help? Is the containerized code working for you, or you are experiencing the same issue as I am?

@jgough thank you for the suggestion, I would like to first verify whether running everything inside docker works. If not then I would consider running it in two steps, as you proposed.

[breml]

@wynxel I have not tested it myself.

[Pix3lSt0rm]

I'm seeing a similar issue (Using docker desktop on Windows 10 running linux containers), logstash v8.14.1, lfv v2.0.0-beta.2. The problem is the same whether using & to background the daemon or using a separate shell via docker exec. Used a slightly modified version of Dockerfile from here: https://github.com/megah3rtz/logstash-filter-verifier-docker

I downgraded to logstash 8.0.1 but the problem still manifests.

This was the Dockerfile change to force downgrade. RUN apt-get update -y && apt-get install logstash=1:8.0.1-1 -y --no-install-recommends && apt-get clean && rm -rf /var/lib/apt/