failed to list alerts... context canceled

[mfominov]

problem with 0.4.0 bot version

[metalmatze]

Could you please give some more details?
I suppose this is happening because the bot can't reach your Alertmanager.
The logs from this container would be interesting to see.

[mfominov]

all other commands works properly.

[mfominov]

maybe problem with alerts amount?

[metalmatze]

Maybe, yes. We should see that in the logs.

[mfominov]

thats strange, bot bot logging any command

[f4rx]

I have the same problem, and I getting absolutely nothing in debug logs

level=info ts=2019-02-28T14:33:19.530407946Z caller=main.go:218 component=telegram msg="starting alertmanager-bot" version=0.4.0 revision=3dfe88e1cf837e0cb6c568d8a412a2c9334c54df buildDate=2019-02-19T20:49:19+0000 goVersion=go1.11.5
level=info ts=2019-02-28T14:33:19.530617676Z caller=main.go:260 component=webserver msg="starting webserver" addr=0.0.0.0:8080
level=debug ts=2019-02-28T14:33:26.94652227Z caller=bot.go:213 component=telegram msg="message received" text=/alerts
level=debug ts=2019-02-28T14:33:30.68015425Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:33:30.682396107Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:33:37.305574415Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:33:37.310993373Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:33:46.083201345Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=debug ts=2019-02-28T14:34:42.597080385Z caller=bot.go:213 component=telegram msg="message received" text=/start
level=debug ts=2019-02-28T14:34:47.217632004Z caller=bot.go:213 component=telegram msg="message received" text=/start
level=debug ts=2019-02-28T14:34:48.529469783Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:34:48.534023702Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:34:50.385014085Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:34:50.387712596Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:34:54.719546961Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:34:54.723194213Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:34:57.739431983Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:34:57.742933804Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-02-28T14:35:00.260289882Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-02-28T14:35:00.26347428Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"

[pieter91]

I'm getting:

level=error ts=2019-05-20T15:24:17.685373068Z caller=bot.go:277 component=telegram msg="failed to get chat list from store" err="Key not found in store"

Is this related?

[metalmatze]

I'm getting:

level=error ts=2019-05-20T15:24:17.685373068Z caller=bot.go:277 component=telegram msg="failed to get chat list from store" err="Key not found in store"

Is this related?

Are you sure your user is subscribed? If not, it cannot be found in the data store.

[pieter91]

Yes, the user is definitely subscribed. I'm getting alerts, but I can't reliably use the /alerts command. It only works some of the time.

[metanovii]

+1 , but some time

[H0r0s]

I have the same problem, and I getting absolutely nothing in debug logs

Same Problem here when calling /status, but when i hit it again and again i get the status after several times.

[metalmatze]

Something needs to be in the logs. Can you try setting --log.level=debug and try once more? Thanks

[H0r0s]

level=debug ts=2019-08-14T15:50:49.253916512Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-08-14T15:50:49.258615528Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-08-14T15:50:51.656765693Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-08-14T15:50:51.66198168Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-08-14T15:50:53.518331525Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-08-14T15:50:53.523219185Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=debug ts=2019-08-14T15:50:54.435571873Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=debug ts=2019-08-14T15:51:00.626654797Z caller=bot.go:213 component=telegram msg="message received" text=/status
level=warn ts=2019-08-14T15:51:00.628721514Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"

the third last line was when i got the status correctly.

[metalmatze]

Hmm. Looks like you're running into timeouts? Sadly I don't log anything more verbose than context canceled.
We might want to increase the initial timeout for the backoff:

alertmanager-bot/pkg/alertmanager/retry.go

Line 16 in 254008d

b.InitialInterval = 200 * time.Millisecond

[H0r0s]

but the rest of it works just fine, i downloaded the linux-arm release and started with the following arguments:

/usr/local/bin/alertmanager-bot \
> --alertmanager.url=http://<ip of Alertmanager>:9093 \
> --listen.addr=0.0.0.0:8080 \
> --store=bolt \
> --bolt.path=/etc/alert_bot/bot.db \
> --telegram.admin=XXXX \
> --telegram.token=XXXX \
> --log.level=debug

maybe this will help you

[titansmc]

I am getting the same random behaviour, something like 1 out of 3/4 times works /status . I have increased the initialInterval to 2000 * time.Millisecond but still the same problem. Any hint where I should be looking at?

[titansmc]

After upgrading alertmanager and prometheus, it seems that the problem is gone, either with the official image or the one I built increasing the time out.

[titansmc]

but when running it towards SSL alertmanager it is unreliable:

Sometimes it works and some others it fails:

10:41 $ docker logs -f alertmanager-bot 
level=info ts=2019-11-08T09:41:36.963725188Z caller=main.go:218 component=telegram msg="starting alertmanager-bot" version= revision= buildDate=2019-11-08T09:28:43+0000 goVersion=go1.13
level=info ts=2019-11-08T09:41:36.963743873Z caller=main.go:260 component=webserver msg="starting webserver" addr=0.0.0.0:8080
level=warn ts=2019-11-08T09:41:43.223002345Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=warn ts=2019-11-08T09:41:47.394347456Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"
level=warn ts=2019-11-08T09:41:53.789223632Z caller=bot.go:364 component=telegram msg="failed to get status" err="context canceled"

[tazhate]

same bug for me :(

[optimistic5]

In logs I get

alertmanager-bot_1        | level=info ts=2019-12-17T12:49:09.110955295Z caller=main.go:260 component=webserver msg="starting webserver" addr=0.0.0.0:8080
alertmanager-bot_1        | level=info ts=2019-12-17T12:49:09.11093035Z caller=main.go:218 component=telegram msg="starting alertmanager-bot" version=0.4.0 revision=3dfe88e1cf837e0cb6c568d8a412a2c9334c54df buildDate=2019-02-19T20:49:19+0000 goVersion=go1.11.5
alertmanager-bot_1        | level=error ts=2019-12-17T12:49:46.347005498Z caller=bot.go:277 component=telegram msg="failed to get chat list from store" err="Key not found in store"

but it worked today.

I use the same code on different machine.
I have no problem on another instance.

alertmanager:
    image: prom/alertmanager
    container_name: alertmanager
    expose:
      - 9093
    volumes:
      - ./alertmanager/:/etc/alertmanager/
    restart: always
    command:
      - '--config.file=/etc/alertmanager/config.yml'
      - '--storage.path=/alertmanager'

  alertmanager-bot:
    image: metalmatze/alertmanager-bot
    environment:
        - ALERTMANAGER_URL=http://alertmanager:9093
        - LISTEN_ADDR=0.0.0.0:8080
        - BOLT_PATH=/data/bot.db
        - STORE=bolt
        - TELEGRAM_ADMIN=xxx
        - TELEGRAM_TOKEN=xxx
        - TEMPLATE_PATHS=/templates/default.tmpl
    volumes:
        - /srv/monitoring/alertmanager-bot:/data
    expose:
        - 8080

[owodunni]

Edit: I am back to msg="failed to get status" err="context canceled". It only worked one time.. However I have never manager to get it working without the workaround bellow..
Edit 2: I ran docker-compose up -d and now /status feels stable..

I had the same issue. I think I found the problem. I am also using docker-compose. When trying a similar configuration as @optimistic5 I get the issue. But if I switch to:

alertmanager-bot:
    image: metalmatze/alertmanager-bot:0.4.2
    command:
    - --log.level=info
    - --store=bolt
    - --bolt.path=/data/bot.db
    environment:
      ALERTMANAGER_URL: http://192.168.1.220:9093 # External ip of alertmanager
      TELEGRAM_ADMIN: xxx
      TELEGRAM_TOKEN: xxx
    volumes:
    - alertmanager-bot-data:/data

Then /status works fine. which it didn't before.

I think the issue is how to setup networking so that alertmanager-bot can reach the alertmanager inside the cluster. Any suggestions?

[metalmatze]

I think the issue is how to setup networking so that alertmanager-bot can reach the alertmanager inside the cluster. Any suggestions?

Yes, exactly. For these commands to work, the bot needs to be able to successfully make HTTP requests against alertmanager.

[aksenk]

+1. The same problems occur periodically.

For example now /silences and other commands works fine, but /alerts say: "failed to list alerts... context canceled". And it worked just recently.

Exec to the container and check connectivity works fine:

kubectl exec -ti -n monitoring  alertmanager-bot-0 -- sh
curl http://prometheus-operator-alertmanager:9093/api/v1/alerts

[metalmatze]

Is that a continous problem? If just one of these fails then that's totally normal. Network is reliable.

[aksenk]

Is that a continous problem? If just one of these fails then that's totally normal. Network is reliable.

2-3 successful requests from 20 attempts, the rest with an error "failed to list alerts... context canceled"

/silences there are also errors here, but now all requests have been successful.

[metalmatze]

What do you see in the logs of the bot and alertmanager while that happens?

[aksenk]

What do you see in the logs of the bot and alertmanager while that happens?

Practically nothing...

level=debug ts=2020-07-02T14:02:38.579104419Z caller=bot.go:213 component=telegram msg="message received" text=/alerts
In alertmanager-bot logs and nothing in alertmanager logs

[aksenk]

I don't know if this information will help you, but I noticed this fact: I look at traffic up to alertmanager - the bot always gets the correct json with alerts.

Here are 2 screenshots of traffic when requesting /alerts:

The first is when the error occurs "failed to list alerts... context canceled".

The second is when the bot gives a correct response.

[hamiteza]

same bug for me :(

[bazuchan]

Same bug, no solution yet? Why issue was closed?