search

AsamK / signal-cli

signal-cli provides an unofficial commandline, JSON-RPC and dbus interface for the Signal messenger.
GNU General Public License v3.0
3.19k stars 301 forks source link

Unable to create v2 groups despite profile being set #1410

Closed marsavar closed 9 months ago

marsavar commented 9 months ago

I'm running signal-cli in a Docker container.

I'm trying to create a group chat that includes the account signal-cli is registered with (let's call it account A) and my personal Signal number (account B), which I have done successfully before. I'm driving signal-cli with a Rust JSON-RPC client. However, I'm getting this warning:

INFO  DaemonCommand - Starting daemon in multi-account mode
INFO  IOUtils - Listening on socket: /0.0.0.0:7583
INFO  DaemonCommand - Accepted new client connection 0: /10.42.0.58:32994 null
WARN  GroupV2Helper - Cannot create a V2 group as self does not have a versioned profile

After doing some research, it looks like a profile needs to exist in order for the account to join a group, so I've run

./signal-cli -a <REDACTED> updateProfile --name Test --avatar /path/to/avatar.png --about "Test message"

In Signal Desktop, I can see that the command worked as the new info appears as expected (about message, new avatar, etc). However, the signal-cli account is still unable to create new groups, as I keep getting the same WARN message about the lack of a versioned profile.

Any pointers on how to debug this further? Thank you very much and happy new year.

AsamK commented 9 months ago

Are you using the latest version 0.12.7? If yes, a verbose log (with -v) would be helpful.

marsavar commented 9 months ago

Using 0.12.4 at the moment. Here are the logs:

2024-01-02T15:30:53.689Z [main] DEBUG org.asamk.signal.util.IOUtils - XDG_RUNTIME_DIR not set, falling back to temp dir
2024-01-02T15:30:53.696Z [main] DEBUG org.asamk.signal.App - Starting signal-cli 0.12.4
2024-01-02T15:30:53.910Z [main] INFO  LibSignal - [libsignal]: rust/bridge/jni/src/logging.rs:158: Initializing libsignal version:0.32.1
2024-01-02T15:30:53.911Z [main] DEBUG org.asamk.signal.util.IOUtils - XDG_DATA_HOME not set, falling back to home dir
2024-01-02T15:30:54.027Z [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2024-01-02T15:30:54.118Z [main] INFO  com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@47f4e407
2024-01-02T15:30:54.119Z [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2024-01-02T15:30:55.547Z [main] INFO  o.a.signal.commands.DaemonCommand - Starting daemon in multi-account mode
2024-01-02T15:30:55.556Z [main] INFO  org.asamk.signal.util.IOUtils - Listening on socket: /0.0.0.0:7583
2024-01-02T15:33:30.521Z [daemon-listener] INFO  o.a.signal.commands.DaemonCommand - Accepted new client connection 0: /10.42.0.58:45550 null
2024-01-02T15:33:31.119Z [pool-2-thread-1] DEBUG o.asamk.signal.jsonrpc.JsonRpcReader - Received json rpc request, method: subscribeReceive
2024-01-02T15:33:31.122Z [receive-0] DEBUG o.a.s.manager.internal.ManagerImpl - Starting receiving messages
2024-01-02T15:33:31.145Z [receive-0] INFO  LibSignal - [WebSocketConnection]: [normal:148897314] connect()
2024-01-02T15:33:31.151Z [receive-0] INFO  LibSignal - [WebSocketConnection]: [unidentified:869929731] connect()
2024-01-02T15:33:31.155Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-01-02T15:33:31.158Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-01-02T15:33:31.484Z [OkHttp https://chat.signal.org/...] INFO  LibSignal - [WebSocketConnection]: [unidentified:869929731] onOpen() connected
2024-01-02T15:33:31.484Z [RxComputationThreadPool-4] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-01-02T15:33:31.485Z [OkHttp https://chat.signal.org/...] INFO  LibSignal - [WebSocketConnection]: [normal:148897314] onOpen() connected
2024-01-02T15:33:31.485Z [RxComputationThreadPool-5] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-01-02T15:33:31.501Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Received indicator that server queue is empty
2024-01-02T15:33:31.501Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-01-02T15:33:31.501Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-01-02T15:34:01.490Z [Thread-3] INFO  LibSignal - [WebSocketConnection]: [normal:148897314] Sending keep alive...

### SNIP (lots of checking for new message from server / sending keep alive) ###

2024-01-02T15:38:31.525Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-01-02T15:38:33.290Z [pool-2-thread-2] DEBUG o.asamk.signal.jsonrpc.JsonRpcReader - Received json rpc request, method: updateGroup
2024-01-02T15:38:33.313Z [pool-2-thread-2] WARN  LibSignal - [PhoneNumberFormatter]: Got local CC: GB
2024-01-02T15:38:33.336Z [pool-2-thread-2] DEBUG org.asamk.signal.manager.util.Utils - Invalid locale 'en', using fallback: en_US

## Warning here ###

2024-01-02T15:38:33.457Z [pool-2-thread-2] WARN  o.a.s.manager.helper.GroupV2Helper - Cannot create a V2 group as self does not have a versioned profile
2024-01-02T15:38:33.502Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Need to do 1 legacy sends.
2024-01-02T15:38:33.774Z [pool-2-thread-2] DEBUG org.asamk.signal.manager.util.Utils - Invalid locale 'en', using fallback: en_US
2024-01-02T15:38:34.083Z [pool-2-thread-2] WARN  LibSignal - [DigestingRequestBody]: Content uploaded -53 bytes compared to expected!
2024-01-02T15:38:34.590Z [pool-1-thread-1] INFO  LibSignal - [libsignal]: rust/protocol/src/session_cipher.rs:73: Building PreKeyWhisperMessage for: ********-94cb-425f-a6ca-b18ac7093b77.9 with preKeyId: <none>
2024-01-02T15:38:34.791Z [pool-1-thread-1] WARN  LibSignal - [SignalServiceMessageSender]: [sendMessage][1704209913473] Handling mismatched devices. (StatusCode: 409)
2024-01-02T15:38:34.797Z [pool-1-thread-1] WARN  LibSignal - [SignalServiceMessageSender]: [handleMismatchedDevices] Address: ********-94cb-425f-a6ca-b18ac7093b77, ExtraDevices: [9], MissingDevices: []
2024-01-02T15:38:34.938Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Successfully sent using 1:1 to 1/1 legacy targets.
2024-01-02T15:38:34.939Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Sending took PT1.437S
2024-01-02T15:38:34.947Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Need to do 1 legacy sends.
2024-01-02T15:38:35.037Z [pool-2-thread-2] WARN  LibSignal - [DigestingRequestBody]: Content uploaded -53 bytes compared to expected!
2024-01-02T15:38:35.554Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Successfully sent using 1:1 to 1/1 legacy targets.
2024-01-02T15:38:35.554Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Sending took PT0.607S
2024-01-02T15:38:35.564Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Need to do 1 legacy sends.
2024-01-02T15:38:35.602Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-01-02T15:38:35.606Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-01-02T15:38:35.608Z [receive-0] INFO  LibSignal - [libsignal]: rust/protocol/src/sealed_sender.rs:432: deserialized UnidentifiedSenderMessageContent from 010a8f51-94cb-425f-a6ca-b18ac7093b77.7 with type Whisper
2024-01-02T15:38:35.609Z [receive-0] INFO  LibSignal - [libsignal]: rust/protocol/src/session_cipher.rs:654: ********-94cb-425f-a6ca-b18ac7093b77.7 creating new chains.
2024-01-02T15:38:35.609Z [receive-0] INFO  LibSignal - [libsignal]: rust/protocol/src/state/session.rs:293: Trimming excessive receiver_chain for session with base key ********d4d6d83bcdc5123ec936101db611cc74495a97fb29b1c0ee770a467d, chain count: 6
2024-01-02T15:38:35.609Z [receive-0] INFO  LibSignal - [libsignal]: rust/protocol/src/session_cipher.rs:452: decrypted Whisper message from ********-94cb-425f-a6ca-b18ac7093b77.7 with current session state (base key ********4c494df6ea789d332ed90e4ac1800cc07a24f11db4951b56c72fce60)
2024-01-02T15:38:35.681Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Successfully sent using 1:1 to 1/1 legacy targets.
2024-01-02T15:38:35.682Z [pool-2-thread-2] DEBUG o.a.signal.manager.helper.SendHelper - Sending took PT0.118S
{"envelope":{"source":"REDACTED,"sourceNumber":"REDACTED","sourceUuid":"********-94cb-425f-a6ca-b18ac7093b77","sourceName":"REDACTED","sourceDevice":7,"timestamp":1704209915357,"receiptMessage":{"when":1704209915357,"isDelivery":true,"isRead":false,"isViewed":false,"timestamps":[1704209913473]}},"account":"REDACTED"}
2024-01-02T15:38:35.686Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-01-02T15:38:35.686Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server

I should also point out that, even though the warning says a group chat cannot be created, the JSON-RPC response that I get from the updateGroup request does include a group chat id, which seems to contradict the warning.

AsamK commented 9 months ago

Thanks, then this should be fixed in 0.12.5 (same root cause as #1362)

It falls back to creating a v1 group, which however is not supported by the Signal-Android client anymore...