Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Error reading from websocket: websocket: close 1006 (abnormal closure): unexpected EOF #5

Open
cincodenada opened this issue Sep 11, 2021 · 6 comments · May be fixed by mautrix/imessage#90

Comments

@cincodenada
Copy link

cincodenada commented Sep 11, 2021

[Ignore or delete this, I missed some redactions and didn't know about the "delete revision" functionality until after I posted a new message]

@cincodenada
Copy link
Author

cincodenada commented Sep 11, 2021

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: false

SMS 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-constants

My 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 imessage

And 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: 9

I didn't see anything that looked relevant in the Synapse logs, but I can include those too if useful.

@Aerex
Copy link

Aerex commented Mar 17, 2022

Were you able to get your stuff working? I noticed the error error requesting syncproxy stop after imessage disconnected: M_NOT_FOUND: No appservice found with that ID you can try and check if your registration.yaml has the same id value as the one in your config.yaml

Also, I would strongly suggest removing any references to ipv6 such as listen [::]:443 ssl; # managed by Certbot and changing the proxy_pass http://localhost:29331 to proxy_pass http://127.0.01:29331;

@raxod502
Copy link

raxod502 commented Sep 4, 2022

I experience this problem as well. Incoming messages seem ok so far, but when I try to send a message from Element in a bridge-controlled channel, I get the error in the report above.

wsproxy logs
mautrix-wsproxy      | 2022/09/03 21:25:58 Found one appservice from environment variables
mautrix-wsproxy      | 2022/09/03 21:25:58 Starting to listen on :29331                                                                                                                       
mautrix-wsproxy      | 2022/09/03 23:28:29 imessage connected to websocket     
mautrix-wsproxy      | 2022/09/03 23:28:29 Unknown command bridge_status in request #0 from websocket. Data: {"state_event":"CONNECTED","timestamp":1662247708,"ttl":600,"source":"bridge","us
er_id":"@raxod502:intuitiveexplanations.com"}                                                  
mautrix-wsproxy      | 2022/09/03 23:28:54 Error reading from websocket: websocket: close 1006 (abnormal closure): unexpected EOF                                                             mautrix-wsproxy      | 2022/09/03 23:28:54 imessage disconnected from websocket
mautrix-wsproxy      | 2022/09/03 23:28:54 Error requesting syncproxy stop after imessage disconnected: M_NOT_FOUND: No appservice found with that ID
appservice registration
# appservice -> id from the config
id: imessage
# appservice -> as_token and hs_token from the config
as_token: "redacted"
hs_token: "redacted"
namespaces:
  users:
    # The localpart here is username_template from the config, but .+ instead of {{.}}
    - regex: '@sms_.+:intuitiveexplanations\.com'
      exclusive: true
    # Localpart here is appservice -> bot -> username from the config
    - regex: '@smsbot:intuitiveexplanations\.com'
      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: false
wsproxy and syncproxy docker-compose file
version: "3.7"

services:
  mautrix-wsproxy:
    container_name: mautrix-wsproxy
    image: dock.mau.dev/mautrix/wsproxy
    restart: unless-stopped
    ports:
      - 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://syncproxy:redacted@matrix-postgres:5432/syncproxy
      HOMESERVER_URL: http://localhost:8008
      SHARED_SECRET: "redacted"

networks:
  default:
    name: matrix
    external: true
Ansible configuration
matrix_domain: intuitiveexplanations.com
matrix_homeserver_implementation: synapse
matrix_homeserver_generic_secret_key: 'redacted'
matrix_ssl_lets_encrypt_support_email: 'radon@intuitiveexplanations.com'
matrix_postgres_connection_password: 'redacted'

matrix_synapse_container_extra_arguments:
  ["-v", "/etc/synapse-custom:/etc/synapse-custom:ro"]

matrix_synapse_app_service_config_files:
  - /etc/synapse-custom/mautrix-imessage-registration.yaml

matrix_postgres_additional_databases:
  - name: syncproxy
    username: syncproxy
    password: "redacted"

matrix_synapse_ext_password_provider_shared_secret_auth_enabled: true
matrix_synapse_ext_password_provider_shared_secret_auth_shared_secret: "redacted"

matrix_nginx_proxy_container_extra_arguments:
  ["-p", "29333:29333"]

matrix_nginx_proxy_proxy_http_additional_server_configuration_blocks:
  - |
    server {
      listen 29333 ssl http2;

      server_name matrix.intuitiveexplanations.com;

      server_tokens off;
      root /dev/null;

      ssl_certificate /matrix/ssl/config/live/matrix.intuitiveexplanations.com/fullchain.pem;
      ssl_certificate_key /matrix/ssl/config/live/matrix.intuitiveexplanations.com/privkey.pem;

      ssl_protocols TLSv1.2 TLSv1.3;
      ssl_ciphers ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384;
      ssl_prefer_server_ciphers off;

      ssl_stapling on;
      ssl_stapling_verify on;
      ssl_trusted_certificate /matrix/ssl/config/live/matrix.intuitiveexplanations.com/chain.pem;

      ssl_session_tickets off;
      ssl_session_cache shared:MozSSL:10m;
      ssl_session_timeout 1d;

      add_header Strict-Transport-Security "max-age=31536000; includeSubDomains" always;

      location / {
        set $backend "mautrix-wsproxy:29331";
        proxy_pass http://$backend;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "Upgrade";
        proxy_set_header Host $host;
        proxy_set_header X-Forwarded-For $remote_addr;
      }
    }
android-sms config
homeserver:
    address: https://matrix.intuitiveexplanations.com
    websocket_proxy: wss://matrix.intuitiveexplanations.com:29333
    domain: intuitiveexplanations.com
    async_media: false

appservice:
    database: /data/user/0/com.beeper.sms.app/mautrix-imessage.db
    id: imessage
    bot:
        username: smsbot
        displayname: Android SMS bridge bot
        avatar: mxc://maunium.net/tManJEpANASZvDVzvRvhILdX
    ephemeral_events: false
    as_token: "redacted"
    hs_token: "redacted"

imessage:
    platform: android

bridge:
    user: "@raxod502:intuitiveexplanations.com"
    username_template: sms_{{.}}
    displayname_template: "{{.}} (iMessage)"
    personal_filtering_spaces: false
    delivery_receipts: false
    message_status_events: true
    send_error_notices: true
    max_handle_seconds: 0
    sync_with_custom_puppets: false
    sync_direct_chat_list: false
    login_shared_secret: "redacted"
    double_puppet_server_url: null
    chat_sync_max_age: 0.5
    initial_backfill_limit: 100
    initial_backfill_disable_notifications: true
    periodic_sync: true
    find_portals_if_db_empty: false
    media_viewer_url: null
    media_viewer_sms_min_size: 409600
    media_viewer_imessage_min_size: 52428800
    convert_heif: true
    convert_video:
        enabled: false
        ffmpeg_args: ["-c:v", "libx264", "-preset", "faster", "-crf", "22", "-c:a", "copy"]
        extension: "mp4"
        mime_type: "video/mp4"
    command_prefix: "!im"
    federate_rooms: true
    encryption:
        allow: true
        default: true
        appservice: false
        key_sharing:
            allow: false
            require_cross_signing: false
            require_verification: true
    relay:
        enabled: false
        whitelist: []
        message_formats:
            m.text: "{{ .Sender.Displayname }}: {{ .Message }}"
            m.notice: "{{ .Sender.Displayname }}: {{ .Message }}"
            m.emote: "* {{ .Sender.Displayname }} {{ .Message }}"
            m.file: "{{ .Sender.Displayname }} sent a file: {{ .FileName }}"
            m.image: "{{ .Sender.Displayname }} sent an image: {{ .FileName }}"
            m.audio: "{{ .Sender.Displayname }} sent an audio file: {{ .FileName }}"
            m.video: "{{ .Sender.Displayname }} sent a video: {{ .FileName }}"

logging:
    directory: /data/user/0/com.beeper.sms.app/logs
    file_name_format: "{{.Date}}-{{.Index}}.log"
    file_date_format: 2006-01-02
    file_mode: 0600
    timestamp_format: Jan _2, 2006 15:04:05
    print_level: debug
adb logs when attempting to send message

Message is sent a few seconds after 17:22:23.666, no logs appear until 10-15 seconds later when websocket error shows up at 17:22:47.077 and triggers reconnect

09-03 17:21:51.153 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:21:51] [INFO] Startup sync complete
09-03 17:22:20.821 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:20] [Crypto/Bot/DEBUG] req #17: GET https://matrix.intuitiveexplanations.com/_matrix/client/v3/sync?filter=0&since=s485_245_6_17_65_7_42_11_0&timeout=30000
09-03 17:22:20.874 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:20] [Crypto/Bot/DEBUG] req #18: GET https://matrix.intuitiveexplanations.com/_matrix/client/v3/sync?filter=0&since=s485_247_6_17_65_7_42_11_0&timeout=30000
09-03 17:22:23.644 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:23] [Crypto/DEBUG] Handling encrypted to-device event from @raxod502:intuitiveexplanations.com/PKnncXyCcsEyJd1QJJlvoGsrBoB8D84j8TRsQeYHFm8 (trace: 00:22:23.642455)
09-03 17:22:23.666 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:23] [Crypto/DEBUG] Received inbound group session !QTUDxWGOfRJSwthmZt:intuitiveexplanations.com / PKnncXyCcsEyJd1QJJlvoGsrBoB8D84j8TRsQeYHFm8 / QMVeho0xHHM/Kw2FB19R7RA6rLerkaoq3gdCzq3+Xds
09-03 17:22:23.666 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:23] [Crypto/Bot/DEBUG] req #19: GET https://matrix.intuitiveexplanations.com/_matrix/client/v3/sync?filter=0&since=s485_247_7_17_65_7_43_11_0&timeout=30000
09-03 17:22:47.077 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:47] [Matrix/DEBUG] Error reading from websocket: websocket: close 1006 (abnormal closure): unexpected EOF
09-03 17:22:47.078 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:47] [INFO] Websocket disconnected, reconnecting in 4 seconds...
09-03 17:22:47.078 31853 31875 E SMS-BridgeService: [Sep  4, 2022 00:22:47] [ERROR] Error in appservice websocket: websocket: close 1006 (abnormal closure): unexpected EOF
09-03 17:22:51.245 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:51] [Matrix/DEBUG] Appservice transaction websocket connected
09-03 17:22:51.245 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:51] [DEBUG] Sending bridge status to server
09-03 17:22:51.246 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:51] [Matrix/DEBUG] Starting handling of transaction  ()
09-03 17:22:53.746 31853 31876 D SMS-BridgeService: [Sep  4, 2022 00:22:53] [Crypto/Bot/DEBUG] req #20: GET https://matrix.intuitiveexplanations.com/_matrix/client/v3/sync?filter=0&since=s486_247_8_17_65_7_43_11_0&timeout=30000

I'll update this thread if I find a resolution. (I already went through the suggestions in #5 (comment) and no luck.)

@raxod502
Copy link

raxod502 commented Sep 4, 2022

Solved, the following appservice registration config was wrong:

# Address that Synapse uses to contact mautrix-wsproxy
url: "http://localhost:29331"

As can be verified by attempting to reach the address from within the synapse container:

admin@spensa:~/files/matrix-docker-ansible-deploy$ sudo docker exec -it matrix-synapse curl http://localhost:29331
curl: (7) Failed to connect to localhost port 29331: Connection refused

While based on my docker-compose configuration, I should be using the following instead:

# Address that Synapse uses to contact mautrix-wsproxy
url: "http://mautrix-wsproxy:29331"

Which does work:

admin@spensa:~/files/matrix-docker-ansible-deploy$ sudo docker exec -it matrix-synapse curl http://mautrix-wsproxy:29331
404 page not found

After making the change to that config file (which I have bind-mounted into the synapse container via matrix_synapse_container_extra_arguments) and restarting synapse, messages immediately started sending properly. Bless 🙏

This will likely resolve your issue as well @cincodenada

@raxod502
Copy link

I've filed a PR at mautrix/imessage#90 to improve the documentation and avoid future confusion around this issue.

@2600box
Copy link

2600box commented Apr 11, 2023

I have this issue too, and have not been able to resolve it... It seems to be working despite the errors.

If I try to enable end to end encryption, I have 502 errors like this issue: mautrix/imessage#93

I get repeating errors:

2023/04/11 16:54:07 imessage disconnected from websocket
2023/04/11 16:54:07 Error requesting websocket stop after imessage disconnected: M_NOT_FOUND: No appservice found with that ID
2023/04/11 16:54:09 imessage connected to websocket
2023-04-11T16:59:11+02:00 DBG Appservice transaction websocket opened
2023-04-11T16:59:11+02:00 DBG Starting handling of transaction content={"pdu":0} req_id=0 ws_command=
2023-04-11T16:59:11+02:00 DBG Finished dispatching events from transaction req_id=0 ws_command=
2023-04-11T16:59:11+02:00 DBG Sending bridge status to server: {StateEvent:CONNECTED Timestamp:0 TTL:0 Source: Error: Message: UserID: RemoteID:unknown RemoteName: Info:map[]}
2023-04-11T16:59:11+02:00 DBG Sent response to transaction req_id=0 ws_command=
2023-04-11T17:04:11+02:00 DBG Error reading from websocket error="websocket: close 1006 (abnormal closure): unexpected EOF"
2023-04-11T17:04:11+02:00 ERR Error in appservice websocket: websocket: close 1006 (abnormal closure): unexpected EOF
2023-04-11T17:04:11+02:00 INF Websocket disconnected, reconnecting in 2 seconds...

Any ideas? I am not using docker.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging a pull request may close this issue.

4 participants