BlueBubblesApp / bluebubbles-server

Server for forwarding iMessages to clients within the BlueBubbles App ecosystem
https://bluebubbles.app
Apache License 2.0
554 stars 47 forks source link

Sending Replies using the REST API times out for some #616

Closed trek-boldly-go closed 9 months ago

trek-boldly-go commented 9 months ago

Hello again 👋 I am the one building the bridge between Beeper and BlueBubbles and you already helped me solve one issue before, I am grateful and need your assistance again.

For a subset of users, sending a text {{host}}/api/v1/message/text?password={{password}} times out when trying to send a reply:

{"data":{"handle":{}},"error":{"message":"Transaction timeout","type":"iMessage Error"},"message":"Message Send Error","status":500}

I have checked everything I can think of.
Server version doesn't matter Phone number vs email sending doesn't matter private-api vs apple-script doesn't matter

@jasonlaguidice got the error log out of the BlueBubbles server UI for me:

ih: [500] Message Send Error at sendText (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:244446) at async validateText (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:277093) at async /Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:286566 at async sh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:234316) at async Rh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268149) at async xh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268528) at async Ih (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:267663) at async xh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268528)

Do you know of any cases that would cause this error? Do you need more information about the request? Here is my code that is sending the message: https://github.com/mautrix/imessage/blob/1de4b891c83c7f13c28cb1c48095f479d683d816/imessage/bluebubbles/api.go#L879C1-L910C2

Many thanks 🙏

tneotia commented 9 months ago

Couple of things to confirm here, are you sending replies as in the iMessage inline replies or just a response to a text? And does the text actually go through despite it timing out? If not, does the text appear in the iMessage app at all?

trek-boldly-go commented 9 months ago

As you describe them, inline replies (or I've also seen them called threads). Regular texts send perfectly fine, but when I set the selected message guid (or whatever it's called, I'm on mobile and can't check this moment) it fails for some users with this timeout. It does not send at all, so the message is not visible in the bluebubbles clients or the official messages app.

tneotia commented 9 months ago

What macOS version are these users on? Remember that replies/threads are only supported on or after macOS 11. Users must have the private API setup to use replies. If they have a supported macOS and SIP disabled, please have them look at the logs from the dylib by doing the following:

  1. Open Mac Console app
  2. Start streaming logs
  3. Search at the top right BLUEBUBBLESHELPER
  4. Try to reply from Matrix client
  5. Observe what logs appear
trek-boldly-go commented 9 months ago

@tneotia I have asked them to check what you suggested and follow your steps.

I am not including the method (meaning apple-script vs private API) in my request body because it is listed as optional. Is the server intelligent enough to pick the right method? I'd think so because it works for some users this way. Should I build in conditional logic for the method just in case?

trek-boldly-go commented 9 months ago

A user tested this for me and this was the only logs in the console that matched the bluebubbles helper query Screenshot 2024-02-03 at 10.31.38_20240203133649.png

I believe this implies the message didn't make it to the helper and failed in the server.

tneotia commented 9 months ago

Yeah I see nothing regarding the reply. Can you have the user also share the server logs (with debug logs checked) and check the alerts tab when replying. If its easier we can troubleshoot on Discord.

jasonlaguidice commented 9 months ago

My copy of MacOS is running 13.6.3. I see the following in the console:

And my error in the BlueBubbles server log seems to be the same as stated above in the initial post for the issue.

Can you point me to the Alerts tab you mention? Additionally I'd be down to do some troubleshooting via Discord if you'd like to choose a time to work with me. I can be reached on Discord at @shadowdrake.

tneotia commented 9 months ago

The alerts tab is the notification bell in the top right of the server. @trek-boldly-go is doing some investigation in the server itself because it seems the issue does not crop up when using BB clients, which also use the REST API

zlshames commented 9 months ago

My copy of MacOS is running 13.6.3. I see the following in the console:

And my error in the BlueBubbles server log seems to be the same as stated above in the initial post for the issue.

Can you point me to the Alerts tab you mention? Additionally I'd be down to do some troubleshooting via Discord if you'd like to choose a time to work with me. I can be reached on Discord at @shadowdrake.

Hey @jasonlaguidice i had to remove the image due to PII (phone numbers). if you want to redact them and re-share, go for it. I'm wondering if it has to do with stopping sending the typing indicators, but im not sure

trek-boldly-go commented 9 months ago

Could be. I just pushed an update which added mutex locks around the request functions, that way it never sends more than one request to the server at any point in time. I'll get feedback and let you know.

jasonlaguidice commented 9 months ago

No problem on numbers - they're mine and readily reachable (work number). I can re-share if it's needed but there doesn't seem to be too much useful in the logs.

I'll test the update for mutex locks and test for results.

trek-boldly-go commented 9 months ago

@zlshames A few people have tested and don't see an improvement. I am out of ideas on what this might be or how to diagnose it. Here are the server logs for one user that it failed for with the latest update: image We can see it made it to this logger in the server: https://github.com/BlueBubblesApp/bluebubbles-server/blob/4a36b7da39c8f71adaa8717f05a8b96516fad6cc/packages/server/src/server/api/interfaces/messageInterface.ts#L86 Somewhere downstream of that line (after all the validation code has already ran and checked the incoming request looks fine) it throws this this timeout. When we opened the console and looked for BLUEBUBBLESHELPER logs, we didn't see any record of the transaction, so it may not have made it to the helper. Beyond that, I don't know. What else should we check or try? Maybe disable typing notifications completely to eliminate the typing cache from being a possibility?

wastingoctober commented 9 months ago

What macOS version are these users on? Remember that replies/threads are only supported on or after macOS 11. Users must have the private API setup to use replies. If they have a supported macOS and SIP disabled, please have them look at the logs from the dylib by doing the following:

  1. Open Mac Console app
  2. Start streaming logs
  3. Search at the top right BLUEBUBBLESHELPER
  4. Try to reply from Matrix client
  5. Observe what logs appear

I'm one of the affected users. I've got an interesting one here. One that worked (first one), and one that didn't work (second one).

[2024-02-05 15:50:45.193] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing (URL Params: {}) [2024-02-05 15:50:45.195] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing took 2 ms [2024-02-05 15:50:46.422] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing (URL Params: {}) [2024-02-05 15:50:46.422] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing took 0 ms [2024-02-05 15:50:46.712] [debug] Request to /api/v1/message/text (URL Params: {}) [2024-02-05 15:50:46.712] [debug] Sending message "Reply" to iMessage;-;+<PHONENUMBERREDACTED> [2024-02-05 15:50:46.712] [info] Adding await for chat: "iMessage;-;+<PHONENUMBERREDACTED>"; text: Reply; tempGuid: temp-HgOCXCHA [2024-02-05 15:50:46.717] [info] Request to /api/v1/message/text took 5 ms [2024-02-05 15:50:47.127] [info] Message match found for text, ["Reply"; Date: 2/5/2024, 3:50:46 PM] [2024-02-05 15:50:47.128] [info] New Message from You, "Reply"; Date: 2/5/2024, 3:50:46 PM [2024-02-05 15:50:47.128] [debug] Sending FCM notification (Priority: normal) to 1 device(s) [2024-02-05 15:50:47.129] [debug] Sending FCM notification (Priority: normal) to 1 device(s) [2024-02-05 15:50:49.644] [info] New message from [+<PHONENUMBERREDACTED>]: ["Reply"; Date: 2/5/2024, 3:50:46 PM] [2024-02-05 15:50:49.645] [debug] Sending FCM notification (Priority: high) to 1 device(s) [2024-02-05 15:50:50.135] [info] Updated message from [You]: ["Reply"; Date: 2/5/2024, 3:50:46 PM] - [Text Read -> 2/5/2024, 3:50:48 PM] [2024-02-05 15:50:50.136] [debug] Sending FCM notification (Priority: normal) to 1 device(s) [2024-02-05 15:50:50.384] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/read (URL Params: {}) [2024-02-05 15:50:50.384] [debug] Sending FCM notification (Priority: normal) to 1 device(s) [2024-02-05 15:50:50.385] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED> (URL Params: {"with":"participants,lastMessage"}) [2024-02-05 15:50:50.389] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED> took 4 ms [2024-02-05 15:50:50.391] [debug] Request to /api/v1/message/D91D24FD-7550-4460-90B9-A823803A78C6 (URL Params: {"with":"chats"}) [2024-02-05 15:50:50.392] [info] Request to /api/v1/message/D91D24FD-7550-4460-90B9-A823803A78C6 took 2 ms [2024-02-05 15:50:50.526] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/read took 142 ms [2024-02-05 15:50:54.103] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing (URL Params: {}) [2024-02-05 15:50:54.104] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing took 1 ms [2024-02-05 15:50:57.738] [debug] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing (URL Params: {}) [2024-02-05 15:50:57.739] [info] Request to /api/v1/chat/iMessage;-;+<PHONENUMBERREDACTED>/typing took 1 ms [2024-02-05 15:50:57.975] [debug] Request to /api/v1/message/text (URL Params: {}) [2024-02-05 15:50:57.975] [debug] Sending message "Reply #2 (1 worked)" to iMessage;-;+<PHONENUMBERREDACTED> [2024-02-05 15:50:57.975] [info] Adding await for chat: "iMessage;-;+<PHONENUMBERREDACTED>"; text: Reply21worked; tempGuid: temp-vSrvKWNd [2024-02-05 15:52:57.981] [debug] Raw Error: ih: [500] Message Send Error [2024-02-05 15:52:57.982] [debug] API Error: [500] Message Send Error -> Transaction timeout [2024-02-05 15:52:57.982] [debug] ih: [500] Message Send Error at sendText (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:244446) at async validateText (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:277093) at async /Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:286566 at async sh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:234316) at async Rh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268149) at async xh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268528) at async Ih (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:267663) at async xh (/Applications/BlueBubbles.app/Contents/Resources/app.asar/dist/main.js:1:268528) [2024-02-05 15:52:57.982] [info] Request to /api/v1/message/text took 120007 ms

trek-boldly-go commented 9 months ago

A third user's logs from Bluebubbles just for good measure: https://pastebin.com/qwtV4D3F

They all make it to the same logger in the server, successfully passing all the validation, then get this error. 🤷‍♂️

jasonlaguidice commented 9 months ago

Confirming +1 more for the issue. I had one send successfully and one right behind it (to a different chat) fail. My logs look exactly like these others. There doesn't seem to be any logged information related to the failure.

zlshames commented 9 months ago

Hey @trek-boldly-go I have a couple of questions:

  1. Is this with the Private API enabled or disabled? You said it doesn't matter, so I assume you were able to reproduce the issue in either case? I just want to make it 100% clear
    • I would expect the outcome to be different for the Private API but maybe the bug is elsewhere. And identifying that may be useful
    • Also, replies are only available via the Private API. So if you are sending "apple-script", but providing private-api parameters (i.e. reply stuff), it will assume the method is private-api and switch it automatically.
  2. Does this happen randomly, or does it happen when sending texts rapidly?
  3. Does this only happen for replies? Or regular texts also have this issue?
trek-boldly-go commented 9 months ago

@zlshames

  1. All these users have private API enabled and I even remoted into one of their computers to check it looked correct. I said it happens either way, but what I meant was, it doesn't matter what method I set in the body of the request, the result is the same. Makes sense after looking at your server code, because even setting apple-script in the body would be overwrote by the server once it checks the selectedMessageGuid is populated.
  2. I had to send a lot of replies very fast to trigger this, but lots of these users can let it idle for a long time (with no requests to the server) then send a reply which has this error.
  3. For a bit, I tried to have my code take advantage of the private-api method to send regular texts as well, but then a bunch of those same users couldn't even send a regular text. So the short answer is I think it happens for both, but I changed my code back to only use the private-api if there is a reply.
zlshames commented 9 months ago

had to send a lot of replies very fast to trigger this, but lots of these users can let it idle for a long time (with no requests to the server) then send a reply which has this error.

You're saying the user couldn't send any regular texts? or sometimes after idle, when they send a text, just that one won't go through?

I know I'm asking super specific questions, but they matter and will help figure out where the issue is.

If the user can't send any regular texts, I would say maybe their account is marked as Spam or being blocked in some kind of way. If they can send texts, but every once in a while, it errors out, then that's an issue. Not one that I've run into though.

Follow-up... if you do get a Transaction Timeout error, does the message still go through, or does it not go through?

trek-boldly-go commented 9 months ago

I am saying they could send texts using the BlueBubbles app and the official Messages app, but sending the HTTP request from the bridge was getting the errors we showed above. My comment about being idle was to show that it isn't some kind of overloading causing it.

No worries on the specificity, we want to get this fixed and that starts with understanding what is happening.

They aren't banned, because they can still send messages over apple-script or using your apps or using the official app.

The message does not go through when we get this timeout. As I said above, when monitoring the BLUEBUBBLESHELPER in the console app, there is no record that this message ever tried to send. The server has the logs we provided, but the helper says nothing (other than typing indicators).

zlshames commented 9 months ago

I am saying they could send texts using the BlueBubbles app and the official Messages app, but sending the HTTP request from the bridge was getting the errors we showed above. My comment about being idle was to show that it isn't some kind of overloading causing it.

No worries on the specificity, we want to get this fixed and that starts with understanding what is happening.

They aren't banned, because they can still send messages over apple-script or using your apps or using the official app.

The message does not go through when we get this timeout. As I said above, when monitoring the BLUEBUBBLESHELPER in the console app, there is no record that this message ever tried to send. The server has the logs we provided, but the helper says nothing (other than typing indicators).

I know you've already shared the code that sends the message (that's failing), but do you mind sending me the actual POST body payload of a request that fails? I want to see if it's reproducible, or if there are any issues that I may notice in it.

Thanks!

wrobm2 commented 9 months ago

I have been having this problem with the beeper bluebubbles bridge, and just got it with the normal ( desktop ) bluebubbles app. I followed the dockerosx bluebubbles tutorial here: https://docs.bluebubbles.app/server/advanced/macos-virtualization/running-bluebubbles-in-docker-osx

Replies usually work for me on the bluebubbles app, and work much less consistently on the beeper bridge, and this is the only time I have had it fail, but it looks like the same issue. I sent 10 replies ( to my own icloud email ) afterward to test and could not get it to fail again.

image

here is the message info associated with that message : { "ROWID": 10557, "originalROWID": null, "guid": "error-{status: 500, error: {type: timeout, error: Failed to receive response from server.}}-Ww1UKdVY", "handleId": 0, "otherHandle": null, "text": "the flu has been sucky but i feel like the suckier part is gonna be making up the missed school", "subject": "", "country": null, "_error": 0, "dateCreated": "February 6, 2024 4:23:17 PM", "dateRead": null, "dateDelivered": null, "isFromMe": true, "hasDdResults": true, "datePlayed": null, "itemType": 0, "groupTitle": null, "groupActionType": 0, "balloonBundleId": null, "associatedMessageGuid": null, "associatedMessagePart": null, "associatedMessageType": null, "expressiveSendStyleId": null, "handle": null, "hasAttachments": false, "hasReactions": false, "dateDeleted": null, "metadata": "{}", "threadOriginatorGuid": "904D22F8-4DF1-4797-8494-8ACAEF725252", "threadOriginatorPart": "0:0:0", "hasApplePayloadData": false, "dateEdited": null, "wasDeliveredQuietly": false, "didNotifyRecipient": false, "isBookmarked": false, "attachments": [], "attributedBody": [], "messageSummaryInfo": [], "payloadData": null }

here is the snippet of my bluebubbles realtime log file from when it happened: [BlueBubblesApp][2024-02-06 16:11:59.031069][INFO] Received typing-indicator from socket [BlueBubblesApp][2024-02-06 16:12:04.107226][ERROR] (ERROR[null]) -> PATH: https://myserverlinkcensored [BlueBubblesApp][2024-02-06 16:12:04.107328][ERROR] (ERROR[null]) -> null [BlueBubblesApp][2024-02-06 16:12:04.107369][ERROR] (ERROR[null]) -> application/json [BlueBubblesApp][2024-02-06 16:12:04.107409][ERROR] (ERROR[null]) -> null [BlueBubblesApp][2024-02-06 16:12:04.107496][ERROR] Failed to send message! Error: {"status":500,"error":{"type":"timeout","error":"Failed to receive response from server."}}

Worked just like the beeper bridge one did. I sent a reply, the reply didn't work, and the messages after the reply had to wait until the reply timed out before they could be sent.

LMK if there are other logs needed!

Edit: I am also on macos 13.6.3

zlshames commented 9 months ago

I have been having this problem with the beeper bluebubbles bridge, and just got it with the normal ( desktop ) bluebubbles app. I followed the dockerosx bluebubbles tutorial here: https://docs.bluebubbles.app/server/advanced/macos-virtualization/running-bluebubbles-in-docker-osx

Replies usually work for me on the bluebubbles app, and work much less consistently on the beeper bridge, and this is the only time I have had it fail, but it looks like the same issue. I sent 10 replies ( to my own icloud email ) afterward to test and could not get it to fail again.

image

here is the message info associated with that message : { "ROWID": 10557, "originalROWID": null, "guid": "error-{status: 500, error: {type: timeout, error: Failed to receive response from server.}}-Ww1UKdVY", "handleId": 0, "otherHandle": null, "text": "the flu has been sucky but i feel like the suckier part is gonna be making up the missed school", "subject": "", "country": null, "_error": 0, "dateCreated": "February 6, 2024 4:23:17 PM", "dateRead": null, "dateDelivered": null, "isFromMe": true, "hasDdResults": true, "datePlayed": null, "itemType": 0, "groupTitle": null, "groupActionType": 0, "balloonBundleId": null, "associatedMessageGuid": null, "associatedMessagePart": null, "associatedMessageType": null, "expressiveSendStyleId": null, "handle": null, "hasAttachments": false, "hasReactions": false, "dateDeleted": null, "metadata": "{}", "threadOriginatorGuid": "904D22F8-4DF1-4797-8494-8ACAEF725252", "threadOriginatorPart": "0:0:0", "hasApplePayloadData": false, "dateEdited": null, "wasDeliveredQuietly": false, "didNotifyRecipient": false, "isBookmarked": false, "attachments": [], "attributedBody": [], "messageSummaryInfo": [], "payloadData": null }

here is the snippet of my bluebubbles realtime log file from when it happened: [BlueBubblesApp][2024-02-06 16:11:59.031069][INFO] Received typing-indicator from socket [BlueBubblesApp][2024-02-06 16:12:04.107226][ERROR] (ERROR[null]) -> PATH: https://myserverlinkcensored [BlueBubblesApp][2024-02-06 16:12:04.107328][ERROR] (ERROR[null]) -> null [BlueBubblesApp][2024-02-06 16:12:04.107369][ERROR] (ERROR[null]) -> application/json [BlueBubblesApp][2024-02-06 16:12:04.107409][ERROR] (ERROR[null]) -> null [BlueBubblesApp][2024-02-06 16:12:04.107496][ERROR] Failed to send message! Error: {"status":500,"error":{"type":"timeout","error":"Failed to receive response from server."}}

Worked just like the beeper bridge one did. I sent a reply, the reply didn't work, and the messages after the reply had to wait until the reply timed out before they could be sent.

LMK if there are other logs needed!

Edit: I am also on macos 13.6.3

Just to be 100% sure, when it failed to send, did it send in the iMessage app on the Mac, only erroring in the BB app? Or did it not send in either?

Also, what macOS version are you using? Trying to figure out if there is a trend in the occurrences.

Typically when I have this error, it still sends on the Mac, I just get an error cuz my Mac is slow.

Any chance you could also grab your server logs for when the message failed to send? I wanna see what happened on the server side

zlshames commented 9 months ago

I am saying they could send texts using the BlueBubbles app and the official Messages app, but sending the HTTP request from the bridge was getting the errors we showed above. My comment about being idle was to show that it isn't some kind of overloading causing it.

No worries on the specificity, we want to get this fixed and that starts with understanding what is happening.

They aren't banned, because they can still send messages over apple-script or using your apps or using the official app.

The message does not go through when we get this timeout. As I said above, when monitoring the BLUEBUBBLESHELPER in the console app, there is no record that this message ever tried to send. The server has the logs we provided, but the helper says nothing (other than typing indicators).

If this is easily reproducible, I wouldn't be opposed to building a "debug" build of the server with lots of (unnecessary) logging to see exactly where it fails

trek-boldly-go commented 9 months ago

If this is easily reproducible, I wouldn't be opposed to building a "debug" build of the server with lots of (unnecessary) logging to see exactly where it fails

@zlshames Plenty of users of the bridge are seeing this error and want it fixed. I promise at least one user would run a debug build so we can fix it.

wrobm2 commented 9 months ago

I'm on macos 13.6.3.

The message did not send in imessage, only showed up and only errored in BB.

I was looking for that message and found a bunch of other ( non reply ) messages that did the same thing... not sure what thats about. * this is a new issue. I have been using bluebubbles for atleast a year and had not ever had this problem ( on the bluebubbles official apps ).

my mac should be fast enough that message sending speed shouldn't be a problem for it. ( it is a VM on a pretty capable computer. )

I don't really know how to find full server logs, I only see the recent logs in the app, and am not really sure where the file is stored. If you wanna remote into my mac though I am very open to that ( you can also probably debug better that way ) ( i am the guy trek-boldly-go remoted into ). LMK and ill message you on discord.

wrobm2 commented 9 months ago

I also would be down to run a debug build of the server.

zlshames commented 9 months ago

I also would be down to run a debug build of the server.

I'll make a build with additional logging and share it here

wrobm2 commented 9 months ago

found the server log file and found a timestamp of one of them in server logs image

zlshames commented 9 months ago

Alright, so below is the current beta for v1.9.5 + additional logging. This can be installed alongside the stable build, but just can't be ran at the same time.

https://drive.google.com/file/d/17AT_cbnP8erAsZcVoBT4vcQu8USzWv6X/view?usp=sharing

I added a bunch more logging right after the Adding await for chat: "${chatGuid}"; text: ${text}; tempGuid: ${tempGuid} log. You should see the following logs when sending a message now:

Adding await for chat: "${chatGuid}"; text: ${text}; tempGuid: ${tempGuid}
Stopping typing for chat: ${chatGuid}
Sending message via the Private API
Creating transaction promise for outgoing message...
Passing data to Private API Helper: ${json_data}
Message passed to the Private API... awaiting results
Returning from MessageInterface.sendMessagePrivateApi()
Message sent using the Private API

If the logging stops before any of the above messages, it's failing silently somewhere. And hopefully I can identify where based on the logs.

To properly test this do the following:

  1. Open the debug server and navigate to the Debug/Logs page
  2. Enable Debug Logs
  3. Open the Console App
  4. In the search bar of the Console app, search BLUEBUBBLESHELPER and hit enter
  5. Clear, then start streaming logs in the Console app
  6. Try reproducing the issue

If you are able to reproduce the issue, check your server logs at the time of the error and look for the new logging I added. Also, grab/copy the logs from the Console app for the Private API helper. Essentially, we need to corroborate the logs from the server with the Console app to see if one, the server sends the message to the Private API Helper, and two, if the Private API helper receives the message. If the server logs scroll by too fast, you can use the Manage -> Open Log Location button to get the raw log file.

If the Private API does receive the message, but the message isn't sent, the issue lies somewhere in the Private API helper is my guess.

Happy testing :) and good luck

wrobm2 commented 9 months ago

on 1.9.5 server beta: here is the log for sending from the beeper bridge: image ( it says received findmy location a bunch so im skipping over those ) and then : image

here is another screenshot of a different reply sent from the beeper bridge: image

image

so its getting stuck on the passing of data to the private api helper. neither message showed up at all in the logs in Console when searching for BLUEBUBBLESHELPER. I got the stuff saying im typing and that ive stopped typing, but other than that it was just a whole ton of geolocations for find my.

here is a screenshot of a normal message sent through bluebubbles successfully going through ( to prove messages CAN go through ) : image

and here is a screenshot of a normal reply sent through bluebubbles going through: image

I didnt have it consistently failing with bluebubbles clients themselves, that was a rare thing, but now that i have debug logs enabled I will be watching out for the next time i get one of those. Sent about 20 messages to myself ( replies, images, normal messages ) and none of them errored on Bluebubbles

please let me know if you'd be interested in just doing remote desktop onto my mac ( through web vnc ) .

zlshames commented 9 months ago

on 1.9.5 server beta: here is the log for sending from the beeper bridge: image ( it says received findmy location a bunch so im skipping over those ) and then : image

here is another screenshot of a different reply sent from the beeper bridge: image

image

so its getting stuck on the passing of data to the private api helper. neither message showed up at all in the logs in Console when searching for BLUEBUBBLESHELPER. I got the stuff saying im typing and that ive stopped typing, but other than that it was just a whole ton of geolocations for find my.

here is a screenshot of a normal message sent through bluebubbles successfully going through ( to prove messages CAN go through ) : image

and here is a screenshot of a normal reply sent through bluebubbles going through: image

I didnt have it consistently failing with bluebubbles clients themselves, that was a rare thing, but now that i have debug logs enabled I will be watching out for the next time i get one of those. Sent about 20 messages to myself ( replies, images, normal messages ) and none of them errored on Bluebubbles

please let me know if you'd be interested in just doing remote desktop onto my mac ( through web vnc ) .

Next thing I'm going to check is if the "stopped typing" call is somehow interfering with the Private API helper communications. So I'll remove that line of code temporarily to see if that has an effect. Build incoming shortly.

zlshames commented 9 months ago

@wrobm2 give this build a try to see if you can reproduce the issue: https://drive.google.com/file/d/1mZxP9enRUjWIQov-Jqc1OVEruo8tvQaN/view?usp=sharing

(I removed the stopped typing papi call)

wrobm2 commented 9 months ago

I have sent a total of 25 replies now ( to my own icloud email ) through the beeper bridge, with not a single one failing. before the rate was around 75% of my replies would fail. I will update if I do get a reply to fail but this looks like it is working flawlessly. The problem being in the stopped typing call is incredibly confusing to me.

wastingoctober commented 9 months ago

@zlshames after reading the positive feedback from @wrobm2, I installed that build as well. Exact same experience. Replies are working perfectly now. Thanks so much!

zlshames commented 9 months ago

@wrobm2 @rushinburrito ok guys, this should (hopefully) be the last test build. I've introduced a semaphore lock on the write function that sends messages to the Private API Helper. I've now re-introduced the "stopped typing" call as well. My hope is that it all just works. Otherwise, my initial assumption that there is some interference when writing might be incorrect.

Try it out: https://drive.google.com/file/d/1Efely-YpCZZuKmdclzckANwtTNVDmEup/view?usp=sharing

Oh, and let me know if you notice if things are slower. They shouldn't be but who knows

wrobm2 commented 9 months ago

On this build, replies still mostly worked. Certainly worked more often than they did before. I could still get it to fail if i sent enough replies in quick succession. ( I sent like 6 replies and they worked and then I sent another 3 in a row and the first 1 of that 3 failed and that failed the rest of them ( this happened in a span of maybe 20 seconds ) )

I guess i could maybe see things being slower, but really things are still going at an a-ok speed. I can't really tell if things are actually slower cause i wasnt paying enough attention to their speed before. I could run the other build and start timing the messages i guess, but it really seems like this speed is fine.

zlshames commented 9 months ago

On this build, replies still mostly worked. Certainly worked more often than they did before. I could still get it to fail if i sent enough replies in quick succession. ( I sent like 6 replies and they worked and then I sent another 3 in a row and the first 1 of that 3 failed and that failed the rest of them ( this happened in a span of maybe 20 seconds ) )

I guess i could maybe see things being slower, but really things are still going at an a-ok speed. I can't really tell if things are actually slower cause i wasnt paying enough attention to their speed before. I could run the other build and start timing the messages i guess, but it really seems like this speed is fine.

hmmm, in the case when it failed... can you try again and check the Console app to see if the private API helper got it? I'm wondering if i should add like an artificial 100ms delay or something. I'm not sure why it would still fail even with the semaphore lock.

What could be happening now is that the server is done writing data, but the Private API bundle isn't done reading the data, and as a result, still combines with a different request's data. Makes sense it would happen less often too if that's the case. Definitely seems a bit like a race case

wrobm2 commented 9 months ago

messaging you the log on discord because i do not want to censor every time my icloud email shows up in this

zlshames commented 9 months ago

Looks like we've solved it. The semaphore lock should fix the issue in 95% of cases. The artificial lock release delay will account for the other 4% of cases. And unless someone is consistently spamming the API, that final 1% should rarely cause an issue. Code pushed to the development branch

trek-boldly-go commented 9 months ago

@zlshames Great news! I'd like to let everyone else know how to install the version that includes this fix. Is the development branch generating an installer they can use until it is released for real?

zlshames commented 9 months ago

@zlshames Great news! I'd like to let everyone else know how to install the version that includes this fix. Is the development branch generating an installer they can use until it is released for real?

I would just wait till the release is official. Will be today or tomorrow I think