client hang on close

[dbish]

User: Debo
Recording ID: UGUORPtwAA

What happened?

• recorded for about 2 minutes and closed the client
• client hung on close
  

Expected?

• client should have closed cleanly

Other notes

• the recording was made and server received it (user to confirm that it showed what they did)

[dbish]

No server issues found yet, investigating further.

[dbish]

One possibility, it looked frozen because it was still processing end of stream, need to get back info on client side

[dbish]

Opening a new issue for better status reporting for cases like this where there is still data to process at the end and we can't close the client quite yet: #15

[dray92]

debo@debosmits-air T % ls augmend*
augmend_client_5_1_2024__9_25.log	augmend_client_5_1_2024__9_27.log	augmend_client_5_1_2024__9_29.log

debo@debosmits-air T % cat augmend_client_5_1_2024__9_25.log | pbcopy
[    0.0000s] INFO:    Augmend client version: 0.1.60 - 36013b495908a1cf11b58d694823c5f92f1a67f3
[    0.0006s] INFO:    Feature flags: FeatureFlags { accessibility_tree_trace: false }
[    0.0731s] INFO:    system permissions check: SystemPermissions { screen_capture: false, accessibility: false, microphone: false, webcam: false }
[    0.2588s] INFO:    App cpu usage high:  100.00%
[    0.4597s] INFO:    Update event: AlreadyUpToDate
[    0.7762s] INFO:    on_page_load(tauri://localhost/permissions_start.html)
[    4.1792s] INFO:    on_page_load(tauri://localhost/macos_permissions_camera.html)
[    4.6825s] INFO:    request_webcam_permission()
[   29.1887s] INFO:    on_page_load(tauri://localhost/permissions_start.html)
[   30.4988s] INFO:    on_page_load(tauri://localhost/macos_permissions_microphone.html)
[   31.0001s] INFO:    request_microphone_permission()
[   42.0448s] INFO:    request_microphone_permission()
[   42.1544s] INFO:    request_microphone_permission()
[   43.2238s] INFO:    request_microphone_permission()
[   47.6951s] INFO:    request_microphone_permission()
[   52.4573s] INFO:    System CPU high:     100.00%
[   81.6074s] INFO:    request_microphone_permission()
[   82.0250s] INFO:    request_microphone_permission()
[   82.2245s] INFO:    request_microphone_permission()
[   82.4137s] INFO:    request_microphone_permission()
[  106.2271s] INFO:    on_page_load(tauri://localhost/permissions_start.html)
[  109.1786s] INFO:    on_page_load(tauri://localhost/macos_permissions_accessibility.html)
[  109.6811s] INFO:    request_accessibility_permission()
[  113.8402s] INFO:    System CPU high:     91.16%
[  114.3430s] INFO:    System CPU high:     93.30%
[  117.7794s] INFO:    on_page_load(tauri://localhost/permissions_start.html)
[  123.9313s] INFO:    on_page_load(tauri://localhost/macos_permissions_screen_recording.html)
[  124.4334s] INFO:    request_screen_capture_permission()

debo@debosmits-air T % cat augmend_client_5_1_2024__9_27.log | pbcopy
[    0.0000s] INFO:    Augmend client version: 0.1.60 - 36013b495908a1cf11b58d694823c5f92f1a67f3
[    0.0006s] INFO:    Feature flags: FeatureFlags { accessibility_tree_trace: false }
[    0.0703s] INFO:    system permissions check: SystemPermissions { screen_capture: true, accessibility: true, microphone: true, webcam: true }
[    0.4180s] INFO:    Update event: AlreadyUpToDate
[    0.5440s] INFO:    on_page_load(tauri://localhost)
[    0.6718s] INFO:    System CPU high:     91.84%
[    0.7895s] INFO:    on_page_load(https://augmend.com/client_index)
[   28.4621s] INFO:    on_page_load(https://augmend.com/static/client/window_picker.html?initial=true)
[   37.9250s] INFO:    System CPU high:     96.96%
[   69.8506s] INFO:    Main window destroyed

debo@debosmits-air T % cat augmend_client_5_1_2024__9_29.log | pbcopy
[    0.0000s] INFO:    Augmend client version: 0.1.60 - 36013b495908a1cf11b58d694823c5f92f1a67f3
[    0.0006s] INFO:    Feature flags: FeatureFlags { accessibility_tree_trace: false }
[    0.0650s] INFO:    system permissions check: SystemPermissions { screen_capture: true, accessibility: true, microphone: true, webcam: true }
[    0.4040s] INFO:    Update event: AlreadyUpToDate
[    0.5195s] INFO:    on_page_load(tauri://localhost)
[    0.7056s] INFO:    on_page_load(https://augmend.com/client_index)
[   16.4238s] INFO:    on_page_load(https://augmend.com/static/client/window_picker.html?initial=true)
[   33.3575s] INFO:    Metal GPU: Apple M2, OS Version: 14.4.1
[   33.3611s] INFO:    Starting activity: 02ad2be3-d58a-42d7-b6ef-f12d5283cc82
[   33.3711s] INFO:    Metal GPU: Apple M2, OS Version: 14.4.1
[   33.3718s] INFO:    Starting activity: 9334d753-366d-4b24-a25b-3108a492d160
[   33.4789s] INFO:    Metal GPU: Apple M2, OS Version: 14.4.1
[   33.5689s] INFO:    App ID: Some("macos.terminal"), sharing video: false
[   33.5696s] INFO:    App ID: Some("common.chrome"), sharing video: false
[   33.6786s] INFO:    H264 encoder: OpenH264 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
[   33.6786s] INFO:    H264 encoder: OpenH264 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
[   33.8602s] INFO:    on_page_load(tauri://localhost/window_highlight.html)
[   33.8713s] INFO:    on_page_load(tauri://localhost/window_highlight.html)
[   34.1078s] WARNING: Watchdog MacosAccessibilityContext::new() timed out (7 ms past 500 ms timeout) with feed label: populate tree leaves
[   34.3373s] INFO:    App cpu usage high:  100.00%
[   34.4438s] WARNING: Watchdog MacosAccessibilityContext::new() recovered from timeout after 843 ms
[   34.8387s] INFO:    App cpu usage high:  89.75%
[   36.3425s] INFO:    App cpu usage high:  80.79%
[   37.3463s] INFO:    App cpu usage high:  80.51%
[   38.3489s] INFO:    App cpu usage high:  81.36%
[   38.8504s] INFO:    App cpu usage high:  81.67%
[   39.8537s] INFO:    App cpu usage high:  83.87%
[   40.3549s] INFO:    App cpu usage high:  80.67%
[   40.8572s] INFO:    App cpu usage high:  87.90%
[   41.3595s] INFO:    App cpu usage high:  83.07%
[   42.8664s] INFO:    App cpu usage high:  80.60%
[   43.6336s] WARNING: Watchdog MP4 Thread (9334d753-366d-4b24-a25b-3108a492d160) timed out (233 ms past 500 ms timeout) with feed label: sws_scale()
[   43.6391s] WARNING: Watchdog VNC Thread (02ad2be3-d58a-42d7-b6ef-f12d5283cc82) timed out (244 ms past 500 ms timeout) with feed label: vnc update
[   43.6580s] INFO:    System CPU high:     99.64%
[   43.6997s] WARNING: Watchdog MP4 Thread (9334d753-366d-4b24-a25b-3108a492d160) recovered from timeout after 800 ms
[   43.7233s] WARNING: Watchdog VNC Thread (02ad2be3-d58a-42d7-b6ef-f12d5283cc82) recovered from timeout after 834 ms
[   44.6693s] INFO:    App cpu usage high:  83.50%
[   45.1726s] INFO:    App cpu usage high:  94.36%
[   45.6741s] INFO:    App cpu usage high:  86.79%
[   46.1760s] INFO:    App cpu usage high:  81.42%
[   46.6788s] INFO:    App cpu usage high:  81.54%
[   47.1802s] INFO:    App cpu usage high:  81.68%
[   47.6824s] INFO:    App cpu usage high:  80.42%
[   48.1846s] INFO:    App cpu usage high:  82.88%
[   50.1907s] INFO:    App cpu usage high:  80.98%
[   51.1953s] INFO:    App cpu usage high:  80.55%
[   52.1988s] INFO:    App cpu usage high:  83.52%
[   53.2026s] INFO:    App cpu usage high:  80.73%
[   53.7034s] INFO:    App cpu usage high:  82.00%
[   54.7058s] INFO:    App cpu usage high:  80.68%
[   61.7289s] INFO:    App cpu usage high:  80.14%
[   62.7326s] INFO:    App cpu usage high:  81.24%
[   67.7524s] INFO:    App cpu usage high:  80.47%
[   68.7560s] INFO:    App cpu usage high:  80.87%
[   70.2616s] INFO:    App cpu usage high:  80.76%
[   71.2657s] INFO:    App cpu usage high:  80.13%
[   71.7670s] INFO:    App cpu usage high:  81.14%
[   75.2814s] INFO:    App cpu usage high:  82.87%
[   75.7844s] INFO:    App cpu usage high:  85.14%
[   76.2868s] INFO:    App cpu usage high:  80.89%
[   76.7878s] INFO:    App cpu usage high:  81.47%
[   77.7918s] INFO:    App cpu usage high:  81.12%
[   78.2932s] INFO:    App cpu usage high:  81.43%
[   82.8079s] INFO:    App cpu usage high:  85.69%
[   85.3178s] INFO:    App cpu usage high:  80.72%
[   86.3213s] INFO:    App cpu usage high:  83.01%
[   86.8236s] INFO:    App cpu usage high:  80.34%
[   87.3257s] INFO:    App cpu usage high:  82.22%
[   88.3294s] INFO:    App cpu usage high:  82.85%
[   89.3331s] INFO:    App cpu usage high:  85.11%
[   91.3414s] INFO:    App cpu usage high:  83.72%
[   91.8431s] INFO:    App cpu usage high:  82.01%
[   92.8462s] INFO:    App cpu usage high:  87.45%
[   94.8546s] INFO:    App cpu usage high:  88.22%
[   95.3568s] INFO:    App cpu usage high:  83.03%
[   95.8582s] INFO:    App cpu usage high:  86.32%
[   96.3604s] INFO:    App cpu usage high:  81.29%
[   96.4020s] FATAL:   panicked at src/websocket_stream.rs:103:87:
called `Result::unwrap()` on an `Err` value: Io(Os { code: 32, kind: BrokenPipe, message: "Broken pipe" })
[   96.4045s] ERROR:   Websocket closed with an error on close(), IO error: connection closed via error
[   96.8350s] FATAL:   panicked at /Users/tim/.cargo/registry/src/index.crates.io-6f17d22bba15001f/objc-foundation-0.1.1/src/object.rs:49:34:
Uncaught exception <NSException: 0x6000028efd50>
[  126.4056s] INFO:    on_page_load(https://augmend.com/static/client/window_picker.html?initial=false)
[  127.1778s] INFO:    App cpu usage high:  91.82%
[  127.6783s] INFO:    System CPU high:     91.98%
[  127.6783s] INFO:    App cpu usage high:  97.68%
[  127.7140s] WARNING: Watchdog outer get_window_thumbnail(153) timed out (9 ms past 1000 ms timeout) with feed label: get window
[  127.7141s] WARNING: Watchdog outer get_window_thumbnail(154) timed out (9 ms past 1000 ms timeout) with feed label: get window
[  127.7343s] WARNING: Watchdog outer get_window_thumbnail(153) recovered from timeout after 1029 ms
[  127.7535s] WARNING: Watchdog outer get_window_thumbnail(154) recovered from timeout after 1048 ms
[  144.5930s] INFO:    on_page_load(https://augmend.com/static/client/window_picker.html?initial=false)
[  145.2421s] INFO:    App cpu usage high:  80.57%
[  145.7436s] INFO:    App cpu usage high:  89.69%
[  147.3362s] INFO:    Metal GPU: Apple M2, OS Version: 14.4.1
[  147.3368s] INFO:    Starting activity: 974146c9-a164-48eb-bdc6-4e3b7fea514e
[  147.4949s] INFO:    H264 encoder: OpenH264 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
[  147.5265s] INFO:    App ID: Some("common.vscode"), sharing video: false
[  147.7141s] INFO:    on_page_load(tauri://localhost/window_highlight.html)
[  148.2530s] INFO:    App cpu usage high:  88.92%
[  148.7551s] INFO:    App cpu usage high:  85.06%
[  149.2563s] INFO:    App cpu usage high:  84.93%
[  149.7577s] INFO:    App cpu usage high:  81.03%
[  150.2590s] INFO:    App cpu usage high:  82.83%
[  150.7614s] INFO:    App cpu usage high:  81.64%
[  151.2635s] INFO:    App cpu usage high:  83.11%
[  151.7652s] INFO:    App cpu usage high:  81.46%
[  152.2665s] INFO:    App cpu usage high:  81.74%
[  152.7686s] INFO:    App cpu usage high:  83.49%
[  153.2710s] INFO:    App cpu usage high:  84.00%
[  154.2751s] INFO:    App cpu usage high:  81.21%
[  155.2781s] INFO:    App cpu usage high:  80.24%
[  156.2823s] INFO:    App cpu usage high:  83.98%
[  156.7839s] INFO:    App cpu usage high:  82.23%
[  157.8157s] INFO:    App cpu usage high:  85.11%
[  158.3179s] INFO:    App cpu usage high:  82.48%
[  158.8203s] INFO:    App cpu usage high:  81.64%
[  159.3224s] INFO:    App cpu usage high:  82.80%
[  159.8335s] INFO:    App cpu usage high:  81.94%
[  160.0022s] INFO:    on_stream_closed(id: 9334d753-366d-4b24-a25b-3108a492d160, reason: WorkspaceConnection::disconnect() called)...
[  160.0061s] INFO:    close_stream called with activity id: 9334d753-366d-4b24-a25b-3108a492d160
[  160.0124s] INFO:    on_stream_closed(id: 02ad2be3-d58a-42d7-b6ef-f12d5283cc82, reason: WorkspaceConnection::disconnect() called)...
[  160.0126s] INFO:    close_stream called with activity id: 02ad2be3-d58a-42d7-b6ef-f12d5283cc82
[  160.0136s] INFO:    FFMPEG done encoding. Total skipped frames: 960
[  160.0161s] INFO:    on_stream_closed(id: 974146c9-a164-48eb-bdc6-4e3b7fea514e, reason: WorkspaceConnection::disconnect() called)...
[  160.0162s] INFO:    close_stream called with activity id: 974146c9-a164-48eb-bdc6-4e3b7fea514e
[  160.0199s] INFO:    Main window destroyed
[  160.0529s] INFO:    Websocket closed normally
[  160.0532s] INFO:    ffmpeg thread complete: 9334d753-366d-4b24-a25b-3108a492d160
[  160.1289s] INFO:    FFMPEG done encoding. Total skipped frames: 95
[  160.1602s] INFO:    VNC: stream ended from EndOfStream
[  160.1931s] INFO:    Websocket closed normally
[  160.1932s] INFO:    ffmpeg thread complete: 974146c9-a164-48eb-bdc6-4e3b7fea514e
[  160.4576s] INFO:    VNC: stream ended from EndOfStream
[  160.5187s] INFO:    VNC: stream ended from EndOfStream
[  160.7152s] ERROR:   Websocket closed with an error
[  160.7154s] INFO:    VNC thread complete: 9334d753-366d-4b24-a25b-3108a492d160
[  160.7165s] ERROR:   Websocket closed with an error
[  160.7166s] INFO:    VNC thread complete: 02ad2be3-d58a-42d7-b6ef-f12d5283cc82
[  160.9059s] ERROR:   Websocket closed with an error
[  160.9062s] INFO:    VNC thread complete: 974146c9-a164-48eb-bdc6-4e3b7fea514e
[  196.9823s] INFO:    System CPU high:     91.20%

[dbish]

Also note, recording for other apps and audio came through, but VSCode wasn't capture entirely, probably related to the errors we see here that then caused the client to hang on close.

[TimMisiak]

On the server side I see the connection drop around the same time as the panic, but it's not clear which came first. The connection also drops at almost exactly 20 seconds (plus about 90 milliseconds) after the last frame seen by the server, so it kind of seems like a timeout happened somewhere. I'm working on some more logging on the server side to see if we can rule out network issues.

[TimMisiak]

I've put some better logging on the production video server. If this gets hit again, we'll have better info on what went wrong. The logs should be enough to show us if some reconnection functionality would be effective here or if there's some bug on the client that needs to be fixed.

[dbish]

Noting here for posterity as we prepare a new build and test. Using displaylink is able to consistently cause slow down and crashes/hangs (https://www.synaptics.com/products/displaylink-graphics/downloads/macos). This does some form of virtual screen capture as well which may be conflicting. OBS has similar issues with it. Good test setup is to run displaylink and connect to an external monitor through a displaylink enabled adapter.