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

SEB 3.7.1 unexpectedly terminated #977

Open
RoChess opened this issue Sep 19, 2024 · 15 comments
Open

SEB 3.7.1 unexpectedly terminated #977

RoChess opened this issue Sep 19, 2024 · 15 comments
Assignees
Labels
can't reproduce This issue cannot be reproduced and thus also not be fixed. information required This issue lacks information or requires feedback. stale This issue had no recent activity and will thus soon be closed.

Comments

@RoChess
Copy link

RoChess commented Sep 19, 2024

From three different systems (it is not a consistent issue, as many report no problems), I've gathered the following:

/* Safe Exam Browser, Version 3.7.1 (x64), Build 3.7.1.704

2024-09-18 18:13:20.380 [08] - INFO: Successfully started new client instance.
2024-09-18 18:13:20.380 [08] - INFO: Successfully activated first session 'd801310d-12d5-4b07-8bdd-a89c0d0428ee'.
2024-09-18 18:13:20.380 [08] - INFO: ### ---------------------------------------- Session Running ----------------------------------------- ###
2024-09-18 18:14:10.448 [23] - DEBUG: [RuntimeHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-09-18 18:14:20.366 [24] - DEBUG: [ClientProxy] Sending message 'SimpleMessage -> Ping'...
2024-09-18 18:14:20.369 [24] - DEBUG: [ClientProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-09-18 18:14:20.371 [24] - INFO: [ClientProxy] Pinged host, connection is alive.
2024-09-18 18:14:42.369 [23] - ERROR: Client application has unexpectedly terminated with exit code -1073741819!
2024-09-18 18:14:42.369 [23] - INFO: ### ------------------------------------- Session Stop Procedure ------------------------------------- ###
2024-09-18 18:14:42.379 [23] - INFO: Reverting kiosk mode 'CreateNewDesktop'...

Hoping the exit code from Runtime.log provides better insight in what I could pursuit next as possible cause.

Have not been able to reproduce it myself, which is making it difficult to provide additional information as I don't like forwarding logs from end-users.

@RoChess
Copy link
Author

RoChess commented Sep 19, 2024

Adjusting my Google search (the - was eliminating the exit code from search), I came across the following at least:

The exit code -1073741819 in hex is 0xC0000005. If you look up this code in Microsoft's documentation (NTSTATUS Values) you will see that it indicates that your program was terminated due to an access violation. This error can occur for a variety of reasons, including de-referencing a NULL pointer or referencing an invalid address.

@dbuechel
Copy link
Member

dbuechel commented Sep 20, 2024

Are there any hints in the client log? If the client application component crashed, then you'll normally find the reason in the event logs of Windows itself; open "Event Viewer" via the start menu and search the "Application" log under "Windows Logs".

@dbuechel dbuechel added the information required This issue lacks information or requires feedback. label Sep 20, 2024
@RoChess
Copy link
Author

RoChess commented Sep 20, 2024

Just had zoom call with end-user on their phone while they reproduced it on their laptop, and indeed two Event Viewer entries.

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name=".NET Runtime" /> 
  <EventID Qualifiers="0">1026</EventID> 
  <Version>0</Version> 
  <Level>2</Level> 
  <Task>0</Task> 
  <Opcode>0</Opcode> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2024-09-20T17:10:07.7203706Z" /> 
  <EventRecordID>38444</EventRecordID> 
  <Correlation /> 
  <Execution ProcessID="3356" ThreadID="0" /> 
  <Channel>Application</Channel> 
  <Computer>DESKTOP-21LEK0F</Computer> 
  <Security /> 
  </System>
 <EventData>
  <Data>Application: SafeExamBrowser.Client.exe Framework Version: v4.0.30319 Description: The process was terminated due to an unhandled exception. Exception Info: exception code c0000005, exception address 00007FFA9AA2940A Stack:</Data> 
  </EventData>
  </Event>


 <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="Application Error" Guid="{a0e9b465-b939-57d7-b27d-95d8e925ff57}" /> 
  <EventID>1000</EventID> 
  <Version>0</Version> 
  <Level>2</Level> 
  <Task>100</Task> 
  <Opcode>0</Opcode> 
  <Keywords>0x8000000000000000</Keywords> 
  <TimeCreated SystemTime="2024-09-20T17:10:08.0817066Z" /> 
  <EventRecordID>38445</EventRecordID> 
  <Correlation /> 
  <Execution ProcessID="15140" ThreadID="14628" /> 
  <Channel>Application</Channel> 
  <Computer>DESKTOP-21LEK0F</Computer> 
  <Security UserID="S-1-5-21-3503941340-2752403389-1054329371-1001" /> 
  </System>
 <EventData>
  <Data Name="AppName">SafeExamBrowser.Client.exe</Data> 
  <Data Name="AppVersion">3.7.1.704</Data> 
  <Data Name="AppTimeStamp">666c3189</Data> 
  <Data Name="ModuleName">libcef.dll</Data> 
  <Data Name="ModuleVersion">121.3.13.0</Data> 
  <Data Name="ModuleTimeStamp">65ca6af2</Data> 
  <Data Name="ExceptionCode">c0000005</Data> 
  <Data Name="FaultingOffset">000000000028940a</Data> 
  <Data Name="ProcessId">0xd1c</Data> 
  <Data Name="ProcessCreationTime">0x1db0b7fb515f660</Data> 
  <Data Name="AppPath">C:\Program Files\SafeExamBrowser\Application\SafeExamBrowser.Client.exe</Data> 
  <Data Name="ModulePath">C:\Program Files\SafeExamBrowser\Application\libcef.dll</Data> 
  <Data Name="IntegratorReportId">5f18af84-0c4e-44e2-bade-97a3a4a64677</Data> 
  <Data Name="PackageFullName" /> 
  <Data Name="PackageRelativeAppId" /> 
  </EventData>
  </Event>

(waiting on ZIP file on the three SEB log files, as they appear to be stuck in Microsoft O365 queue -- probably anti-virus scanner stuck on them)

@dbuechel
Copy link
Member

Thanks, this looks like a crash caused by the internal browser engine:

<Data Name="ModuleName">libcef.dll</Data>

This can unfortunately happen, so unless there is a reliable way for reproducing the problem, I'm afraid there is not much we can do.

@dbuechel dbuechel added the can't reproduce This issue cannot be reproduced and thus also not be fixed. label Sep 23, 2024
@RoChess
Copy link
Author

RoChess commented Sep 23, 2024

@dbuechel it appears random indeed. Only impacts a few students, and I'm unable to create any scenario masquerading as them where I can reproduce it on the test-systems available to me, but the users themselves can reproduce it consistently. I've had a few Teams/Zoom meetings and go through their OS/system and ensured default Windows updates were all done, but also the optional ones and verified the "other Microsoft updates" toggle was active. Then also had them update videocard driver as we rely on WebGL/Tensorflow. To be safe went through installed-apps list and had them remove anything they weren't using anymore such as Citrix, RDLB, and other apps.

But crash still happened.

Weirdly it happens at the very end when everything successfully completed and quiz submitted. But it happens like 10+ seconds afterwards. The last action is that SignalR connection between LMS and pop-up is closed.

Finally located the ZIP files stuck in Azure Exchange Security section, so I have little bit more info to share.

One student has these entries in their browser.log as the final two with nothing after (nobody else had these entries):

[0917/201625.489:WARNING:sync_reader.cc(175)] ASR: No room in socket buffer.: The pipe is being closed. (0xE8)
[0917/201625.489:WARNING:sync_reader.cc(175)] ASR: No room in socket buffer.: The pipe is being closed. (0xE8)

But the crash happens 7 seconds later for them, and only this student had these sync_reader.cc entries, with this being their runtime log:

2024-09-17 20:16:21.323 [09] - DEBUG: [ClientProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-09-17 20:16:21.328 [09] - INFO: [ClientProxy] Pinged host, connection is alive.
2024-09-17 20:16:32.404 [13] - ERROR: Client application has unexpectedly terminated with exit code -1073741819!
2024-09-17 20:16:32.404 [13] - INFO: ### ------------------------------------- Session Stop Procedure ------------------------------------- ###

client.log last entries are:

2024-09-17 20:16:20.858 [20] - DEBUG: [PowerSupply] Power grid is not connected, battery charge at 94% (02:09:00).
2024-09-17 20:16:21.319 [12] - DEBUG: [ClientHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-09-17 20:16:24.512 [30] - INFO: [Browser Window #1] Navigated.
2024-09-17 20:16:24.681 [30] - INFO: [Browser Window #1] Navigated.
2024-09-17 20:16:25.513 [01] - DEBUG: [Browser Window #2] Window is closing...
2024-09-17 20:16:25.529 [01] - DEBUG: [Browser Window #2] Window has been closed.
2024-09-17 20:16:25.538 [01] - INFO: [BrowserApplication] Window #2 has been closed.

Scenario is quick the reproduce as you can see. They click button to launch pop-up (window #2). Camera/microphone started in window #2 with FaceAPI JS framework active and a SignalR connection between window #2 and LMS in #1, and they go back to #1 (window #2 becomes a pop-under), submit single-question quiz. JavaScript in #1 via SignalR tells window #2 to close and the end-user sees success message.

Then a few moments later crash.

But majority of end-users have no issue at all.

Needle in the haystack, but I'll take pointers or have the end-user install a special trace version of SEB if you have one.

@dbuechel
Copy link
Member

Thanks for the additional information. A possible next step would be to verify whether this might be an upstream issue in the browser engine itself. To do so, please try to reproduce the issue in the CEF sample application (see https://cef-builds.spotifycdn.com/index.html). If it does reproduce there, then we'd be a step further.

@RoChess
Copy link
Author

RoChess commented Oct 11, 2024

Sorry for the long delay, but it took a while to connect with students experiencing the issue as it is only a small number impacted. Both users updated to v3.8.0.742 just to be on the safe side.

Google CEF Sample app with --enable-media-stream does not give a camera+microphone ID, so we needed to modify our code to accept this workflow in order for windows #2 to proceed with the proctoring.

There is one warning in developer console "Warning: No client method with the name 'connect' found." which relates to signalr.min.js library we use, so going to investigate that next week on our end, but it did not at all impact functionality (and with vast majority of users having no issues at all using SEB it would be extremely unlikely, but I personally don't like any errors and/or warnings, so will work on it).

CEF-Sample app did not crash.

So, tried again with SEB 3.8, and it seems the logging got modified.

Most importantly the 'Browser' logs did not contain any of the 'sync_reader.cc' errors, but will confirm that with more users experiencing this issue to really consider that "resolved" once they all tried it on SEB v3.8

Those entries would be at the very end and read like:

[1009/215745.412:WARNING:sync_reader.cc(175)] ASR: No room in socket buffer.: The pipe is being closed. (0xE8)
[1009/215745.412:WARNING:sync_reader.cc(175)] ASR: No room in socket buffer.: The pipe is being closed. (0xE8)

LOGS FROM TEST TODAY

Runtime:

Safe Exam Browser, Version 3.8.0 (x64), Build 3.8.0.742
Application started at 2024-10-11 18:11:48.048
Running on Windows 11, Microsoft Windows NT 10.0.22631.0 (x64)
Computer 'LAPTOP' is a IdeaPad 3 15ITL6 82H8 manufactured by LENOVO

2024-10-11 18:12:06.858 [08] - INFO: Successfully activated first session '[session-GUID]'.
2024-10-11 18:12:06.862 [08] - INFO: ### ---------------------------------------- Session Running ----------------------------------------- ###
2024-10-11 18:12:58.848 [16] - DEBUG: [RuntimeHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-10-11 18:13:06.846 [18] - DEBUG: [ClientProxy] Sending message 'SimpleMessage -> Ping'...
2024-10-11 18:13:06.846 [18] - DEBUG: [ClientProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-10-11 18:13:06.846 [18] - INFO: [ClientProxy] Pinged host, connection is alive.
2024-10-11 18:13:58.847 [12] - DEBUG: [RuntimeHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-10-11 18:14:06.851 [18] - DEBUG: [ClientProxy] Sending message 'SimpleMessage -> Ping'...
2024-10-11 18:14:06.853 [18] - DEBUG: [ClientProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-10-11 18:14:06.853 [18] - INFO: [ClientProxy] Pinged host, connection is alive.
2024-10-11 18:14:23.540 [14] - ERROR: Client application has unexpectedly terminated with exit code -1073741819!
2024-10-11 18:14:23.540 [14] - INFO: ### ------------------------------------- Session Stop Procedure ------------------------------------- ###
2024-10-11 18:14:23.544 [14] - INFO: Reverting kiosk mode 'CreateNewDesktop'...
2024-10-11 18:14:23.545 [14] - INFO: [DesktopMonitor] Stopped monitoring desktop 'ZwZfdrfpNdCdmOHfU' [5623].
2024-10-11 18:14:23.560 [14] - INFO: Switched back to original desktop 'Default' [188].
2024-10-11 18:14:23.560 [14] - INFO: Closed custom desktop 'ZwZfdrfpNdCdmOHfU' [5623].
2024-10-11 18:14:23.576 [14] - INFO: Finalizing service...
2024-10-11 18:14:23.584 [14] - INFO: [SystemSentinel] Successfully reverted sticky keys (original state: functionality available and disabled, hotkey active).
2024-10-11 18:14:23.584 [14] - INFO: ### --------------------------------------- Session Terminated --------------------------------------- ###
2024-10-11 18:14:38.160 [14] - DEBUG: [Process 'SafeExamBrowser.Client.exe' (7236)] Process has terminated.

2024-10-11 18:14:38.203 [18] - INFO: Initiating shutdown procedure...
2024-10-11 18:14:38.204 [18] - INFO: Stopping communication host...
2024-10-11 18:14:38.205 [18] - DEBUG: [RuntimeHost] Communication host is closing...
2024-10-11 18:14:38.214 [18] - DEBUG: [RuntimeHost] Communication host has been closed.
2024-10-11 18:14:38.215 [18] - DEBUG: [RuntimeHost] Terminated communication host for endpoint 'net.pipe://localhost/safeexambrowser/runtime/f8c29e2e-7c80-4ce5-bf76-9b4c6c23a258'.
2024-10-11 18:14:38.216 [18] - INFO: Application successfully finalized.

Application terminated at 2024-10-11 18:14:38.251

Browser:

[1011/181417.758:INFO:CONSOLE(0)] "Third-party cookie will be blocked. Learn more in the Issues tab.", source: https://[censored].instructure.com/courses/12619/quizzes/53122 (0)
[1011/181417.758:INFO:CONSOLE(0)] "Third-party cookie will be blocked. Learn more in the Issues tab.", source: https://[censored].instructure.com/courses/12619/quizzes/53122 (0)
[1011/181417.835:INFO:CONSOLE(923)] "Detection done, faces: 1", source: https://[us].com/Index?sessionToken=ydrqeljz0wcvft5jbzgc0aa1 (923)
[1011/181417.972:INFO:CONSOLE(2582)] "Proctoring Started!", source: https://[censored].cloudfront.net/dist/webpack-production/main-entry-[session-ID-CF].js (2582)
[1011/181417.972:INFO:CONSOLE(2582)] "Proctoring Stopped!", source: https://[censored].cloudfront.net/dist/webpack-production/main-entry-[session-ID-CF].js (2582)
[1011/181417.972:INFO:CONSOLE(2582)] "Proctoring Quiz Fix", source: https://[censored].cloudfront.net/dist/webpack-production/main-entry-[session-ID-CF].js (2582)

Client:

2024-10-11 18:12:05.077 [01] - INFO: [ApplicationMonitor] Started monitoring applications.
2024-10-11 18:12:05.077 [01] - INFO: [ApplicationMonitor] Registered system capture start event with ID = [GUID].
2024-10-11 18:12:05.077 [01] - INFO: [ApplicationMonitor] Registered system foreground event with ID = [GUID].
2024-10-11 18:12:05.077 [01] - INFO: Initializing working area...
2024-10-11 18:12:05.097 [01] - DEBUG: [Taskbar] Calculated physical taskbar height is 50px.
2024-10-11 18:12:05.110 [01] - INFO: [DisplayMonitor] Saved original working area for DISPLAY1 (1920x1080): Left = 0, Top = 50, Right = 1920, Bottom = 1020.
2024-10-11 18:12:05.110 [01] - INFO: [DisplayMonitor] Trying to set new working area for DISPLAY1 (1920x1080): Left = 0, Top = 0, Right = 1920, Bottom = 1030.
2024-10-11 18:12:05.110 [01] - INFO: [DisplayMonitor] Working area of DISPLAY1 (1920x1080) is now set to: Left = 0, Top = 0, Right = 1920, Bottom = 1030.
2024-10-11 18:12:05.114 [01] - INFO: [DisplayMonitor] Started monitoring display changes.
2024-10-11 18:12:05.115 [01] - INFO: Initializing shell...
2024-10-11 18:12:05.307 [01] - INFO: [Audio] Found 'Speakers (Realtek(R) Audio)' to be the active audio device.
2024-10-11 18:12:05.760 [01] - INFO: [Audio] Started monitoring the audio device.
2024-10-11 18:12:05.791 [01] - INFO: [Keyboard] Saved current keyboard layout 'English (United States)' [ENG, US].
2024-10-11 18:12:05.791 [01] - INFO: [Keyboard] Detected keyboard layout 'English (United States)' [ENG, US].
2024-10-11 18:12:05.894 [01] - DEBUG: [NetworkAdapter] Found 1 wireless network adapter(s).
2024-10-11 18:12:05.910 [01] - DEBUG: [NetworkAdapter] Successfully initialized wireless network adapter '\\[DEVICE-ID]'.
2024-10-11 18:12:05.981 [01] - INFO: [NetworkAdapter] Connection established (Wireless, [SSID]).
2024-10-11 18:12:05.981 [01] - INFO: [NetworkAdapter] Started monitoring the network adapter.
2024-10-11 18:12:05.981 [01] - INFO: [PowerSupply] Started monitoring the power supply (battery charge thresholds: low = 20%, critical = 10%).
2024-10-11 18:12:05.981 [01] - INFO: Initializing action center...
2024-10-11 18:12:06.045 [01] - DEBUG: [PowerSupply] Power grid is connected, battery charge at 100%.
2024-10-11 18:12:06.061 [01] - INFO: Initializing taskbar...
2024-10-11 18:12:06.076 [01] - INFO: Initializing task view...
2024-10-11 18:12:06.092 [01] - INFO: Display(s) will be always on.
2024-10-11 18:12:06.092 [01] - INFO: System will use the operating system configuration and may enter sleep mode or standby.
2024-10-11 18:12:06.092 [01] - INFO: Initializing browser...
2024-10-11 18:12:06.092 [01] - INFO: [BrowserApplication] Starting initialization...
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Accept Language: en-US
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Cache Path: C:\Users\[user]\AppData\Local\SafeExamBrowser\Cache
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Engine Version: Chromium 121.0.6167.184, CEF r121.3.13+g5c4a81b+chromium-121.0.6167.184, CefSharp 121.3.130.0
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Log File: C:\Users\[user]\AppData\Local\SafeExamBrowser\Logs\2024-10-11_18h11m48s_Browser.log
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Log Severity: Info.
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] PDF Reader: Enabled.
2024-10-11 18:12:06.196 [01] - DEBUG: [BrowserApplication] Session Persistence: Disabled.
2024-10-11 18:12:06.400 [01] - DEBUG: [BrowserApplication] Browser Exam Key (BEK) transmission is enabled.
2024-10-11 18:12:06.400 [01] - DEBUG: [BrowserApplication] Configuration Key (CK) transmission is enabled.
2024-10-11 18:12:06.400 [01] - DEBUG: [BrowserApplication] The browser application will be using the default browser exam key.
2024-10-11 18:12:06.409 [01] - DEBUG: [BrowserApplication] Successfully initiated cookie deletion.
2024-10-11 18:12:06.414 [01] - INFO: [BrowserApplication] Initialized browser.
2024-10-11 18:12:06.435 [01] - INFO: Initializing clipboard...
2024-10-11 18:12:06.435 [01] - DEBUG: [Clipboard] Cleared clipboard.
2024-10-11 18:12:06.439 [01] - DEBUG: [Clipboard] Started clipboard monitoring with interval 50 ms.
2024-10-11 18:12:06.439 [01] - INFO: [Clipboard] Initialized clipboard for policy 'Isolated'.
2024-10-11 18:12:06.503 [01] - DEBUG: [Taskbar] Set taskbar bounds to 1536x40 at (0/824), in physical pixels: 1920x50 at (0/1030).
2024-10-11 18:12:06.505 [01] - INFO: Auto-starting browser...
2024-10-11 18:12:06.573 [01] - DEBUG: [Browser Window #1] Initialized browser control.
2024-10-11 18:12:06.576 [33] - DEBUG: [BrowserApplication] Deleted 7 cookies.
2024-10-11 18:12:06.742 [01] - DEBUG: [Browser Window #1] Initialized browser window.
2024-10-11 18:12:06.742 [01] - INFO: [BrowserApplication] Created browser window #1.
2024-10-11 18:12:06.758 [01] - INFO: [SystemSentinel] Started monitoring system events.
2024-10-11 18:12:06.758 [01] - INFO: [SystemSentinel] Started monitoring sticky keys.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'AppStarting' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_working.ani'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'Arrow' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_arrow.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'ContactVisualization' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: '1'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'Crosshair' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: ''.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'CursorBaseSize' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: '32'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'GestureVisualization' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: '31'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'Hand' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_link.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'Help' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_helpsel.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'IBeam' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: ''.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'No' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_unavail.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'NWPen' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_pen.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'Scheme Source' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: '2'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'SizeAll' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_move.cur'.
2024-10-11 18:12:06.758 [01] - DEBUG: [Registry] Started monitoring value 'SizeNESW' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_nesw.cur'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'SizeNS' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_ns.cur'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'SizeNWSE' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_nwse.cur'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'SizeWE' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_ew.cur'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'UpArrow' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_up.cur'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'Wait' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'C:\Windows\cursors\aero_busy.ani'.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value '' from registry key 'HKEY_CURRENT_USER\Control Panel\Cursors'. Initial value: 'Windows Default'.
2024-10-11 18:12:06.773 [01] - INFO: [SystemSentinel] Started monitoring cursors.
2024-10-11 18:12:06.773 [01] - DEBUG: [Registry] Started monitoring value 'Debugger' from registry key 'HKEY_LOCAL_MACHINE\Software\Microsoft\Windows NT\CurrentVersion\Image File Execution Options\Utilman.exe'. Value does currently not exist or initial read failed.
2024-10-11 18:12:06.773 [01] - INFO: [SystemSentinel] Started monitoring ease of access.
2024-10-11 18:12:06.773 [01] - DEBUG: [RuntimeProxy] Sending message 'SimpleMessage -> ClientIsReady'...
2024-10-11 18:12:06.773 [22] - DEBUG: [ApplicationMonitor] Window has changed from  to 'Taskbar' (393254).
2024-10-11 18:12:06.773 [22] - DEBUG: [ApplicationMonitor] Window has changed from 'Taskbar' (393254) to '' (2033262).
2024-10-11 18:12:06.779 [01] - DEBUG: [RuntimeProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> ClientIsReady'.
2024-10-11 18:12:06.779 [01] - DEBUG: [RuntimeProxy] Runtime acknowledged that the client is ready.
2024-10-11 18:12:06.779 [01] - INFO: Application successfully initialized.

2024-10-11 18:12:06.828 [16] - DEBUG: [ClientHost] Received connection request with authentication token '[token]'.
2024-10-11 18:12:06.829 [16] - DEBUG: [ClientHost] Accepted connection request.
2024-10-11 18:12:06.846 [11] - DEBUG: [ClientHost] Received message 'SimpleMessage -> Authenticate', sending response 'AuthenticationResponse'.
2024-10-11 18:12:06.862 [22] - DEBUG: [ApplicationMonitor] Window has changed from '' (2033262) to 'ActionCenter' (262256).
2024-10-11 18:12:06.862 [22] - DEBUG: [ApplicationMonitor] Window has changed from 'ActionCenter' (262256) to '' (2033262).
2024-10-11 18:12:06.958 [38] - DEBUG: [KeyGenerator] Initializing browser exam key...
2024-10-11 18:12:07.382 [22] - DEBUG: [ApplicationMonitor] Window has changed from '' (2033262) to 'ActionCenter' (262256).
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (17188) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (9844) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (6392) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (5248) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (8264) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (14556) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'ms-teams.exe' (12216) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'ms-teams.exe' (15592) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (17396) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (5284) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (15192) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (9128) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (1336) has been terminated.
2024-10-11 18:12:07.494 [35] - DEBUG: [ApplicationMonitor] Process 'msedgewebview2.exe' (14548) has been terminated.
2024-10-11 18:12:09.365 [22] - DEBUG: [ApplicationMonitor] Window has changed from 'ActionCenter' (262256) to '' (2033262).
2024-10-11 18:12:09.828 [38] - DEBUG: [KeyGenerator] Successfully calculated browser exam key using integrity module.
2024-10-11 18:12:09.867 [19] - DEBUG: [ApplicationMonitor] Process 'msedge.exe' (12212) has been terminated.
2024-10-11 18:12:11.277 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:13.364 [21] - DEBUG: [ApplicationMonitor] Window has changed from '' (2033262) to '' (263538).
2024-10-11 18:12:16.890 [19] - DEBUG: [ApplicationMonitor] Process 'SearchProtocolHost.exe' (16132) has been terminated.
2024-10-11 18:12:23.908 [35] - DEBUG: [ApplicationMonitor] Process 'msedge.exe' (12312) has been terminated.
2024-10-11 18:12:35.562 [06] - DEBUG: [ApplicationMonitor] Process 'msedge.exe' (13864) has been started [Original Name: 'msedge.exe', Path: 'C:\Program Files (x86)\Microsoft\Edge\Application\msedge.exe', Signature: 05a822642cf64464460cb4684ff11c7f476873ca].
2024-10-11 18:12:35.562 [06] - DEBUG: [ApplicationMonitor] Process 'RuntimeBroker.exe' (14608) has been terminated.
2024-10-11 18:12:46.797 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:47.257 [39] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (5904) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:47.595 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:48.784 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:49.631 [36] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (9620) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:12:49.631 [36] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (9844) has been terminated.
2024-10-11 18:12:57.891 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:58.024 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:12:58.847 [36] - DEBUG: [RuntimeProxy] Sending message 'SimpleMessage -> Ping'...
2024-10-11 18:12:58.849 [36] - DEBUG: [RuntimeProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-10-11 18:12:58.850 [36] - INFO: [RuntimeProxy] Pinged host, connection is alive.
2024-10-11 18:13:03.635 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:13:03.845 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:13:06.093 [36] - DEBUG: [PowerSupply] Power grid is connected, battery charge at 100%.
2024-10-11 18:13:06.846 [14] - DEBUG: [ClientHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-10-11 18:13:19.080 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:13:19.224 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:13:20.299 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (7048) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:13:22.431 [32] - DEBUG: [Browser Window #1] Forwarding request to open new window...
2024-10-11 18:13:22.431 [01] - INFO: [BrowserApplication] Received request to create new window...
2024-10-11 18:13:22.431 [01] - DEBUG: [Browser Window #2] Initialized browser control.
2024-10-11 18:13:22.431 [01] - INFO: [BrowserApplication] Created browser window #2.
2024-10-11 18:13:22.468 [22] - DEBUG: [ApplicationMonitor] Window has changed from '' (263538) to '' (591866).
2024-10-11 18:13:22.478 [01] - DEBUG: [Browser Window #2] Initialized browser window.
2024-10-11 18:13:22.638 [32] - INFO: [Browser Window #2] Navigated.
2024-10-11 18:13:22.694 [06] - DEBUG: [ApplicationMonitor] Process 'svchost.exe' (5304) has been terminated.
2024-10-11 18:13:28.225 [21] - DEBUG: [ApplicationMonitor] Window has changed from '' (591866) to '' (198070).
2024-10-11 18:13:29.862 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (14104) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:13:29.862 [35] - DEBUG: [ApplicationMonitor] Process 'svchost.exe' (9384) has been started [Original Name: n/a, Path: n/a, Signature: n/a].
2024-10-11 18:13:29.863 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (15676) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:13:39.474 [22] - DEBUG: [ApplicationMonitor] Window has changed from '' (198070) to 'Practice taking a proctored quiz' (2033262).
2024-10-11 18:13:39.504 [21] - DEBUG: [ApplicationMonitor] Window has changed from 'Practice taking a proctored quiz' (2033262) to '' (263538).
2024-10-11 18:13:58.846 [36] - DEBUG: [RuntimeProxy] Sending message 'SimpleMessage -> Ping'...
2024-10-11 18:13:58.848 [36] - DEBUG: [RuntimeProxy] Received response 'SimpleResponse -> Acknowledged' for message 'SimpleMessage -> Ping'.
2024-10-11 18:13:58.848 [36] - INFO: [RuntimeProxy] Pinged host, connection is alive.
2024-10-11 18:14:00.684 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:00.840 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:06.213 [19] - DEBUG: [PowerSupply] Power grid is connected, battery charge at 100%.
2024-10-11 18:14:06.852 [16] - DEBUG: [ClientHost] Received message 'SimpleMessage -> Ping', sending response 'SimpleResponse -> Acknowledged'.
2024-10-11 18:14:08.531 [35] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (3616) has been started [Original Name: 'CefSharp.BrowserSubprocess.exe', Path: 'C:\Program Files\SafeExamBrowser\Application\CefSharp.BrowserSubprocess.exe', Signature: 2bc82fe8e56a39f96bc6c4b91d6703a0379b76a2].
2024-10-11 18:14:10.912 [39] - DEBUG: [ApplicationMonitor] Process 'CefSharp.BrowserSubprocess.exe' (3616) has been terminated.
2024-10-11 18:14:10.993 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:11.151 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:17.330 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:17.463 [32] - INFO: [Browser Window #1] Navigated.
2024-10-11 18:14:18.064 [01] - DEBUG: [Browser Window #2] Window is closing...
2024-10-11 18:14:18.070 [01] - DEBUG: [Browser Window #2] Window has been closed.
2024-10-11 18:14:18.076 [01] - INFO: [BrowserApplication] Window #2 has been closed.

Tried to be careful not to remove too much, and definitely covered the start of process and when it eventually terminates, but forced to censor the logs as they are not mine to share, and I don't want to risk violating privacy laws.

@dbuechel
Copy link
Member

Thanks for the extensive update. Do I understand you correctly that thus the issue still persists? Either way, we'd unfortunately need a way to reproduce the issue, otherwise there's not much we can do I'm afraid.

@RoChess
Copy link
Author

RoChess commented Oct 17, 2024

It indeed still persist, and I believe I'm up to 7 users now (out of thousands without any issue). My next plan of attack is to take remote control and have Microsoft SysInternal Process Monitor running to keep track of any application other than SEB that is reading into the program and user-data folders that SEB uses. There has to be something interfering. Windows Safe Mode is not easy to do remote, but going to try documenting a step-by-step guide for that as well.

The ESET Anti-Virus and Cisco WebEx comment made in another thread as known conflicts is something I'll dig into further as well.

@dbuechel
Copy link
Member

Great, yes that would be very helpful. Once we have a reliably reproducible issue, we can and most definitely will attempt to solve it.

@RoChess
Copy link
Author

RoChess commented Oct 17, 2024

Totally understand the need to reproduce as it is not feasible to expect a solution otherwise. That's what I'm struggling with, because it only happens for these handful of students and nobody else. It does consistently happen for these students though, and very easy to reproduce.

One question though, I went through entire process in CEF Sample App without a problem, but it was the latest version published on that day. There is a slim chance that Google fixed a bug, so could you tell me the version of CEF that SEB 3.8.0 uses? I can then at least repeat testing with the correct matching CEF Sample App version.

@dbuechel
Copy link
Member

dbuechel commented Oct 18, 2024

Exactly, that is indeed possible. Please do also note that we're in the end using CefSharp, i.e. a wrapper of CEF, which may also be interfering or causing issues here.

The current browser engine version is always logged in the client log, e.g. for SEB 3.7.1:

2024-06-14 18:35:24.964 [01] - DEBUG: [BrowserApplication] Engine Version: Chromium 121.0.6167.184, CEF r121.3.13+g5c4a81b+chromium-121.0.6167.184, CefSharp 121.3.130.0

Copy link

This issue is stale because it has been open for 28 days with no activity. It will soon be closed automatically if there are no updates.

@github-actions github-actions bot added the stale This issue had no recent activity and will thus soon be closed. label Nov 16, 2024
@RoChess
Copy link
Author

RoChess commented Nov 16, 2024

It has been tough scheduling with the students impacted as they've been exempted for the time being, so I'm forced to connect with them in their free time.

Heading to OLC 2024 conference next week but will pick this up once I return to try to get the details needed.

@github-actions github-actions bot removed the stale This issue had no recent activity and will thus soon be closed. label Nov 17, 2024
Copy link

This issue is stale because it has been open for 28 days with no activity. It will soon be closed automatically if there are no updates.

@github-actions github-actions bot added the stale This issue had no recent activity and will thus soon be closed. label Dec 15, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
can't reproduce This issue cannot be reproduced and thus also not be fixed. information required This issue lacks information or requires feedback. stale This issue had no recent activity and will thus soon be closed.
Projects
None yet
Development

No branches or pull requests

2 participants