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

PT10 - Websockets get disconnected #1419

Open
roopa0222 opened this issue Jan 7, 2025 · 1 comment
Open

PT10 - Websockets get disconnected #1419

roopa0222 opened this issue Jan 7, 2025 · 1 comment
Labels
bug Something isn't working

Comments

@roopa0222
Copy link

Describe the bug
I noticed this when working with PT10, the WebSockets get disconnected silently. The application does not work as it should and the user is not aware of it. The application needs to be restarted to work normal

To Reproduce
Steps to reproduce the behavior:

  1. Have the PT10 application up and running for a while.
  2. The disconnect happens randomly I am not aware any known trigger.
  3. If the application is not working as it should, check the logs for below messages.
[2025-01-07 13:34:17.307] [info]  [extension host] 13:34:17.306 > Fetched from UPDATED EXTENSIONS! [at C:\Users\rupa_\AppData\Local\Temp\2rFZinH5VBqNvRhOZjgbZqEoqLE\resources\app.asar\dist\extension-host\extension-host.js:8:90092]
[2025-01-07 13:34:17.306] [info]  Fetched from UPDATED EXTENSIONS! [at C:\Users\rupa_\AppData\Local\Temp\2rFZinH5VBqNvRhOZjgbZqEoqLE\resources\app.asar\dist\extension-host\extension-host.js:8:90092]
[2025-01-07 13:58:25.374] [warn]  Tried to retrieve data immediately for ChapterUSJ with selector {"book":"MAT","chapterNum":1,"verseNum":2,"versificationStr":"English"}, but it threw. Error: Tried to send payload while not connected
[2025-01-07 13:58:25.376] [warn]  Tried to retrieve data immediately for Comments with selector {"bookId":"MAT","chapterNum":1}, but it threw. Error: Tried to send payload while not connected
[2025-01-07 13:58:27.643] [warn]  Tried to retrieve data immediately for ChapterUSJ with selector {"book":"MAT","chapterNum":1,"verseNum":1,"versificationStr":"English"}, but it threw. Error: Tried to send payload while not connected
[2025-01-07 13:58:27.645] [warn]  Tried to retrieve data immediately for Comments with selector {"bookId":"MAT","chapterNum":1}, but it threw. Error: Tried to send payload while not connected
[2025-01-07 14:01:10.552] [warn]  Tried to retrieve data immediately for ChapterUSJ with selector {"book":"MAT","chapterNum":1,"verseNum":2,"versificationStr":"English"}, but it threw. Error: Tried to send payload while not connected
[2025-01-07 14:01:10.554] [warn]  Tried to retrieve data immediately for Comments with selector {"bookId":"MAT","chapterNum":1}, but it threw. Error: Tried to send payload while not connected

Expected behavior
A clear and concise description of what you expected to happen.

main_websocket_disconnected.log

@roopa0222 roopa0222 added the bug Something isn't working label Jan 7, 2025
@lyonsil
Copy link
Member

lyonsil commented Jan 8, 2025

The peculiar part in the log starts at 13:17:11:

[2025-01-07 13:04:03.794] [info]  [extension host] DataProvider-s9vuh2UnuU2zuEi3YKhIaTUN9aSrVDIg-pdp is being resolved now
[2025-01-07 13:17:11.209] [info]  Method 'dialog:showDialog' removed since websocket 3 closed
[2025-01-07 13:34:09.605] [info]  Method 'dialog:selectProject' removed since websocket 3 closed
[2025-01-07 13:34:09.609] [info]  Method 'object:ScrollGroupService' removed since websocket 3 closed
[2025-01-07 13:34:09.614] [info]  Method 'object:ScrollGroupService.getScrRef' removed since websocket 3 closed
[2025-01-07 13:34:09.618] [info]  Method 'object:ScrollGroupService.setScrRef' removed since websocket 3 closed
[2025-01-07 13:34:09.621] [info]  Method 'object:WebViewService' removed since websocket 3 closed
[2025-01-07 13:34:09.625] [info]  Method 'object:WebViewService.getOpenWebViewDefinition' removed since websocket 3 closed
[2025-01-07 13:34:09.629] [info]  Method 'object:WebViewService.getSavedWebViewDefinition' removed since websocket 3 closed
[2025-01-07 13:34:09.633] [info]  Method 'object:WebViewService.getWebView' removed since websocket 3 closed
[2025-01-07 13:34:09.636] [info]  Method 'object:WebViewService.getWebViewController' removed since websocket 3 closed
[2025-01-07 13:34:09.627] [info]  Fetching from UPDATING EXTENSIONS... [at C:\Users\rupa_\AppData\Local\Temp\2rFZinH5VBqNvRhOZjgbZqEoqLE\resources\app.asar\dist\extension-host\extension-host.js:8:90092]
[2025-01-07 13:34:09.640] [info]  Method 'object:WebViewService.openWebView' removed since websocket 3 closed
[2025-01-07 13:34:09.644] [info]  Fetching from https://api-marketplace-qa.paratext.bible/extensions... [at C:\Users\rupa_\AppData\Local\Temp\2rFZinH5VBqNvRhOZjgbZqEoqLE\resources\app.asar\dist\extension-host\extension-host.js:8:90092]
[2025-01-07 13:34:09.649] [info]  Method 'webViewMessage:2be2f4ec-e4e0-4bd3-bbc9-400918777f2f' removed since websocket 3 closed
[2025-01-07 13:34:09.655] [info]  Method 'command:platform.openSettings' removed since websocket 3 closed
[2025-01-07 13:34:09.658] [info]  Method 'command:platform.openProjectSettings' removed since websocket 3 closed
[2025-01-07 13:34:09.661] [info]  Method 'command:platform.openUserSettings' removed since websocket 3 closed

Before that point, everything appears to have been working as expected. Then at 13:17:11 the first sign of a disconnect happens (websocket 3 is the one between main and the renderer). But the teardown after the websocket closed didn't finish until 17 minutes later, at 13:34:09. That is very odd and indicates the main process (which is where the "Method removed" messages originate) was so bogged down it couldn't quickly finish running through a foreach loop that should have taken milliseconds.

    this.rpcMethodDetailsByMethodName.forEach(({ handler }, methodName) => {
      if (handler !== this) return;

      logger.info(`Method '${methodName}' removed since websocket ${this.name} closed`);
      this.rpcMethodDetailsByMethodName.delete(methodName);
    });

My best guess at this point is that something bad was happening inside the main process which caused the websocket to close. What that could be is still a mystery. Notice that the forEach loop above has no asynchronous code, That means the entire Javascript engine did not allow any user code to run for 17 minutes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
Status: No status
Development

No branches or pull requests

2 participants