search

isamert / scli

a simple terminal user interface for signal messenger (using signal-cli)
GNU General Public License v3.0
439 stars 40 forks source link

Crash on startup: list index out of range #137

Closed cycneuramus closed 2 years ago

cycneuramus commented 2 years ago

Hi,

Today I updated Signal on my phone (version 5.23.7), and now I'm getting the following crash when starting scli. It occurs once the signal-cli daemon has been started:

Traceback (most recent call last):
  File "/usr/bin/scli", line 4438, in <module>
    main()
  File "/usr/bin/scli", line 4432, in main
    loop.run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 287, in run
    self._run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 385, in _run
    self.event_loop.run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 790, in run
    self._loop()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 827, in _loop
    self._watch_files[fd]()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 233, in cb
    rval = callback(data)
  File "/usr/bin/scli", line 520, in watchpipe_handler
    callback(proc, *callback_args, **callback_kwargs)
  File "/usr/bin/scli", line 798, in proc_callback
    name = proc.output.split('\n')[1][11:-1]   # Ad-hoc parsing of `dbus-send` output
IndexError: list index out of range

I don't know if this has to do with the new version of Signal or not; either way, it's probably an issue with signal-cli, but I figured I'd report it anyway.

exquo commented 2 years ago

Thank you for reporting this!

Could you please try the hotfix/137 branch, running scli with debug output 

scli --debug

and pasting here the output of the log file (in ~/.local/share/scli/log by default). (You can change the personal info such as your phone number and the group's name)

cycneuramus commented 2 years ago

Sure thing. The log output is attached below (with phone numbers and group names redacted). I also tried clearing all data from signal-cli and scli and re-linking, but the issue persists.

INFO:root:scli ?
DEBUG:root:signal-cli account: linked device
WARNING:root:Could not open v2 group cache file
    group_id = 5M/tXbYhXZUDIrVkpPqcNrQMbd1A1jNFyVr+1fULQxI=
    filepath = /home/user/.local/share/signal-cli/data/+00000000000.d/group-cache/5M_tXbYhXZUDIrVkpPqcNrQMbd1A1jNFyVr+1fULQxI=
WARNING:root:Could not open v2 group cache file
    group_id = 5M/tXbYhXZUDIrVkpPqcNrQMbd1A1jNFyVr+1fULQxI=
    filepath = /home/user/.local/share/signal-cli/data/+00000000000.d/group-cache/e4cfed5db6215d950322b564a4fa9c36b40c6ddd40d63345c95afed5f50b4312
WARNING:root:Could not open v2 group cache file
    group_id = 9bFmVdGrgksgnRUY6rV53gbm+y7wuLWuR0cKaEy5otc=
    filepath = /home/user/.local/share/signal-cli/data/+00000000000.d/group-cache/9bFmVdGrgksgnRUY6rV53gbm+y7wuLWuR0cKaEy5otc=
WARNING:root:Could not open v2 group cache file
    group_id = 9bFmVdGrgksgnRUY6rV53gbm+y7wuLWuR0cKaEy5otc=
    filepath = /home/user/.local/share/signal-cli/data/+00000000000.d/group-cache/f5b16655d1ab824b209d1518eab579de06e6fb2ef0b8b5ae47470a684cb9a2d7
DEBUG:root:callf: `['signal-cli', '-u', '+00000000000', '--output=json', 'daemon']`
INFO:root:daemon_log: INFO DaemonCommand - Exported dbus object: /org/asamk/Signal
INFO:root:signal-cli dbus service started
DEBUG:root:method return time=1631867636.522647 sender=:1.325 -> destination=:1.327 serial=6 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.521948 sender=:1.325 -> destination=:1.329 serial=5 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.522696 sender=:1.325 -> destination=:1.331 serial=7 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.524323 sender=:1.325 -> destination=:1.333 serial=8 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.532603 sender=:1.325 -> destination=:1.335 serial=13 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.532953 sender=:1.325 -> destination=:1.337 serial=14 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.533587 sender=:1.325 -> destination=:1.339 serial=15 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.533846 sender=:1.325 -> destination=:1.341 serial=17 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.535925 sender=:1.325 -> destination=:1.343 serial=21 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.537145 sender=:1.325 -> destination=:1.345 serial=22 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.541650 sender=:1.325 -> destination=:1.347 serial=25 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.555970 sender=:1.325 -> destination=:1.349 serial=27 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.564968 sender=:1.325 -> destination=:1.351 serial=29 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.589158 sender=:1.325 -> destination=:1.355 serial=31 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.602053 sender=:1.325 -> destination=:1.357 serial=33 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.611818 sender=:1.325 -> destination=:1.359 serial=35 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.624020 sender=:1.325 -> destination=:1.361 serial=37 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.632621 sender=:1.325 -> destination=:1.363 serial=39 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.643364 sender=:1.325 -> destination=:1.365 serial=41 reply_serial=2
   string "groupname"
DEBUG:root:method return time=1631867636.658195 sender=:1.325 -> destination=:1.367 serial=43 reply_serial=2
   string "groupname"
INFO:root:daemon_log: WARN GroupV2Helper - Failed to retrieve Group V2 info, ignoring: StatusCode: 403
INFO:root:signal-cli 0.9.0
ERROR:root:proc: cmd:`dbus-send --session --type=method_call --print-reply --dest=org.asamk.Signal /org/asamk/Signal org.asamk.Signal.getGroupName array:byte:228,207,237,93,182,33,93,149,3,34,181,100,164,250,156,54,180,12,109,221,64,214,51,69,201,90,254,213,245,11,67,18 1>&2; echo $$ $?`; return_code:1; output:"Error org.freedesktop.dbus.exceptions.DBusExecutionException: Error Executing Method org.asamk.Signal.getGroupName: Cannot invoke "Object.toString()" because "data" is null"
DEBUG:root:Error org.freedesktop.dbus.exceptions.DBusExecutionException: Error Executing Method org.asamk.Signal.getGroupName: Cannot invoke "Object.toString()" because "data" is null
exquo commented 2 years ago

Looks like signal-cli gives a 403 error when getting some group information. I think you can open an issue in signal-cli's repo about this. To reproduce the problem:

signal-cli -u +YOUR_PHONE_NUM --output=json daemon &

wait a bit after the daemon starts up; it'll probably print the following without any additional commands from you: 

WARN GroupV2Helper - Failed to retrieve Group V2 info, ignoring: StatusCode: 403

Then entering the command 

 dbus-send --session --type=method_call --print-reply --dest=org.asamk.Signal /org/asamk/Signal org.asamk.Signal.getGroupName array:byte:228,207,237,93,182,33,93,149,3,34,181,100,164,250,156,54,180,12,109,221,64,214,51,69,201,90,254,213,245,11,67,18

should give the error from your logs:

Error org.freedesktop.dbus.exceptions.DBusExecutionException: Error Executing Method org.asamk.Signal.getGroupName: Cannot invoke "Object.toString()" because "data" is null

This probably happens only for that group id, so changing it to anything else (e.g. changing the last number 18 → 180 in the previous command) should not result an error, just return an empty name string:

method return time=1631867636.658195 sender=:1.325 -> destination=:1.367 serial=43 reply_serial=2
     string ""

See also if you get anything relevant using signal-cli's verbose output (add --debug flag to the first signal-cli … command above).

Still, scli should handle this more gracefully. I've pushed a new commit to the hotfix/137 branch that should fix the startup crash.

cycneuramus commented 2 years ago

Thank you for looking into it. Following your instructions, I'm not able to reproduce the problem with signal-cli, nor do I notice anything relevant in the debug output. The hotfix branch of scli is chugging along fine, though, so thanks again for your help.

exquo commented 2 years ago

That's odd.. Does running the master branch of scli still give the 403 error in the logs? Maybe it was an intermittent issue with the signal servers.

cycneuramus commented 2 years ago

Yes, it still does.

Additionally, the hotfix branch (which I had kept running in the background) just crashed when I resumed my laptop from suspend. As of yet I'm not able to reproduce the issue in debug mode, though it seemed to happen when fetching updates from one particular group, so I might be able to get back to you on that. Sorry I can't be more helpful at this time, but here is the error in any case: 

Traceback (most recent call last):
  File "/home/user/./scli", line 2865, in get
    w = self._cache[key]
KeyError: 1621153894561439745

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/./scli", line 4443, in <module>
    main()
  File "/home/user/./scli", line 4437, in main
    loop.run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 287, in run
    self._run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 385, in _run
    self.event_loop.run()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 790, in run
    self._loop()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 827, in _loop
    self._watch_files[fd]()
  File "/usr/lib/python3.9/site-packages/urwid/main_loop.py", line 233, in cb
    rval = callback(data)
  File "/home/user/./scli", line 631, in _daemon_stdout_handler
    self._envelope_handler(envelope)
  File "/home/user/./scli", line 659, in _envelope_handler
    self.callbacks['receive_reaction'](envelope)
  File "/home/user/./scli", line 3912, in _on_receive_reaction
    msg_w = self._ui.msg_ws_cache.get(msg)
  File "/home/user/./scli", line 2867, in get
    w = MessageWidget(msg)
  File "/home/user/./scli", line 2683, in __init__
    color = None if not cfg.color else cfg.color.for_message(msg)
  File "/home/user/./scli", line 1809, in for_message
    return msg.sender.color
AttributeError: 'NoneType' object has no attribute 'color'
exquo commented 2 years ago

I might have been wrong above about getting signal-cli's error right after starting the daemon. Could you try to run the following script / shell commands? It should give the same errors as in your scli logs, assuming the corresponding group_id's cache file is still missing. (Change the phone number in the first line)

phone_num=+1234567890   # <-- Replace with your phone number

group_id=5M/tXbYhXZUDIrVkpPqcNrQMbd1A1jNFyVr+1fULQxI=
group_id_byte_array=228,207,237,93,182,33,93,149,3,34,181,100,164,250,156,54,180,12,109,221,64,214,51,69,201,90,254,213,245,11,67,18

group_id_file=$(echo "$group_id" | sed 's|/|_|g')
stat ~/.local/share/signal-cli/data/$phone_num.d/group-cache/"$group_id_file" 

tmpfile=$(mktemp)
signal-cli -u "$phone_num" daemon  2>$tmpfile &
tail -f $tmpfile | sed '/Exported dbus object/ q'
sleep 0.1
dbus-send --session --type=method_call --print-reply --dest=org.asamk.Signal /org/asamk/Signal org.asamk.Signal.getGroupName array:byte:"$group_id_byte_array"

The other error is probably unrelated. Thanks for reporting it too! I've pushed a commit that will fix it.

cycneuramus commented 2 years ago

The script does indeed seem to throw the same kind of errors:

stat: cannot statx '~/.local/share/signal-cli/data/+[phone-number].d/group-cache/5M_tXbYhXZUDIrVkpPqcNrQMbd1A1jNFyVr+1fULQxI=': No such file or directory
INFO DaemonCommand - Exported dbus object: /org/asamk/Signal
Error org.freedesktop.dbus.exceptions.DBusExecutionException: Error Executing Method org.asamk.Signal.getGroupName: Cannot invoke "Object.toString()" because "data" is null
exquo commented 2 years ago

There we go then, it's a signal-cli issue. You can use that script (and its output) pretty much as is to submit a bug report upstream.

For clarity, to show that the group_id is in signal-cli's groupStore, you can add another command anywhere in the script:

grep "$group_id" ~/.local/share/signal-cli/data/$phone_num

Also, adding --debug flag to the signal-cli … command wouldn't hurt.

To help them troubleshoot this, it would be helpful to know if there's anything special you can think of about this group. (If you can figure out which group this group_id corresponds to; probably can be done by a method of elimination, comparing the groups you have on the phone and in scli)

cycneuramus commented 2 years ago

Alright, I'm closing this issue then. Thank you again for helping me investigate.

Just for the record, what I found on comparing the problematic groups with the ones on my phone was that they did not correspond to any groups of which I am actually a member. signal-cli listGroups simply listed their name as null, and I was able to get rid of the issue simply by issuing signal-cli quitGroup --delete -g [group_id]. So I suppose this might have been some kind of issue with the Signal servers.

exquo commented 2 years ago

Glad you could get it resolved!