cincodenada
commented
3 years ago Hello,
I'm fairly new to Matrix, and have it set up as a personal hub currently with the Facebook, Instagram, and iMessage bridges. The former two are working pretty well at this point. I'm trying to use wsproxy to run mautrix-imessage with the (Beeper) Android SMS bridge, and it works great for syncing incoming messages, but I have had very little success with outgoing messages. I just rebuilt the bridge app and pulled the latest wsproxy/syncproxy images. After syncing up the messages, I stopped the bridge app, stopped wsproxy with docker stop, and then restarted the proxy with docker up, and restarted the bridge app, then sent two outgoing messages from Matrix (Element). I got nothing on my phone, and the bridge app crashed. I'm not sure whether the issue is here or the bridge, so I wasn't sure where was the best place to file this, but it seems like the issue starts with this abnormal websocket closure?
I'm not sure where to start digging in here, so I've just attached all the logs and configs that seemed relevant.
Configs
docker-compose.yml:
version: "3.7"
services:
mautrix-wsproxy:
container_name: mautrix-wsproxy
image: dock.mau.dev/mautrix/wsproxy
restart: unless-stopped
ports:
- 29331:29331
environment:
#LISTEN_ADDRESS: ":29331"
APPSERVICE_ID: imessage
AS_TOKEN: "[redacted]"
HS_TOKEN: "[redacted]"
# These URLs will work as-is with docker networking
SYNC_PROXY_URL: http://mautrix-syncproxy:29332
SYNC_PROXY_WSPROXY_URL: http://mautrix-wsproxy:29331
SYNC_PROXY_SHARED_SECRET: "[redacted]"
mautrix-syncproxy:
container_name: mautrix-syncproxy
image: dock.mau.dev/mautrix/syncproxy
restart: unless-stopped
environment:
#LISTEN_ADDRESS: ":29332"
DATABASE_URL: "postgres://mautrixsyncproxy:[redacted]@172.26.0.1/mautrixsyncproxy"
HOMESERVER_URL: http://172.26.0.1:8008
SHARED_SECRET: "[redacted]"
DEBUG: "true"mautrix-imessage.yaml (appservice config):
as_token: "[redacted]"
hs_token: "[redacted]"
namespaces:
users:
# The localpart here is username_template from the config, but .+ instead of {{.}}
- regex: '@imessage_.+:[mydomain]\.dev'
exclusive: true
# Localpart here is appservice -> bot -> username from the config
- regex: '@imessagebot:[mydomain]\.dev'
exclusive: true
# Address that Synapse uses to contact mautrix-wsproxy
url: "http://localhost:29331"
# Put a new random string here, it doesn't affect anything else
sender_localpart: "[redacted]"
rate_limited: falseSMS Bridge config.yaml diff from example-config.yaml:
--- example-config.yaml 2021-08-16 22:12:54.168217774 -0700
+++ config.yaml 2021-08-17 00:11:16.767943684 -0700
@@ -1,16 +1,16 @@
# Homeserver details.
homeserver:
# The address that this appservice can use to connect to the homeserver.
- address: https://example.com
- websocket_proxy: ws://localhost:29331
+ address: https://matrix.[mydomain].dev
+ websocket_proxy: wss://mautrix-proxy.[mydomain].dev
# The domain of the homeserver (for MXIDs, etc).
- domain: example.com
+ domain: [mydomain].dev
# Application service host/registration related details.
# Changing these values requires regeneration of the registration.
appservice:
# SQLite database path
- database: mautrix-imessage.db
+ database: /data/user/0/com.beeper.sms.app/mautrix-imessage.db
# The unique ID of this appservice.
id: imessage
@@ -24,8 +24,8 @@
avatar: mxc://maunium.net/tManJEpANASZvDVzvRvhILdX
# Authentication tokens for AS <-> HS communication. Autogenerated; do not modify.
- as_token: "This value is generated when generating the registration"
- hs_token: "This value is generated when generating the registration"
+ as_token: "[redacted]"
+ hs_token: "[redacted]"
# iMessage connection config
imessage:
@@ -34,14 +34,14 @@
# * ios: Jailbreak iOS connector when using with Brooklyn.
# * android: Equivalent to ios, but for use with the Android SMS wrapper app.
# * mac-nosip: Mac without SIP connector, runs imessage-rest as a subprocess.
- platform: mac
+ platform: android
# imessage-rest executable for mac-nosip connector
#imessage_rest_path: ...
# Bridge config
bridge:
# The user of the bridge.
- user: "@you:example.com"
+ user: "@joel:[mydomain].dev"
# Localpart template of MXIDs for iMessage users.
# {{.}} is replaced with the phone number or email of the iMessage user.
@@ -102,7 +102,8 @@
# Logging config.
logging:
# The directory for log files. Will be created if not found.
- directory: ./logs
+ directory: /data/user/0/com.beeper.sms.app/logs
+ #directory: /sdcard/Android/data/com.beeper.sms.app/logs
# Available variables: .Date for the file date and .Index for different log files on the same day.
file_name_format: "{{.Date}}-{{.Index}}.log"
# Date format for file names in the Go time format: https://golang.org/pkg/time/#pkg-constantsMy nginx config for mautrix-proxy:
server {
server_name mautrix-proxy.[mydomain].dev;
location / {
proxy_pass http://localhost:29331;
proxy_set_header X-Forwarded-For $remote_addr;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_set_header Host $host;
proxy_buffering off;
proxy_http_version 1.1;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection "upgrade";
}
listen [::]:443 ssl; # managed by Certbot
listen 443 ssl; # managed by Certbot
ssl_certificate /etc/letsencrypt/live/[mydomain].dev/fullchain.pem; # managed by Certbot
ssl_certificate_key /etc/letsencrypt/live/[mydomain].dev/privkey.pem; # managed by Certbot
include /etc/letsencrypt/options-ssl-nginx.conf; # managed by Certbot
ssl_dhparam /etc/letsencrypt/ssl-dhparams.pem; # managed by Certbot
}
server {
if ($host = mautrix-proxy.[mydomain].dev) {
return 301 https://$host$request_uri;
} # managed by Certbot
listen 80;
listen [::]:80;
server_name mautrix-proxy.[mydomain].dev;
return 404; # managed by Certbot
}Logs
Here are the logs from the wsproxy docker:
Starting mautrix-syncproxy ... done
Attaching to mautrix-syncproxy, mautrix-wsproxy
mautrix-syncproxy | [Sep 11, 2021 20:23:47] [INFO] Starting old active targets
mautrix-syncproxy | [Sep 11, 2021 20:23:47] [INFO] Started 0 active targets out of 0 total old targets
mautrix-syncproxy | [Sep 11, 2021 20:23:47] [INFO] Starting to listen on :29332
mautrix-wsproxy | 2021/09/11 20:23:47 Found one appservice from environment variables
mautrix-wsproxy | 2021/09/11 20:23:47 Starting to listen on :29331
mautrix-wsproxy | 2021/09/11 20:23:57 imessage connected to websocket
mautrix-wsproxy | 2021/09/11 20:23:57 Unknown command bridge_status in request #0 from websocket. Data: {"state_event":"CONNECTED","timestamp":1631391836,"ttl":600,"source":"bridge","user_id":"@joel:[mydomain].dev"}
mautrix-wsproxy | 2021/09/11 20:24:28 Sending transaction 1781 to imessage containing 1 events, 0 ephemeral events, 0 OTK counts and 0 device list changes
mautrix-wsproxy | 2021/09/11 20:24:28 Sent transaction 1781 to imessage successfully
mautrix-wsproxy | 2021/09/11 20:25:17 Sending transaction 1782 to imessage containing 1 events, 0 ephemeral events, 0 OTK counts and 0 device list changes
mautrix-wsproxy | 2021/09/11 20:25:17 Sent transaction 1782 to imessage successfully
mautrix-wsproxy | 2021/09/11 20:25:18 Error reading from websocket: websocket: close 1006 (abnormal closure): unexpected EOF
mautrix-wsproxy | 2021/09/11 20:25:18 imessage disconnected from websocket
mautrix-wsproxy | 2021/09/11 20:25:18 Error requesting syncproxy stop after imessage disconnected: M_NOT_FOUND: No appservice found with that ID
mautrix-syncproxy | [Sep 11, 2021 20:25:18] [DEBUG] Client requested stopping unknown appservice imessageAnd the adb logs from the bridge app:
09-11 13:23:54.959 8185 8208 D SMS-BridgeService: [Sep 11, 2021 20:23:54] [INFO] Startup sync complete
09-11 13:23:56.239 8185 8516 D SMS-Bridge: start
09-11 13:23:56.255 8185 8516 D SMS-BackfillSentMMS: lastTimestamp 1631391831 -> 1631391836
09-11 13:23:56.258 8185 8516 D SMS-SmsObserver: 112625034 Watching content://sms
09-11 13:23:56.261 8185 8516 D SMS-SmsObserver: 112625034 Watching content://mms
09-11 13:23:56.263 8185 8516 D SMS-SmsObserver: 112625034 Watching content://mms-sms/
09-11 13:23:56.309 8185 8185 D SMS-BridgeService: starting service
09-11 13:23:56.317 8185 8516 D SMS-Bridge: java.lang.UNIXProcess$ProcessPipeInputStream@2feca3d forEach
09-11 13:23:56.319 8185 8209 D SMS-Bridge: java.lang.UNIXProcess$ProcessPipeInputStream@48e232 forEach
09-11 13:23:56.962 8185 8208 D SMS-BridgeService: [Sep 11, 2021 20:23:56] [Matrix/DEBUG] Appservice transaction websocket connected
09-11 13:23:56.962 8185 8208 D SMS-BridgeService: [Sep 11, 2021 20:23:56] [DEBUG] Sending bridge status to server
09-11 13:24:57.440 8185 8319 V SMS-SmsObserver: 153488422 schedule check for new outgoing
09-11 13:24:57.440 8185 8993 V SMS-SmsObserver: 112625034 schedule check for new outgoing
09-11 13:24:57.440 8185 8958 V SMS-SmsObserver: 226847976 schedule check for new outgoing
09-11 13:24:57.440 8185 8214 V SMS-SmsObserver: 114100627 schedule check for new outgoing
09-11 13:24:57.458 8185 8471 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
09-11 13:24:57.473 8185 8471 D WM-SystemJobScheduler: Scheduling work ID 63b2a9ac-e421-4d40-af03-b0982156c777 Job ID 32
09-11 13:24:57.488 8185 8223 D WM-Processor: Processor cancelling 63b2a9ac-e421-4d40-af03-b0982156c777
09-11 13:24:57.488 8185 8223 D WM-Processor: WorkerWrapper could not be found for 63b2a9ac-e421-4d40-af03-b0982156c777
09-11 13:24:57.500 8185 8223 D WM-GreedyScheduler: Cancelling work ID 63b2a9ac-e421-4d40-af03-b0982156c777
09-11 13:24:57.507 8185 8223 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
09-11 13:24:57.518 8185 8223 D WM-SystemJobScheduler: Scheduling work ID cde1c6b9-96bd-45a4-937c-1d10677b9212 Job ID 33
09-11 13:24:57.536 8185 8223 D WM-Processor: Processor cancelling cde1c6b9-96bd-45a4-937c-1d10677b9212
09-11 13:24:57.537 8185 8223 D WM-Processor: WorkerWrapper could not be found for cde1c6b9-96bd-45a4-937c-1d10677b9212
09-11 13:24:57.546 8185 8223 D WM-GreedyScheduler: Cancelling work ID cde1c6b9-96bd-45a4-937c-1d10677b9212
09-11 13:24:57.557 8185 8223 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
09-11 13:24:57.566 8185 8223 D WM-SystemJobScheduler: Scheduling work ID 905fefbe-69fc-4c48-9cb8-3f91d28b48e1 Job ID 34
09-11 13:24:57.578 8185 8223 D WM-Processor: Processor cancelling 905fefbe-69fc-4c48-9cb8-3f91d28b48e1
09-11 13:24:57.578 8185 8223 D WM-Processor: WorkerWrapper could not be found for 905fefbe-69fc-4c48-9cb8-3f91d28b48e1
09-11 13:24:57.587 8185 8223 D WM-GreedyScheduler: Cancelling work ID 905fefbe-69fc-4c48-9cb8-3f91d28b48e1
09-11 13:24:57.593 8185 8223 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
09-11 13:24:57.603 8185 8223 D WM-SystemJobScheduler: Scheduling work ID 05865cce-080a-4a41-96c3-121661e4c683 Job ID 35
09-11 13:24:57.611 8185 8223 D WM-Processor: Processor stopping background work 63b2a9ac-e421-4d40-af03-b0982156c777
09-11 13:24:57.612 8185 8223 D WM-Processor: WorkerWrapper could not be found for 63b2a9ac-e421-4d40-af03-b0982156c777
09-11 13:24:57.612 8185 8223 D WM-StopWorkRunnable: StopWorkRunnable for 63b2a9ac-e421-4d40-af03-b0982156c777; Processor.stopWork = false
09-11 13:24:57.614 8185 8223 D WM-Processor: Processor stopping background work cde1c6b9-96bd-45a4-937c-1d10677b9212
09-11 13:24:57.614 8185 8223 D WM-Processor: WorkerWrapper could not be found for cde1c6b9-96bd-45a4-937c-1d10677b9212
09-11 13:24:57.614 8185 8223 D WM-StopWorkRunnable: StopWorkRunnable for cde1c6b9-96bd-45a4-937c-1d10677b9212; Processor.stopWork = false
09-11 13:24:57.617 8185 8223 D WM-Processor: Processor stopping background work 905fefbe-69fc-4c48-9cb8-3f91d28b48e1
09-11 13:24:57.617 8185 8223 D WM-Processor: WorkerWrapper could not be found for 905fefbe-69fc-4c48-9cb8-3f91d28b48e1
09-11 13:24:57.617 8185 8223 D WM-StopWorkRunnable: StopWorkRunnable for 905fefbe-69fc-4c48-9cb8-3f91d28b48e1; Processor.stopWork = false
09-11 13:24:58.574 8185 8185 D WM-DelayedWorkTracker: Scheduling work 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.575 8185 8185 D WM-GreedyScheduler: Starting work for 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.576 8185 8490 D WM-Processor: Processor: processing 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.590 8185 8185 D WM-WorkerWrapper: Starting work for com.beeper.sms.work.BackfillSentMMS
09-11 13:24:58.615 8185 8995 D SMS-ContentValues: content://mms where=(creator != 'com.beeper.sms.app' AND (msg_box = 4 OR msg_box = 2) AND date > 1631391836): 0 results
09-11 13:24:58.618 8185 8995 D SMS-BackfillSentMMS: No new messages
09-11 13:24:58.620 8185 8471 D WM-WorkerWrapper: com.beeper.sms.work.BackfillSentMMS returned a Success {mOutputData=Data {}} result.
09-11 13:24:58.623 8185 8471 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=05865cce-080a-4a41-96c3-121661e4c683, tags={ com.beeper.sms.work.BackfillSentMMS } ]
09-11 13:24:58.628 8185 8471 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver disabled
09-11 13:24:58.629 8185 8185 D WM-Processor: Processor 05865cce-080a-4a41-96c3-121661e4c683 executed; reschedule = false
09-11 13:24:58.642 8185 8471 D WM-GreedyScheduler: Cancelling work ID 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.649 8185 8490 D WM-Processor: Processor stopping background work 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.649 8185 8490 D WM-Processor: WorkerWrapper could not be found for 05865cce-080a-4a41-96c3-121661e4c683
09-11 13:24:58.649 8185 8490 D WM-StopWorkRunnable: StopWorkRunnable for 05865cce-080a-4a41-96c3-121661e4c683; Processor.stopWork = false
09-11 13:25:16.353 8185 8209 D SMS-BridgeService: [Sep 11, 2021 20:24:27] [Portal/SMS;-;+1[mynumber]/DEBUG] Starting handling Matrix message $p9UyXNmLRZllFgyYwhEhITh04b9uukH-6GaaAmMsTBE
09-11 13:25:16.362 8185 8208 D SMS-BridgeService: [Sep 11, 2021 20:25:16] [Portal/SMS;-;+1[mynumber]/DEBUG] Starting handling Matrix message $Ewsy8YW4xu5woWhKe6OQQC-wvLvxw-ZrNf4Q_CnevI0
09-11 13:25:16.376 8185 8209 D SMS-CommandProcessor: receive: SendMessage(chat_guid='SMS;-;+1[mynumber]', text='Test outgoing message')
09-11 13:25:16.380 8185 8208 D SMS-CommandProcessor: receive: SendMessage(chat_guid='SMS;-;+1[mynumber]', text='Test outgoing message again')
--------- beginning of crash
09-11 13:25:17.002 8185 8209 E AndroidRuntime: FATAL EXCEPTION: DefaultDispatcher-worker-2
09-11 13:25:17.002 8185 8209 E AndroidRuntime: Process: com.beeper.sms.app, PID: 8185
09-11 13:25:17.002 8185 8209 E AndroidRuntime: java.lang.SecurityException
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.os.Parcel.createException(Parcel.java:1950)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.os.Parcel.readException(Parcel.java:1918)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.os.Parcel.readException(Parcel.java:1868)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.android.internal.telephony.ISms$Stub$Proxy.sendTextForSubscriber(ISms.java:894)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.telephony.SmsManager.sendTextMessageInternal(SmsManager.java:380)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.telephony.SmsManager.sendTextMessage(SmsManager.java:363)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.telephony.SmsManager.sendMultipartTextMessageInternal(SmsManager.java:687)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at android.telephony.SmsManager.sendMultipartTextMessage(SmsManager.java:653)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.klinker.android.send_message.Transaction.sendSmsMessage(Transaction.java:366)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.klinker.android.send_message.Transaction.sendNewMessage(Transaction.java:159)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.SmsMmsSender.sendMessage(SmsMmsSender.kt:30)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.SmsMmsSender.sendMessage$default(SmsMmsSender.kt:16)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.CommandProcessor.handle(CommandProcessor.kt:61)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.BridgeService$onStartCommand$2$1.invoke(BridgeService.kt:57)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.BridgeService$onStartCommand$2$1.invoke(BridgeService.kt:55)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlin.io.TextStreamsKt.forEachLine(ReadWrite.kt:155)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.Bridge$Companion.forEach(Bridge.kt:150)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.Bridge$Companion.access$forEach(Bridge.kt:132)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.Bridge.forEachCommand$sms_debug(Bridge.kt:111)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.BridgeService$onStartCommand$2.invoke(BridgeService.kt:55)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.BridgeService$onStartCommand$2.invoke(BridgeService.kt:54)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at com.beeper.sms.BridgeService$restartOnInterrupt$1.invokeSuspend(BridgeService.kt:80)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
09-11 13:25:17.002 8185 8209 E AndroidRuntime: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)
09-11 13:25:17.002 8185 8209 I Process : Sending signal. PID: 8185 SIG: 9I didn't see anything that looked relevant in the Synapse logs, but I can include those too if useful.
Aerex
raxod502
2600box
[Ignore or delete this, I missed some redactions and didn't know about the "delete revision" functionality until after I posted a new message]