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

dbus error even though dbus is running #146

Closed scottwn closed 2 years ago

scottwn commented 2 years ago

Hello, I was having issues getting dbus to start which I documented in this discussion https://github.com/Homebrew/discussions/discussions/2318

I'm not sure how I did it but somehow that error got resolved and I can now start dbus. However, scli is crashing when it tries to verify dbus is running. Any idea what the issue might be?

~ $ brew services start dbus
==> Successfully started `dbus` (label: org.freedesktop.dbus-session)
~ $ scli
Traceback (most recent call last):
  File "/Users/scott/scli/scli", line 4461, in <module>
    main()
  File "/Users/scott/scli/scli", line 4455, in main
    loop.run()
  File "/opt/homebrew/lib/python3.9/site-packages/urwid/main_loop.py", line 287, in run
    self._run()
  File "/opt/homebrew/lib/python3.9/site-packages/urwid/main_loop.py", line 385, in _run
    self.event_loop.run()
  File "/opt/homebrew/lib/python3.9/site-packages/urwid/main_loop.py", line 790, in run
    self._loop()
  File "/opt/homebrew/lib/python3.9/site-packages/urwid/main_loop.py", line 827, in _loop
    self._watch_files[fd]()
  File "/opt/homebrew/lib/python3.9/site-packages/urwid/main_loop.py", line 233, in cb
    rval = callback(data)
  File "/Users/scott/scli/scli", line 639, in _daemon_stderr_handler
    self.callbacks['daemon_log'](line)
  File "/Users/scott/scli/scli", line 3927, in _on_daemon_log
    if log_line.startswith("ERROR") and not self.daemon.is_dbus_service_running:
  File "/Users/scott/scli/scli", line 839, in is_dbus_service_running
    proc = self._dbus_send(args, async_proc=False, capture_output=True, text=True, check=True)
  File "/Users/scott/scli/scli", line 683, in _dbus_send
    proc = subprocess.run(args, *proc_args, **proc_kwargs)
  File "/opt/homebrew/Cellar/python@3.9/3.9.7_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/subprocess.py", line 528, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['dbus-send', '--session', '--type=method_call', '--print-reply', '--dest=org.freedesktop.DBus', '/org/freedesktop/DBus', 'org.freedesktop.DBus.ListNames']' returned non-zero exit status 1.
exquo commented 2 years ago

Try to execute the offending method call in a terminal directly:

dbus-send --session --type=method_call --print-reply --dest=org.freedesktop.DBus /org/freedesktop/DBus org.freedesktop.DBus.ListNames

It should return a list of all dbus services. If it doesn't, something's probably wrong with the dbus setup.

Note that this error is a purely dbus problem, not caused by signal-cli or scli.

scottwn commented 2 years ago

That command runs successfully, not sure if there should be more services in the list.

~ $ brew services
Name    Status  User  Plist
dbus    started scott /Users/scott/Library/LaunchAgents/org.freedesktop.dbus-session.plist
unbound stopped       
~ $ dbus-send --session --type=method_call --print-reply --dest=org.freedesktop.DBus /org/freedesktop/DBus org.freedesktop.DBus.ListNames
method return time=1635255192.770442 sender=org.freedesktop.DBus -> destination=:1.6 serial=3 reply_serial=2
   array [
      string "org.freedesktop.DBus"
      string ":1.6"
   ]

Now when I try to start scli, it fails with a different error:

signal-cli daemon has stopped:
    ERROR DaemonCommand - Dbus command failed
Restart scli to restart the daemon.

When I restart scli I see the same error.

scottwn commented 2 years ago

The error is definitely coming from DaemonCommand.handleCommand but not sure why

https://github.com/AsamK/signal-cli/blob/master/src/main/java/org/asamk/signal/commands/DaemonCommand.java#L80

exquo commented 2 years ago

Looks like signal-cli fails to connect to DBus. Try executing

signal-cli --verbose daemon

to see if there are any more details in the output.

scottwn commented 2 years ago

Here's the output. The issue seems to be Cannot Resolve Session Bus Address: MachineId file can not be found

~ $ signal-cli --verbose daemon
2021-10-30T16:11:37.299-0500 [main] INFO LibSignal - [libsignal-client]: rust/bridge/jni/src/logging.rs:173: Initializing libsignal-client version:0.9.0
2021-10-30T16:11:37.818-0500 [main] WARN org.asamk.signal.manager.Manager - Messages have been last received 15 days ago. The Signal protocol expects that incoming messages are regularly received.
2021-10-30T16:11:38.370-0500 [main] ERROR org.asamk.signal.commands.DaemonCommand - Dbus command failed
org.freedesktop.dbus.exceptions.DBusConnectionException: Cannot Resolve Session Bus Address: MachineId file can not be found
    at org.freedesktop.dbus.connections.impl.DBusConnection.lambda$determineMachineIdFile$3(DBusConnection.java:309)
    at java.base/java.util.Optional.orElseThrow(Optional.java:403)
    at org.freedesktop.dbus.connections.impl.DBusConnection.determineMachineIdFile(DBusConnection.java:309)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getDbusMachineId(DBusConnection.java:286)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:134)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:195)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:158)
    at org.asamk.signal.commands.DaemonCommand.handleCommand(DaemonCommand.java:95)
    at org.asamk.signal.App.handleMultiLocalCommand(App.java:270)
    at org.asamk.signal.App.init(App.java:167)
    at org.asamk.signal.Main.main(Main.java:52)
Dbus command failed
org.freedesktop.dbus.exceptions.DBusConnectionException: Cannot Resolve Session Bus Address: MachineId file can not be found
    at org.freedesktop.dbus.connections.impl.DBusConnection.lambda$determineMachineIdFile$3(DBusConnection.java:309)
    at java.base/java.util.Optional.orElseThrow(Optional.java:403)
    at org.freedesktop.dbus.connections.impl.DBusConnection.determineMachineIdFile(DBusConnection.java:309)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getDbusMachineId(DBusConnection.java:286)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:134)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:195)
    at org.freedesktop.dbus.connections.impl.DBusConnection.getConnection(DBusConnection.java:158)
    at org.asamk.signal.commands.DaemonCommand.handleCommand(DaemonCommand.java:95)
    at org.asamk.signal.App.handleMultiLocalCommand(App.java:270)
    at org.asamk.signal.App.init(App.java:167)
    at org.asamk.signal.Main.main(Main.java:52)
exquo commented 2 years ago

This looks similar to the error in https://github.com/AsamK/signal-cli/wiki/DBus-service#dbus-exception-when-starting-daemon and the issues linked there. Try setting the DBUS_SESSION_BUS_ADDRESS and/or DBUS_LAUNCHD_SESSION_BUS_SOCKET env variables as discussed there.

scottwn commented 2 years ago

Yeah, it is similar and I've read that doc. I'm on MacOS. DBUS_LAUNCHD_SESSION_BUS_SOCKET is set, although the launchctl env suggested in the doc is empty.

~ $ echo $DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.T326GNaOgc/unix_domain_listener
~ $ launchctl getenv DBUS_LAUNCHD_SESSION_BUS_SOCKET
~ $

DBUS_SESSION_BUS_ADDRESS is not set; I checked the process env per this linked blog post, but it doesn't have that variable set either, so if it needs to be set I'm sort of lost regarding what I should set it to.

~ $ launchctl list | grep dbus
14486   0       org.freedesktop.dbus-session
~ $ ps eww 14486
  PID   TT  STAT      TIME COMMAND
14486   ??  S      0:00.01 /opt/homebrew/Cellar/dbus/1.12.20/bin/dbus-daemon --nofork --session XPC_SERVICE_NAME=org.freedesktop.dbus-session DBUS_LAUNCHD_SESSION_BUS_SOCKET=/private/tmp/com.apple.launchd.T326GNaOgc/unix_domain_listener SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.gojJnrsLqL/Listeners PATH=/usr/bin:/bin:/usr/sbin:/sbin XPC_FLAGS=1 LOGNAME=scott USER=scott HOME=/Users/scott SHELL=/opt/homebrew/bin/fish TMPDIR=/var/folders/lt/3q6p5ff92p392nh9w7jxhgmc0000gn/T/
~ $
exquo commented 2 years ago

To set DBUS_SESSION_BUS_ADDRESS, try

export DBUS_SESSION_BUS_ADDRESS=unix:path=$DBUS_LAUNCHD_SESSION_BUS_SOCKET

(based on https://github.com/AsamK/signal-cli/wiki/DBus-service#macos-and-dbus-send)

scottwn commented 2 years ago

This issue seems to also be similar: https://github.com/Spotifyd/spotifyd/issues/562

As suggested there, I checked for the unix_domain_listener paths. There were many.

~ $ ls -l /private/tmp/com.apple.launchd*
/private/tmp/com.apple.launchd.2a91LsdStp:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 16:53 unix_domain_listener

/private/tmp/com.apple.launchd.8Amn2CKP3q:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 16:42 unix_domain_listener

/private/tmp/com.apple.launchd.HKWycvsrB8:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 17:22 unix_domain_listener

/private/tmp/com.apple.launchd.IVMcquzNno:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 17:00 unix_domain_listener

/private/tmp/com.apple.launchd.J0yIRi3k7l:
total 0
ls: /private/tmp/com.apple.launchd.J0yIRi3k7l: Permission denied

/private/tmp/com.apple.launchd.PzQE4QsC9H:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 14:41 unix_domain_listener

/private/tmp/com.apple.launchd.VaWACiK06D:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 17:23 unix_domain_listener

/private/tmp/com.apple.launchd.dwzBdgeeS8:
total 0
srw-rw-rw-  1 scott  wheel  0 Nov  2 09:54 Listeners

/private/tmp/com.apple.launchd.laWCjp6oFU:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 16:45 unix_domain_listener

/private/tmp/com.apple.launchd.t8kk3tXO6h:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 14:42 unix_domain_listener

/private/tmp/com.apple.launchd.wNj4eqN4o7:
total 0
srw-rw-rw-  1 scott  staff  0 Nov  2 09:54 unix_domain_listener

I can set the env to the latest listener path:

~ $ set --erase DBUS_LAUNCHD_SESSION_BUS_SOCKET
~ $ set --erase DBUS_SESSION_BUS_ADDRESS
~ $ launchctl setenv DBUS_LAUNCHD_SESSION_BUS_SOCKET /private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ set -Ux DBUS_LAUNCHD_SESSION_BUS_SOCKET /private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ set -Ux DBUS_SESSION_BUS_ADDRESS unix:path=$DBUS_LAUNCHD_SESSION_BUS_SOCKET
~ $ launchctl getenv DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ echo $DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ echo $DBUS_SESSION_BUS_ADDRESS
unix:path=/private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener

but when I do signal-cli --verbose daemon I get the same MachineId error as above.

After restarting my shell, DBUS_LAUNCHD_SESSION_BUS_SOCKET has changed back to an older path. So that is being set automatically by something, possibly brew or launchd. 

~ $ launchctl getenv DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ echo $DBUS_SESSION_BUS_ADDRESS
unix:path=/private/tmp/com.apple.launchd.VaWACiK06D/unix_domain_listener
~ $ echo $DBUS_LAUNCHD_SESSION_BUS_SOCKET 
/private/tmp/com.apple.launchd.wNj4eqN4o7/unix_domain_listener

I tried setting the other variables to match the global DBUS_LAUNCHD_SESSION_BUS_SOCKET which is set automatically.

~ $ launchctl setenv DBUS_LAUNCHD_SESSION_BUS_SOCKET /private/tmp/com.apple.launchd.wNj4eqN4o7/unix_domain_listener
~ $ set --erase -U DBUS_LAUNCHD_SESSION_BUS_SOCKET
set: Universal variable 'DBUS_LAUNCHD_SESSION_BUS_SOCKET' is shadowed by the global variable of the same name.
~ $ set --erase -U DBUS_SESSION_BUS_ADDRESS 
~ $ set -Ux DBUS_SESSION_BUS_ADDRESS unix:path=$DBUS_LAUNCHD_SESSION_BUS_SOCKET
~ $ launchctl getenv DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.wNj4eqN4o7/unix_domain_listener
~ $ echo $DBUS_LAUNCHD_SESSION_BUS_SOCKET
/private/tmp/com.apple.launchd.wNj4eqN4o7/unix_domain_listener
~ $ echo $DBUS_SESSION_BUS_ADDRESS
unix:path=/private/tmp/com.apple.launchd.wNj4eqN4o7/unix_domain_listener

That didn't help either, I still have the MachineId error, even after a restart.

exquo commented 2 years ago

I'm afraid that exhausts my guesses then.. I believe this is an issue with dbus on mac, rather than anything to do with signal-cli specifically. You can try to reproduce the error with some minimal working example; maybe something here would be useful. Then this error can be reported to the dbus package maintainers at homebrew.

exquo commented 2 years ago

A new commit to signal-cli changes the dbus library dependency. Might be worth trying it out. You can build the latest from source or download the built artifact of a CI run.

scottwn commented 2 years ago

Thanks, that's great! I built the master branch, and now signal-cli --verbose daemon runs without errors.

~ $ signal-cli --verbose daemon
2021-11-15T17:27:48.631-0600 [main] DEBUG org.asamk.signal.util.IOUtils - XDG_RUNTIME_DIR not set, falling back to temp dir
2021-11-15T17:27:48.634-0600 [main] DEBUG org.asamk.signal.util.IOUtils - XDG_DATA_HOME not set, falling back to home dir
2021-11-15T17:27:48.878-0600 [main] INFO LibSignal - [libsignal-client]: rust/bridge/jni/src/logging.rs:173: Initializing libsignal-client version:0.9.7
2021-11-15T17:27:51.872-0600 [main] INFO org.asamk.signal.commands.DaemonCommand - Starting daemon in multi-account mode
2021-11-15T17:27:51.877-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Starting receiving messages
2021-11-15T17:27:51.879-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Handling message actions
2021-11-15T17:27:51.889-0600 [main] DEBUG org.freedesktop.dbus.connections.transports.TransportBuilder - Found provider 'NativeTransportProvider' named 'dbus-java-transport-native-unixsocket' providing bustype 'UNIX'
2021-11-15T17:27:51.917-0600 [Thread-0] INFO LibSignal - [WebSocketConnection]: [normal:67344613] connect()
2021-11-15T17:27:51.919-0600 [main] DEBUG org.freedesktop.dbus.transport.jre.NativeUnixSocketTransport - No alternative ISocketProvider found, using built-in implementation
2021-11-15T17:27:51.922-0600 [Thread-0] INFO LibSignal - [WebSocketConnection]: [unidentified:1404445748] connect()
2021-11-15T17:27:51.924-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Checking for new message from server
2021-11-15T17:27:51.925-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Creating message with serial 1
2021-11-15T17:27:51.925-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending sig: yyyy data: [108, 1, 0, 1]
2021-11-15T17:27:51.925-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending sig: ua(yv) data: [1, [[1, [o, /org/freedesktop/DBus]], [6, [s, org.freedesktop.DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, Hello]]]]
2021-11-15T17:27:51.926-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appended body, type: null start: 128 end: 128 size: 0
2021-11-15T17:27:51.926-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - marshalled size ([0, 0, 0, 0]): 000000 00 00 00 00                                            ....              
2021-11-15T17:27:51.928-0600 [DBus Sender Thread-1] DEBUG org.freedesktop.dbus.spi.message.OutputStreamMessageWriter - <= MethodCall(0,1) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { }
2021-11-15T17:27:51.929-0600 [DBusConnection] DEBUG org.freedesktop.dbus.spi.message.InputStreamMessageReader - => MethodReturn(1,1) { Reply Serial=>1, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { :1.4 }
2021-11-15T17:27:51.929-0600 [DBusConnection] DEBUG org.freedesktop.dbus.connections.impl.DBusConnection - Handling incoming method return: MethodReturn(1,1) { Reply Serial=>1, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { :1.4 }
2021-11-15T17:27:51.929-0600 [DBusConnection] DEBUG org.freedesktop.dbus.spi.message.InputStreamMessageReader - => DBusSignal(1,2) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>NameAcquired, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { :1.4 }
2021-11-15T17:27:51.929-0600 [DBusConnection] DEBUG org.freedesktop.dbus.connections.impl.DBusConnection - Handling incoming signal: DBusSignal(1,2) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>NameAcquired, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { :1.4 }
2021-11-15T17:27:51.930-0600 [DBus Worker Thread-1] DEBUG org.freedesktop.dbus.messages.DBusSignal - Converting signal to type: class org.freedesktop.dbus.interfaces.DBus$NameAcquired
2021-11-15T17:27:51.930-0600 [main] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal to object tree
2021-11-15T17:27:51.931-0600 [DBus Worker Thread-1] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Creating message with serial 2
2021-11-15T17:27:51.931-0600 [DBus Worker Thread-1] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Appending sig: yyyy data: [108, 4, 0, 1]
2021-11-15T17:27:51.931-0600 [DBus Worker Thread-1] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Appending sig: ua(yv) data: [3, [[1, [o, /org/freedesktop/DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, NameAcquired]], [8, [g, s]]]]
2021-11-15T17:27:51.938-0600 [main] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal/_13478139851 to object tree
2021-11-15T17:27:51.939-0600 [main] DEBUG org.asamk.signal.commands.DaemonCommand - Exported dbus object: /org/asamk/Signal/_13478139851
2021-11-15T17:27:52.019-0600 [Thread-2] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal/_13478139851/Devices/1 to object tree
2021-11-15T17:27:52.019-0600 [Thread-2] DEBUG org.asamk.signal.dbus.DbusSignalImpl - Exported dbus object: /org/asamk/Signal/_13478139851/Devices/1
2021-11-15T17:27:52.019-0600 [Thread-2] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal/_13478139851/Devices/2 to object tree
2021-11-15T17:27:52.019-0600 [Thread-2] DEBUG org.asamk.signal.dbus.DbusSignalImpl - Exported dbus object: /org/asamk/Signal/_13478139851/Devices/2
2021-11-15T17:27:52.020-0600 [Thread-2] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal/_13478139851/Devices/3 to object tree
2021-11-15T17:27:52.020-0600 [Thread-2] DEBUG org.asamk.signal.dbus.DbusSignalImpl - Exported dbus object: /org/asamk/Signal/_13478139851/Devices/3
2021-11-15T17:27:52.021-0600 [Thread-2] DEBUG org.freedesktop.dbus.messages.ObjectTree - Removing /org/asamk/Signal/_13478139851/Configuration from object tree
2021-11-15T17:27:52.022-0600 [Thread-2] DEBUG org.freedesktop.dbus.messages.ObjectTree - Adding /org/asamk/Signal/_13478139851/Configuration to object tree
2021-11-15T17:27:52.022-0600 [Thread-2] DEBUG org.asamk.signal.dbus.DbusSignalImpl - Exported dbus object: /org/asamk/Signal/_13478139851/Configuration
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Creating message with serial 3
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending sig: yyyy data: [108, 1, 0, 1]
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending arguments with signature: su
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending sig: ua(yv) data: [3, [[1, [o, /org/freedesktop/DBus]], [6, [s, org.freedesktop.DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, RequestName]], [8, [g, su]]]]
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appending sig: su data: [org.asamk.Signal, 6]
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - Appended body, type: su start: 144 end: 172 size: 28
2021-11-15T17:27:52.023-0600 [main] DEBUG org.freedesktop.dbus.messages.MethodCall - marshalled size ([28, 0, 0, 0]): 000000    1c 00 00 00                                            ...              
2021-11-15T17:27:52.023-0600 [DBus Sender Thread-1] DEBUG org.freedesktop.dbus.spi.message.OutputStreamMessageWriter - <= MethodCall(0,3) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>RequestName, Destination=>org.freedesktop.DBus, Signature=>su } { org.asamk.Signal, 6 }
2021-11-15T17:27:52.024-0600 [DBusConnection] DEBUG org.freedesktop.dbus.spi.message.InputStreamMessageReader - => DBusSignal(1,3) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>NameAcquired, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { org.asamk.Signal }
2021-11-15T17:27:52.024-0600 [DBusConnection] DEBUG org.freedesktop.dbus.connections.impl.DBusConnection - Handling incoming signal: DBusSignal(1,3) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>NameAcquired, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>s } { org.asamk.Signal }
2021-11-15T17:27:52.024-0600 [DBus Worker Thread-2] DEBUG org.freedesktop.dbus.messages.DBusSignal - Converting signal to type: class org.freedesktop.dbus.interfaces.DBus$NameAcquired
2021-11-15T17:27:52.024-0600 [DBusConnection] DEBUG org.freedesktop.dbus.spi.message.InputStreamMessageReader - => MethodReturn(1,4) { Reply Serial=>3, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>u } { 1 }
2021-11-15T17:27:52.024-0600 [DBus Worker Thread-2] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Creating message with serial 4
2021-11-15T17:27:52.024-0600 [DBusConnection] DEBUG org.freedesktop.dbus.connections.impl.DBusConnection - Handling incoming method return: MethodReturn(1,4) { Reply Serial=>3, Destination=>:1.4, Sender=>org.freedesktop.DBus, Signature=>u } { 1 }
2021-11-15T17:27:52.024-0600 [DBus Worker Thread-2] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Appending sig: yyyy data: [108, 4, 0, 1]
2021-11-15T17:27:52.024-0600 [main] INFO org.asamk.signal.commands.DaemonCommand - DBus daemon running on SESSION bus: org.asamk.Signal
2021-11-15T17:27:52.024-0600 [DBus Worker Thread-2] DEBUG org.freedesktop.dbus.interfaces.DBus$NameAcquired - Appending sig: ua(yv) data: [5, [[1, [o, /org/freedesktop/DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, NameAcquired]], [8, [g, s]]]]
2021-11-15T17:27:52.186-0600 [OkHttp https://chat.signal.org/...] INFO LibSignal - [WebSocketConnection]: [normal:67344613] onOpen() connected
2021-11-15T17:27:52.186-0600 [RxComputationThreadPool-3] DEBUG org.asamk.signal.manager.SignalWebSocketHealthMonitor - WebSocket is now connected
2021-11-15T17:27:52.197-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Received indicator that server queue is empty
2021-11-15T17:27:52.197-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Handling message actions
2021-11-15T17:27:52.197-0600 [Thread-0] DEBUG org.asamk.signal.manager.ManagerImpl - Checking for new message from server
2021-11-15T17:27:52.201-0600 [OkHttp https://chat.signal.org/...] INFO LibSignal - [WebSocketConnection]: [unidentified:1404445748] onOpen() connected
2021-11-15T17:27:52.202-0600 [RxComputationThreadPool-4] DEBUG org.asamk.signal.manager.SignalWebSocketHealthMonitor - WebSocket is now connected

Unfortunately, now scli get stuck on Initializing signal-cli daemon.... Any idea how to get scli to play nice with the signal-cli daemon?

exquo commented 2 years ago

Looks like the new signal-cli version does not print out the line scli expects. (It's probably caused by the recent changes in signal-cli's daemon interface).

Could you please run

signal-cli -u +1234567890 --output=json daemon

(replace +1234567890 with your phone number) and paste here the output?

scottwn commented 2 years ago 
~ $ signal-cli -u +13478139851 --output=json daemon
INFO DaemonCommand - Starting daemon in single-account mode for +13478139851
INFO DaemonCommand - DBus daemon running on SESSION bus: org.asamk.Signal

after that it outputs several JSON formatted envelopes, which I can't paste since they contain sensitive content, but they are formatted something like

{
  "envelope": {
    "source": "+1yyyyyyyyyy",
    "sourceNumber": "+1yyyyyyyyyy",
    "sourceUuid": "xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx",
    "sourceName": "⁨John",
    "sourceDevice": 1,
    "timestamp": 1637180002423,
    "receiptMessage": {
      "when": 1637180002423,
      "isDelivery": true,
      "isRead": false,
      "isViewed": false,
      "timestamps": [
        1637180002408
      ]
    }
  },
  "account": "+13478139851"
}
exquo commented 2 years ago

Should now work in 0d436fab9317ba8f5da5e5f1af9fb9bb65166965, feel free to try it out.

scottwn commented 2 years ago

With this change we're back to the original CalledProcessError:frowning:

~ [SIGINT]$ signal-cli -u +13478139851 --output=json daemon
INFO DaemonCommand - Starting daemon in single-account mode for +13478139851
INFO DaemonCommand - DBus daemon running on SESSION bus: org.asamk.Signal
^C⏎                                                                                                                                                                                     ~ [SIGINT]$ cd ~/scli
~/scli (master|✔) [128]$ git pull
remote: Enumerating objects: 21, done.
remote: Counting objects: 100% (21/21), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 19 (delta 12), reused 15 (delta 8), pack-reused 0
Unpacking objects: 100% (19/19), 4.38 KiB | 115.00 KiB/s, done.
From https://github.com/isamert/scli
   2b1670b..6cb807d  master     -> origin/master
   2b1670b..0d436fa  develop    -> origin/develop
 * [new tag]         v0.6.5     -> v0.6.5
Updating 2b1670b..6cb807d
Fast-forward
 scli | 81 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++-------------------------
 1 file changed, 56 insertions(+), 25 deletions(-)
~/scli (master|✔) [128]$ git checkout 0d436fab9317ba8f5da5e5f1af9fb9bb65166965
Note: switching to '0d436fab9317ba8f5da5e5f1af9fb9bb65166965'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at 0d436fa Modify the expected 'DBus daemon started' log string
~/scli ((0d436fab…)|✔) $ git diff master
diff --git a/scli b/scli
index 9f066fd..13c3094 100755
--- a/scli
+++ b/scli
@@ -640,7 +640,10 @@ class Daemon(AsyncProc):
             return
         logging.info('daemon_log: %s', line)
         self.callbacks['daemon_log'](line)
-        if line == "INFO DaemonCommand - Exported dbus object: /org/asamk/Signal":
+        if any(s in line for s in (
+                "Exported dbus object: /org/asamk/Signal",  # signal-cli v0.9.2 or earlier
+                "DBus daemon running",
+                )):
             self._run_when_dbus_service_started(
                     self.callbacks['daemon_started']
                     )
~/scli ((0d436fab…)|✔) $ scli
Traceback (most recent call last):
  File "/Users/scott/scli/scli", line 4495, in <module>
    main()
  File "/Users/scott/scli/scli", line 4489, in main
    loop.run()
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/site-packages/urwid/main_loop.py", line 287, in run
    self._run()
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/site-packages/urwid/main_loop.py", line 385, in _run
    self.event_loop.run()
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/site-packages/urwid/main_loop.py", line 790, in run
    self._loop()
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/site-packages/urwid/main_loop.py", line 827, in _loop
    self._watch_files[fd]()
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/site-packages/urwid/main_loop.py", line 233, in cb
    rval = callback(data)
  File "/Users/scott/scli/scli", line 647, in _daemon_stderr_handler
    self._run_when_dbus_service_started(
  File "/Users/scott/scli/scli", line 856, in _run_when_dbus_service_started
    set_alarm(self.main_loop)
  File "/Users/scott/scli/scli", line 852, in set_alarm
    if self.is_dbus_service_running:
  File "/Users/scott/scli/scli", line 845, in is_dbus_service_running
    proc = self._dbus_send(args, async_proc=False, capture_output=True, text=True, check=True)
  File "/Users/scott/scli/scli", line 689, in _dbus_send
    proc = subprocess.run(args, *proc_args, **proc_kwargs)
  File "/Users/scott/.pyenv/versions/3.10.0/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['dbus-send', '--session', '--type=method_call', '--print-reply', '--dest=org.freedesktop.DBus', '/org/freedesktop/DBus', 'org.freedesktop.DBus.ListNames']' returned non-zero exit status 1.
exquo commented 2 years ago

Back here you did get it to work; maybe there's been some additional commands / setup then?

The rest of the output looks good, so now it's (once more :) just a matter of getting homebrew's DBus to work.