Bot never checks for messages

[btxshark1]

Running into a weird issue here and I'm not sure where to start troubleshooting...
I've been running this setup for about a year now without issue but earlier today I noticed the bot wasn't responding to messages, both containers were alive and healthy.
I can see the bot checking for groups on startup, but it never goes further.

Debug logging shows a normal startup and then.... nothing. After a few minutes it prints a PING/PONG 0 bytes but none of the normal raw envelope messages.

I can send messages with postman so I think the signal api is working as intended

Starting the bot without registering any commands shows the same behavior. Same goes for running the example/bot.py

Watchtower does keep the container images fresh and both signalbot and the api updated recently though I didn't notice any different pulling and running the previous versions.

Normally after an update breaking something there's noise in the logs (and other users opening issues) but I can't find the smoking gun here.
Any help would be greatly appreciated!

signal-cli-rest-api logs:

+ set -e
+ [ -z /home/.local/share/signal-cli ]
+ usermod -u 1000 signal-api
usermod: no changes
+ groupmod -g 1000 signal-api
+ chown 1000:1000 -R /home/.local/share/signal-cli
+ cat
+ cap_prefix=-cap_
+ cat /proc/sys/kernel/cap_last_cap
+ seq -s ,-cap_ 0 40
+ caps=-cap_0,-cap_1,-cap_2,-cap_3,-cap_4,-cap_5,-cap_6,-cap_7,-cap_8,-cap_9,-cap_10,-cap_11,-cap_12,-cap_13,-cap_14,-cap_15,-cap_16,-cap_17,-cap_18,-cap_19,-cap_20,-cap_21,-cap_22,-cap_23,-cap_24,-cap_25,-cap_26,-cap_27,-cap_28,-cap_29,-cap_30,-cap_31,-cap_32,-cap_33,-cap_34,-cap_35,-cap_36,-cap_37,-cap_38,-cap_39,-cap_40
+ [ json-rpc = json-rpc ]
+ /usr/bin/jsonrpc2-helper
time="2024-08-06T03:11:16Z" level=info msg="Updated jsonrpc2.yml"
+ [ -n  ]
+ service supervisor start
Starting supervisor: supervisord.
+ supervisorctl start all
+ hostname+  -I
awk {print $1}
+ export HOST_IP=172.17.0.2
+ exec setpriv --reuid=1000 --regid=1000 --init-groups --inh-caps=-cap_0,-cap_1,-cap_2,-cap_3,-cap_4,-cap_5,-cap_6,-cap_7,-cap_8,-cap_9,-cap_10,-cap_11,-cap_12,-cap_13,-cap_14,-cap_15,-cap_16,-cap_17,-cap_18,-cap_19,-cap_20,-cap_21,-cap_22,-cap_23,-cap_24,-cap_25,-cap_26,-cap_27,-cap_28,-cap_29,-cap_30,-cap_31,-cap_32,-cap_33,-cap_34,-cap_35,-cap_36,-cap_37,-cap_38,-cap_39,-cap_40 signal-cli-rest-api -signal-cli-config=/home/.local/share/signal-cli
time="2024-08-06T03:11:18Z" level=info msg="Started Signal Messenger REST API"
[GIN] 2024/08/06 - 03:11:26 | 200 |     98.8465ms |      172.17.0.1 | GET      "/v1/groups/+<botsPhoneNumber>"

bot logs:

WARNING:root:[Bot] Could not initialize Redis. In-memory storage will be used. Restarting will delete the storage!
INFO:apscheduler.scheduler:Scheduler started
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:root:[Bot] Producer #1 started
INFO:root:[Bot] Consumer #1 started
INFO:root:[Bot] Consumer #2 started
INFO:root:[Bot] Consumer #3 started
DEBUG:websockets.client:= connection is CONNECTING
DEBUG:websockets.client:> GET /v1/receive/<botPhoneNumber> HTTP/1.1
DEBUG:websockets.client:> Host: localhost:6969
DEBUG:websockets.client:> Upgrade: websocket
DEBUG:websockets.client:> Connection: Upgrade
DEBUG:websockets.client:> Sec-WebSocket-Key: vET2ypOOy/uuA6k4wCeJBg==
DEBUG:websockets.client:> Sec-WebSocket-Version: 13
DEBUG:websockets.client:> Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
DEBUG:websockets.client:> User-Agent: Python/3.12 websockets/10.4
DEBUG:websockets.client:< HTTP/1.1 101 Switching Protocols
DEBUG:websockets.client:< Upgrade: websocket
DEBUG:websockets.client:< Connection: Upgrade
DEBUG:websockets.client:< Sec-WebSocket-Accept: 93qdbmnHAZchEXEuJswf97uvMs8=
DEBUG:websockets.client:= connection is OPEN
INFO:root:[Bot] 2 groups detected
DEBUG:websockets.client:< PING '' [0 bytes]
DEBUG:websockets.client:> PONG '' [0 bytes]

docker-compose:

---
services:
  sigBot-backend:
    container_name: sigBot-backend
    userns_mode: "host"
    image: bbernhard/signal-cli-rest-api
    networks:
      - net
    labels:
      - 'traefik.enable=false'
    environment:
      - TZ=America/Eastern
      - MODE=json-rpc
    volumes:
      - /opt/sigBot/signal-cli:/home/.local/share/signal-cli
    expose:
      - 8080
    restart: unless-stopped

  sigBot:
    container_name: sigBot
    image: python:3
    networks:
      - net
    labels:
      - 'traefik.enable=false'
    environment:
      - TZ=America/Eastern
    command: "sh -c 'cd /opt/repo && pip install -r requirements.txt && python3 bot.py'"
    volumes:
      - /opt/sigBot/repo:/opt/repo
      - /root/.ssh:/root/.ssh
    restart: unless-stopped

bot.py

import sys, os
from signalbot import SignalBot
import commands
import logging

from production import config

logging.getLogger().setLevel(logging.DEBUG)
logging.getLogger("apscheduler").setLevel(logging.DEBUG)


def main():
  bot = SignalBot(config)

  for command in commands.commands:
    bot.register(getattr(commands, command)(), groups=[config['group_id'], config['playground_group_id']], contacts=False)

  bot.start()


if __name__ == "__main__":
  try:
    sys.exit(main())
  except KeyboardInterrupt:
    try:
      print("exiting...")
    except:
      pass

[filipre]

On first sight, your code looks fine and it seems like it is connecting fine to the REST API due to INFO:root:[Bot] 2 groups detected. My best bet would be that bot.register has an issue. Either you are passing the wrong inputs or there is a bug in the code. Just for debugging, could you try to set groups=True and contacts=True to listen in every chat? Also, are you sure bot.register is called at all? This issue makes me aware to add more logging on my side so debugging becomes a bit easier.

[btxshark1]

Trying to add simplicity, running the example/bot.py with the extras stripped out.

import os
from signalbot import SignalBot
from commands import PingCommand
import logging

logging.getLogger().setLevel(logging.DEBUG)
logging.getLogger("apscheduler").setLevel(logging.DEBUG)

def main():
    signal_service = os.environ["SIGNAL_SERVICE"]
    phone_number = os.environ["PHONE_NUMBER"]

    config = {
        "signal_service": signal_service,
        "phone_number": phone_number,
        "storage": None,
    }
    bot = SignalBot(config)

    # enable a chat command for all contacts and all groups
    bot.register(PingCommand(), contacts=True, groups=True)

    bot.start()

if __name__ == "__main__":
    main()

Same behavior.

Something I didn't notice yesterday is that when running interactive, sending ctrl+c causes a call to /v1/receive before it exits

[GIN] 2024/08/06 - 20:58:48 | 200 |   86.952212ms |      172.17.0.1 | GET      "/v1/groups/<botNumber>"
[GIN] 2024/08/06 - 20:58:57 | 200 |   8.85725689s |      172.17.0.1 | GET      "/v1/receive/<botNumber>"

I tried adding a canary to the PingCommand

from signalbot import Command, Context
class PingCommand(Command):
    def setup(self):
      print("PingCommand setup() called")

    def describe(self) -> str:
        return "🏓 Ping Command: Listen for a ping"

    async def handle(self, c: Context):
        command = c.message.text

        if command == "ping":
            await c.send("pong")
            return

But it don't see it in the output while the bot starts.
Edit its there I just can't read. So bot.register IS working

randal@homebox ~/repos/signalbot/example master
> python3 bot.py 
WARNING:root:[Bot] Could not initialize Redis. In-memory storage will be used. Restarting will delete the storage!
PingCommand setup() called
INFO:apscheduler.scheduler:Scheduler started
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:root:[Bot] Producer #1 started
INFO:root:[Bot] Consumer #1 started
INFO:root:[Bot] Consumer #2 started
INFO:root:[Bot] Consumer #3 started
DEBUG:websockets.client:= connection is CONNECTING
DEBUG:websockets.client:> GET /v1/receive/<botNumber> HTTP/1.1
DEBUG:websockets.client:> Host: localhost:6969
DEBUG:websockets.client:> Upgrade: websocket
DEBUG:websockets.client:> Connection: Upgrade
DEBUG:websockets.client:> Sec-WebSocket-Key: Yrdg+3BlWLHTVsiPHxFMEg==
DEBUG:websockets.client:> Sec-WebSocket-Version: 13
DEBUG:websockets.client:> Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
DEBUG:websockets.client:> User-Agent: Python/3.12 websockets/10.4
DEBUG:websockets.client:< HTTP/1.1 101 Switching Protocols
DEBUG:websockets.client:< Upgrade: websocket
DEBUG:websockets.client:< Connection: Upgrade
DEBUG:websockets.client:< Sec-WebSocket-Accept: rzV0gI2jDNkflvA2hAcLE3kd2iU=
DEBUG:websockets.client:= connection is OPEN
INFO:root:[Bot] 2 groups detected

However, this

DEBUG:websockets.client:> GET /v1/receive/ HTTP/1.1

is not reflected in the api container log...? The only hit I see to receive is after KeyboardInterrupt
Maybe thats the call thats getting stuck?

DEBUG:websockets.client:< PING '' [0 bytes]
DEBUG:websockets.client:> PONG '' [0 bytes]
^C^CTraceback (most recent call last):
  File "/home/randal/repos/signalbot/example/bot.py", line 26, in <module>
    main()
  File "/root/repos/signalbot/example/bot.py", line 23, in main
    bot.start()
  File "/usr/local/lib/python3.12/site-packages/signalbot/bot.py", line 172, in start
    self._event_loop.run_forever()
  File "/usr/lib64/python3.12/asyncio/base_events.py", line 641, in run_forever
    self._run_once()
  File "/usr/lib64/python3.12/asyncio/base_events.py", line 1949, in _run_once
    event_list = self._selector.select(timeout)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/selectors.py", line 468, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
KeyboardInterrupt

If I connect postman to the v1/receive /<botNumber> websocket it looks good, but I don't know what to send in order to get useful data back from it.
In native mode I can see new messages and mark them read.

[btxshark1]

It was an issue with the cli in json-rpc mode fixed in upstream bbernhard/signal-cli-rest-api#572